From c615b528405cfb6bb36a0028c65ee615adeaa45c Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Mon, 18 Mar 2024 15:45:34 -1000 Subject: [PATCH] Refactor integration startup time to show wall clock time (#113707) * Refactor setup time tracking to exclude time waiting on other operations We now exclude the import time and th time waiting on base platforms to setup from the setup times * tweak * tweak * tweak * tweak * adjust * fixes * fixes * preen * preen * tweak * tweak * adjust * tweak * reduce * do not count integrtion platforms against their parent integration * handle legacy tts platforms * stt as well * one more wait * use the same pattern in all the legacy * fix tts and stt legacy * fix * fix * reduce * preen * entity comp does not wait for platforms * scene blocks as well * fix test * test fixes * coverage * coverage * coverage * fix test * Update tests/test_setup.py Co-authored-by: Martin Hjelmare * Update tests/test_setup.py Co-authored-by: Martin Hjelmare * Update homeassistant/setup.py Co-authored-by: Martin Hjelmare * strip * strip WAIT_PLATFORM_INTEGRATION * strip WAIT_PLATFORM_INTEGRATION * strip WAIT_PLATFORM_INTEGRATION * strip WAIT_PLATFORM_INTEGRATION * remove complexity * Apply suggestions from code review * no longer works that way * fixes * fixes * fixes --------- Co-authored-by: Martin Hjelmare --- homeassistant/bootstrap.py | 33 +-- .../components/device_tracker/legacy.py | 8 +- homeassistant/components/http/__init__.py | 8 +- homeassistant/components/notify/legacy.py | 13 +- homeassistant/components/scene/__init__.py | 5 +- homeassistant/components/stream/__init__.py | 4 +- homeassistant/components/stt/legacy.py | 22 +- homeassistant/components/tts/legacy.py | 36 ++- .../components/websocket_api/commands.py | 5 +- homeassistant/config_entries.py | 27 +- homeassistant/helpers/entity_platform.py | 143 +++++----- homeassistant/loader.py | 7 + homeassistant/setup.py | 180 ++++++++++--- tests/components/config/test_scene.py | 1 + tests/components/homeassistant/test_scene.py | 2 + tests/components/scene/test_init.py | 1 + .../components/websocket_api/test_commands.py | 17 +- tests/test_bootstrap.py | 5 +- tests/test_loader.py | 3 + tests/test_setup.py | 254 ++++++++++++++++-- 20 files changed, 598 insertions(+), 176 deletions(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 85ee15e3aa0..f98c029832e 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -3,8 +3,8 @@ from __future__ import annotations import asyncio +from collections import defaultdict import contextlib -from datetime import timedelta from functools import partial from itertools import chain import logging @@ -82,7 +82,7 @@ from .helpers.typing import ConfigType from .setup import ( BASE_PLATFORMS, DATA_SETUP_STARTED, - DATA_SETUP_TIME, + async_get_setup_timings, async_notify_setup_error, async_set_domains_to_be_loaded, async_setup_component, @@ -597,7 +597,9 @@ class _WatchPendingSetups: """Periodic log and dispatch of setups that are pending.""" def __init__( - self, hass: core.HomeAssistant, setup_started: dict[str, float] + self, + hass: core.HomeAssistant, + setup_started: dict[tuple[str, str | None], float], ) -> None: """Initialize the WatchPendingSetups class.""" self._hass = hass @@ -612,10 +614,11 @@ class _WatchPendingSetups: now = monotonic() self._duration_count += SLOW_STARTUP_CHECK_INTERVAL - remaining_with_setup_started = { - domain: (now - start_time) - for domain, start_time in self._setup_started.items() - } + remaining_with_setup_started: defaultdict[str, float] = defaultdict(float) + for integration_group, start_time in self._setup_started.items(): + domain, _ = integration_group + remaining_with_setup_started[domain] += now - start_time + if remaining_with_setup_started: _LOGGER.debug("Integration remaining: %s", remaining_with_setup_started) elif waiting_tasks := self._hass._active_tasks: # pylint: disable=protected-access @@ -629,7 +632,7 @@ class _WatchPendingSetups: # once we take over LOG_SLOW_STARTUP_INTERVAL (60s) to start up _LOGGER.warning( "Waiting on integrations to complete setup: %s", - ", ".join(self._setup_started), + self._setup_started, ) _LOGGER.debug("Running timeout Zones: %s", self._hass.timeout.zones) @@ -838,10 +841,8 @@ async def _async_set_up_integrations( hass: core.HomeAssistant, config: dict[str, Any] ) -> None: """Set up all the integrations.""" - setup_started: dict[str, float] = {} + setup_started: dict[tuple[str, str | None], float] = {} hass.data[DATA_SETUP_STARTED] = setup_started - setup_time: dict[str, timedelta] = hass.data.setdefault(DATA_SETUP_TIME, {}) - watcher = _WatchPendingSetups(hass, setup_started) watcher.async_start() @@ -934,7 +935,9 @@ async def _async_set_up_integrations( watcher.async_stop() - _LOGGER.debug( - "Integration setup times: %s", - dict(sorted(setup_time.items(), key=itemgetter(1))), - ) + if _LOGGER.isEnabledFor(logging.DEBUG): + setup_time = async_get_setup_timings(hass) + _LOGGER.debug( + "Integration setup times: %s", + dict(sorted(setup_time.items(), key=itemgetter(1), reverse=True)), + ) diff --git a/homeassistant/components/device_tracker/legacy.py b/homeassistant/components/device_tracker/legacy.py index 344443cd878..72fc4ef717b 100644 --- a/homeassistant/components/device_tracker/legacy.py +++ b/homeassistant/components/device_tracker/legacy.py @@ -50,6 +50,7 @@ from homeassistant.helpers.event import ( from homeassistant.helpers.restore_state import RestoreEntity from homeassistant.helpers.typing import ConfigType, GPSType, StateType from homeassistant.setup import ( + SetupPhases, async_notify_setup_error, async_prepare_setup_platform, async_start_setup, @@ -307,7 +308,12 @@ class DeviceTrackerPlatform: assert self.type == PLATFORM_TYPE_LEGACY full_name = f"{self.name}.{DOMAIN}" LOGGER.info("Setting up %s", full_name) - with async_start_setup(hass, [full_name]): + with async_start_setup( + hass, + integration=self.name, + group=str(id(self.config)), + phase=SetupPhases.PLATFORM_SETUP, + ): try: scanner = None setup: bool | None = None diff --git a/homeassistant/components/http/__init__.py b/homeassistant/components/http/__init__.py index b01d80c9997..c9f8c21e0a3 100644 --- a/homeassistant/components/http/__init__.py +++ b/homeassistant/components/http/__init__.py @@ -43,7 +43,11 @@ from homeassistant.helpers.http import ( from homeassistant.helpers.network import NoURLAvailableError, get_url from homeassistant.helpers.typing import ConfigType from homeassistant.loader import bind_hass -from homeassistant.setup import async_start_setup, async_when_setup_or_start +from homeassistant.setup import ( + SetupPhases, + async_start_setup, + async_when_setup_or_start, +) from homeassistant.util import dt as dt_util, ssl as ssl_util from homeassistant.util.async_ import create_eager_task from homeassistant.util.json import json_loads @@ -218,7 +222,7 @@ async def async_setup(hass: HomeAssistant, config: ConfigType) -> bool: async def start_server(*_: Any) -> None: """Start the server.""" - with async_start_setup(hass, ["http"]): + with async_start_setup(hass, integration="http", phase=SetupPhases.SETUP): hass.bus.async_listen_once(EVENT_HOMEASSISTANT_STOP, stop_server) # We already checked it's not None. assert conf is not None diff --git a/homeassistant/components/notify/legacy.py b/homeassistant/components/notify/legacy.py index 6b29df504d9..2f6984e36f1 100644 --- a/homeassistant/components/notify/legacy.py +++ b/homeassistant/components/notify/legacy.py @@ -16,7 +16,11 @@ from homeassistant.helpers.service import async_set_service_schema from homeassistant.helpers.template import Template from homeassistant.helpers.typing import ConfigType, DiscoveryInfoType from homeassistant.loader import async_get_integration, bind_hass -from homeassistant.setup import async_prepare_setup_platform, async_start_setup +from homeassistant.setup import ( + SetupPhases, + async_prepare_setup_platform, + async_start_setup, +) from homeassistant.util import slugify from homeassistant.util.yaml import load_yaml_dict @@ -84,7 +88,12 @@ def async_setup_legacy( full_name = f"{DOMAIN}.{integration_name}" LOGGER.info("Setting up %s", full_name) - with async_start_setup(hass, [full_name]): + with async_start_setup( + hass, + integration=integration_name, + group=str(id(p_config)), + phase=SetupPhases.PLATFORM_SETUP, + ): notify_service: BaseNotificationService | None = None try: if hasattr(platform, "async_get_service"): diff --git a/homeassistant/components/scene/__init__.py b/homeassistant/components/scene/__init__.py index 1baf25735fa..5a7df164e1f 100644 --- a/homeassistant/components/scene/__init__.py +++ b/homeassistant/components/scene/__init__.py @@ -66,7 +66,10 @@ async def async_setup(hass: HomeAssistant, config: ConfigType) -> bool: await component.async_setup(config) # Ensure Home Assistant platform always loaded. - await component.async_setup_platform(HA_DOMAIN, {"platform": HA_DOMAIN, STATES: []}) + hass.async_create_task( + component.async_setup_platform(HA_DOMAIN, {"platform": HA_DOMAIN, STATES: []}), + eager_start=True, + ) component.async_register_entity_service( SERVICE_TURN_ON, {ATTR_TRANSITION: vol.All(vol.Coerce(float), vol.Clamp(min=0, max=6553))}, diff --git a/homeassistant/components/stream/__init__.py b/homeassistant/components/stream/__init__.py index b092e6e8aa6..c1822d596ec 100644 --- a/homeassistant/components/stream/__init__.py +++ b/homeassistant/components/stream/__init__.py @@ -35,6 +35,7 @@ from homeassistant.core import Event, HomeAssistant, callback from homeassistant.exceptions import HomeAssistantError import homeassistant.helpers.config_validation as cv from homeassistant.helpers.typing import ConfigType +from homeassistant.setup import SetupPhases, async_pause_setup from homeassistant.util.async_ import create_eager_task from .const import ( @@ -221,7 +222,8 @@ async def async_setup(hass: HomeAssistant, config: ConfigType) -> bool: logging.getLogger(logging_namespace).setLevel(logging.ERROR) # This will load av so we run it in the executor - await hass.async_add_executor_job(set_pyav_logging, debug_enabled) + with async_pause_setup(hass, SetupPhases.WAIT_IMPORT_PACKAGES): + await hass.async_add_executor_job(set_pyav_logging, debug_enabled) # Keep import here so that we can import stream integration without installing reqs # pylint: disable-next=import-outside-toplevel diff --git a/homeassistant/components/stt/legacy.py b/homeassistant/components/stt/legacy.py index fc7738418f6..997835ef9f8 100644 --- a/homeassistant/components/stt/legacy.py +++ b/homeassistant/components/stt/legacy.py @@ -11,7 +11,11 @@ from homeassistant.config import config_per_platform from homeassistant.core import HomeAssistant, callback from homeassistant.helpers import discovery from homeassistant.helpers.typing import ConfigType, DiscoveryInfoType -from homeassistant.setup import async_prepare_setup_platform +from homeassistant.setup import ( + SetupPhases, + async_prepare_setup_platform, + async_start_setup, +) from .const import ( DATA_PROVIDERS, @@ -68,12 +72,20 @@ def async_setup_legacy( return try: - provider = await platform.async_get_engine(hass, p_config, discovery_info) + with async_start_setup( + hass, + integration=p_type, + group=str(id(p_config)), + phase=SetupPhases.PLATFORM_SETUP, + ): + provider = await platform.async_get_engine( + hass, p_config, discovery_info + ) - provider.name = p_type - provider.hass = hass + provider.name = p_type + provider.hass = hass - providers[provider.name] = provider + providers[provider.name] = provider except Exception: # pylint: disable=broad-except _LOGGER.exception("Error setting up platform: %s", p_type) return diff --git a/homeassistant/components/tts/legacy.py b/homeassistant/components/tts/legacy.py index 0214dcd13e9..88249ed107b 100644 --- a/homeassistant/components/tts/legacy.py +++ b/homeassistant/components/tts/legacy.py @@ -31,7 +31,11 @@ from homeassistant.helpers import discovery import homeassistant.helpers.config_validation as cv from homeassistant.helpers.service import async_set_service_schema from homeassistant.helpers.typing import ConfigType, DiscoveryInfoType -from homeassistant.setup import async_prepare_setup_platform +from homeassistant.setup import ( + SetupPhases, + async_prepare_setup_platform, + async_start_setup, +) from homeassistant.util.yaml import load_yaml_dict from .const import ( @@ -124,20 +128,26 @@ async def async_setup_legacy( return try: - if hasattr(platform, "async_get_engine"): - provider = await platform.async_get_engine( - hass, p_config, discovery_info - ) - else: - provider = await hass.async_add_executor_job( - platform.get_engine, hass, p_config, discovery_info - ) + with async_start_setup( + hass, + integration=p_type, + group=str(id(p_config)), + phase=SetupPhases.PLATFORM_SETUP, + ): + if hasattr(platform, "async_get_engine"): + provider = await platform.async_get_engine( + hass, p_config, discovery_info + ) + else: + provider = await hass.async_add_executor_job( + platform.get_engine, hass, p_config, discovery_info + ) - if provider is None: - _LOGGER.error("Error setting up platform: %s", p_type) - return + if provider is None: + _LOGGER.error("Error setting up platform: %s", p_type) + return - tts.async_register_legacy_engine(p_type, provider, p_config) + tts.async_register_legacy_engine(p_type, provider, p_config) except Exception: # pylint: disable=broad-except _LOGGER.exception("Error setting up platform: %s", p_type) return diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index dcdbae98689..191ea1ea996 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -55,7 +55,7 @@ from homeassistant.loader import ( async_get_integration_descriptions, async_get_integrations, ) -from homeassistant.setup import DATA_SETUP_TIME, async_get_loaded_integrations +from homeassistant.setup import async_get_loaded_integrations, async_get_setup_timings from homeassistant.util.json import format_unserializable_data from . import const, decorators, messages @@ -539,12 +539,11 @@ def handle_integration_setup_info( hass: HomeAssistant, connection: ActiveConnection, msg: dict[str, Any] ) -> None: """Handle integrations command.""" - setup_time: dict[str, float] = hass.data[DATA_SETUP_TIME] connection.send_result( msg["id"], [ {"domain": integration, "seconds": seconds} - for integration, seconds in setup_time.items() + for integration, seconds in async_get_setup_timings(hass).items() ], ) diff --git a/homeassistant/config_entries.py b/homeassistant/config_entries.py index cb854bcf0ad..b73c7b25e41 100644 --- a/homeassistant/config_entries.py +++ b/homeassistant/config_entries.py @@ -57,7 +57,14 @@ from .helpers.frame import report from .helpers.json import json_bytes, json_fragment from .helpers.typing import UNDEFINED, ConfigType, DiscoveryInfoType, UndefinedType from .loader import async_suggest_report_issue -from .setup import DATA_SETUP_DONE, async_process_deps_reqs, async_setup_component +from .setup import ( + DATA_SETUP_DONE, + SetupPhases, + async_pause_setup, + async_process_deps_reqs, + async_setup_component, + async_start_setup, +) from .util import uuid as uuid_util from .util.async_ import create_eager_task from .util.decorator import Registry @@ -529,10 +536,17 @@ class ConfigEntry: self._async_set_state(hass, ConfigEntryState.MIGRATION_ERROR, None) return + setup_phase = SetupPhases.CONFIG_ENTRY_SETUP + else: + setup_phase = SetupPhases.CONFIG_ENTRY_PLATFORM_SETUP + error_reason = None try: - result = await component.async_setup_entry(hass, self) + with async_start_setup( + hass, integration=self.domain, group=self.entry_id, phase=setup_phase + ): + result = await component.async_setup_entry(hass, self) if not isinstance(result, bool): _LOGGER.error( # type: ignore[unreachable] @@ -1838,7 +1852,9 @@ class ConfigEntries: ) -> None: """Forward the setup of an entry to platforms.""" integration = await loader.async_get_integration(self.hass, entry.domain) - await integration.async_get_platforms(platforms) + if not integration.platforms_are_loaded(platforms): + with async_pause_setup(self.hass, SetupPhases.WAIT_IMPORT_PLATFORMS): + await integration.async_get_platforms(platforms) await asyncio.gather( *( create_eager_task( @@ -1860,7 +1876,10 @@ class ConfigEntries: """ # Setup Component if not set up yet if domain not in self.hass.config.components: - result = await async_setup_component(self.hass, domain, self._hass_config) + with async_pause_setup(self.hass, SetupPhases.WAIT_BASE_PLATFORM_SETUP): + result = await async_setup_component( + self.hass, domain, self._hass_config + ) if not result: return False diff --git a/homeassistant/helpers/entity_platform.py b/homeassistant/helpers/entity_platform.py index cc829cc9bd2..b0e094f97b4 100644 --- a/homeassistant/helpers/entity_platform.py +++ b/homeassistant/helpers/entity_platform.py @@ -32,7 +32,7 @@ from homeassistant.core import ( ) from homeassistant.exceptions import HomeAssistantError, PlatformNotReady from homeassistant.generated import languages -from homeassistant.setup import async_start_setup +from homeassistant.setup import SetupPhases, async_start_setup from homeassistant.util.async_ import create_eager_task from . import ( @@ -284,7 +284,13 @@ class EntityPlatform: discovery_info, ) - await self._async_setup_platform(async_create_setup_awaitable) + with async_start_setup( + hass, + integration=self.platform_name, + group=str(id(platform_config)), + phase=SetupPhases.PLATFORM_SETUP, + ): + await self._async_setup_platform(async_create_setup_awaitable) @callback def async_shutdown(self) -> None: @@ -341,81 +347,78 @@ class EntityPlatform: self.platform_name, SLOW_SETUP_WARNING, ) - with async_start_setup(hass, [full_name]): - try: - awaitable = async_create_setup_awaitable() - if asyncio.iscoroutine(awaitable): - awaitable = create_eager_task(awaitable) + try: + awaitable = async_create_setup_awaitable() + if asyncio.iscoroutine(awaitable): + awaitable = create_eager_task(awaitable) - async with hass.timeout.async_timeout(SLOW_SETUP_MAX_WAIT, self.domain): - await asyncio.shield(awaitable) + async with hass.timeout.async_timeout(SLOW_SETUP_MAX_WAIT, self.domain): + await asyncio.shield(awaitable) - # Block till all entities are done - while self._tasks: - # Await all tasks even if they are done - # to ensure exceptions are propagated - pending = self._tasks.copy() - self._tasks.clear() - await asyncio.gather(*pending) + # Block till all entities are done + while self._tasks: + # Await all tasks even if they are done + # to ensure exceptions are propagated + pending = self._tasks.copy() + self._tasks.clear() + await asyncio.gather(*pending) - hass.config.components.add(full_name) - self._setup_complete = True - return True - except PlatformNotReady as ex: - tries += 1 - wait_time = min(tries, 6) * PLATFORM_NOT_READY_BASE_WAIT_TIME - message = str(ex) - ready_message = f"ready yet: {message}" if message else "ready yet" - if tries == 1: - logger.warning( - "Platform %s not %s; Retrying in background in %d seconds", - self.platform_name, - ready_message, - wait_time, - ) - else: - logger.debug( - "Platform %s not %s; Retrying in %d seconds", - self.platform_name, - ready_message, - wait_time, - ) - - async def setup_again(*_args: Any) -> None: - """Run setup again.""" - self._async_cancel_retry_setup = None - await self._async_setup_platform( - async_create_setup_awaitable, tries - ) - - if hass.state is CoreState.running: - self._async_cancel_retry_setup = async_call_later( - hass, wait_time, setup_again - ) - else: - self._async_cancel_retry_setup = hass.bus.async_listen_once( - EVENT_HOMEASSISTANT_STARTED, setup_again - ) - return False - except TimeoutError: - logger.error( - ( - "Setup of platform %s is taking longer than %s seconds." - " Startup will proceed without waiting any longer." - ), + hass.config.components.add(full_name) + self._setup_complete = True + return True + except PlatformNotReady as ex: + tries += 1 + wait_time = min(tries, 6) * PLATFORM_NOT_READY_BASE_WAIT_TIME + message = str(ex) + ready_message = f"ready yet: {message}" if message else "ready yet" + if tries == 1: + logger.warning( + "Platform %s not %s; Retrying in background in %d seconds", self.platform_name, - SLOW_SETUP_MAX_WAIT, + ready_message, + wait_time, ) - return False - except Exception: # pylint: disable=broad-except - logger.exception( - "Error while setting up %s platform for %s", + else: + logger.debug( + "Platform %s not %s; Retrying in %d seconds", self.platform_name, - self.domain, + ready_message, + wait_time, ) - return False - finally: - warn_task.cancel() + + async def setup_again(*_args: Any) -> None: + """Run setup again.""" + self._async_cancel_retry_setup = None + await self._async_setup_platform(async_create_setup_awaitable, tries) + + if hass.state is CoreState.running: + self._async_cancel_retry_setup = async_call_later( + hass, wait_time, setup_again + ) + else: + self._async_cancel_retry_setup = hass.bus.async_listen_once( + EVENT_HOMEASSISTANT_STARTED, setup_again + ) + return False + except TimeoutError: + logger.error( + ( + "Setup of platform %s is taking longer than %s seconds." + " Startup will proceed without waiting any longer." + ), + self.platform_name, + SLOW_SETUP_MAX_WAIT, + ) + return False + except Exception: # pylint: disable=broad-except + logger.exception( + "Error while setting up %s platform for %s", + self.platform_name, + self.domain, + ) + return False + finally: + warn_task.cancel() async def _async_get_translations( self, language: str, category: str, integration: str diff --git a/homeassistant/loader.py b/homeassistant/loader.py index fe825e84bdf..74250a3a150 100644 --- a/homeassistant/loader.py +++ b/homeassistant/loader.py @@ -1172,6 +1172,13 @@ class Integration: raise self._missing_platforms_cache[full_name] return None + def platforms_are_loaded(self, platform_names: Iterable[str]) -> bool: + """Check if a platforms are loaded for an integration.""" + return all( + f"{self.domain}.{platform_name}" in self._cache + for platform_name in platform_names + ) + def get_platform_cached(self, platform_name: str) -> ModuleType | None: """Return a platform for an integration from cache.""" return self._cache.get(f"{self.domain}.{platform_name}") # type: ignore[return-value] diff --git a/homeassistant/setup.py b/homeassistant/setup.py index 45e3b328fc3..f8a123ab797 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -3,8 +3,11 @@ from __future__ import annotations import asyncio -from collections.abc import Awaitable, Callable, Generator, Iterable +from collections import defaultdict +from collections.abc import Awaitable, Callable, Generator, Mapping import contextlib +import contextvars +from enum import StrEnum import logging.handlers import time from timeit import default_timer as timer @@ -29,9 +32,13 @@ from .exceptions import DependencyError, HomeAssistantError from .helpers import translation from .helpers.issue_registry import IssueSeverity, async_create_issue from .helpers.typing import ConfigType -from .util import ensure_unique_string from .util.async_ import create_eager_task +current_setup_group: contextvars.ContextVar[ + tuple[str, str | None] | None +] = contextvars.ContextVar("current_setup_group", default=None) + + _LOGGER = logging.getLogger(__name__) ATTR_COMPONENT: Final = "component" @@ -54,12 +61,12 @@ DATA_SETUP = "setup_tasks" # is finished, regardless of if the setup was successful or not. DATA_SETUP_DONE = "setup_done" -# DATA_SETUP_STARTED is a dict [str, float], indicating when an attempt +# DATA_SETUP_STARTED is a dict [tuple[str, str | None], float], indicating when an attempt # to setup a component started. DATA_SETUP_STARTED = "setup_started" -# DATA_SETUP_TIME is a dict [str, timedelta], indicating how time was spent -# setting up a component. +# DATA_SETUP_TIME is a defaultdict[str, defaultdict[str | None, defaultdict[SetupPhases, float]]] +# indicating how time was spent setting up a component and each group (config entry). DATA_SETUP_TIME = "setup_time" DATA_DEPS_REQS = "deps_reqs_processed" @@ -358,7 +365,7 @@ async def _async_setup_component( # noqa: C901 translation.async_load_integrations(hass, integration_set) ) - with async_start_setup(hass, integration_set): + with async_start_setup(hass, integration=domain, phase=SetupPhases.SETUP): if hasattr(component, "PLATFORM_SCHEMA"): # Entity components have their own warning warn_task = None @@ -430,18 +437,18 @@ async def _async_setup_component( # noqa: C901 # call to avoid a deadlock when forwarding platforms hass.config.components.add(domain) - if entries := hass.config_entries.async_entries( - domain, include_ignore=False, include_disabled=False - ): - await asyncio.gather( - *( - create_eager_task( - entry.async_setup(hass, integration=integration), - name=f"config entry setup {entry.title} {entry.domain} {entry.entry_id}", - ) - for entry in entries + if entries := hass.config_entries.async_entries( + domain, include_ignore=False, include_disabled=False + ): + await asyncio.gather( + *( + create_eager_task( + entry.async_setup(hass, integration=integration), + name=f"config entry setup {entry.title} {entry.domain} {entry.entry_id}", ) + for entry in entries ) + ) # Cleanup if domain in hass.data[DATA_SETUP]: @@ -626,27 +633,134 @@ def async_get_loaded_integrations(hass: core.HomeAssistant) -> set[str]: return integrations +class SetupPhases(StrEnum): + """Constants for setup time measurements.""" + + SETUP = "setup" + """Set up of a component in __init__.py.""" + CONFIG_ENTRY_SETUP = "config_entry_setup" + """Set up of a config entry in __init__.py.""" + PLATFORM_SETUP = "platform_setup" + """Set up of a platform integration. + + ex async_setup_platform or setup_platform or + a legacy platform like device_tracker.legacy + """ + CONFIG_ENTRY_PLATFORM_SETUP = "config_entry_platform_setup" + """Set up of a platform in a config entry after the config entry is setup. + + This is only for platforms that are not awaited in async_setup_entry. + """ + WAIT_BASE_PLATFORM_SETUP = "wait_base_component" + """Wait time for the base component to be setup.""" + WAIT_IMPORT_PLATFORMS = "wait_import_platforms" + """Wait time for the platforms to import.""" + WAIT_IMPORT_PACKAGES = "wait_import_packages" + """Wait time for the packages to import.""" + + +@contextlib.contextmanager +def async_pause_setup( + hass: core.HomeAssistant, phase: SetupPhases +) -> Generator[None, None, None]: + """Keep track of time we are blocked waiting for other operations. + + We want to count the time we wait for importing and + setting up the base components so we can subtract it + from the total setup time. + """ + if not (running := current_setup_group.get()): + # This means we are likely in a late platform setup + # that is running in a task so we do not want + # to subtract out the time later as nothing is waiting + # for the code inside the context manager to finish. + yield + return + + started = time.monotonic() + try: + yield + finally: + time_taken = time.monotonic() - started + integration, group = running + # Add negative time for the time we waited + _setup_times(hass)[integration][group][phase] = -time_taken + + +def _setup_times( + hass: core.HomeAssistant, +) -> defaultdict[str, defaultdict[str | None, defaultdict[SetupPhases, float]]]: + """Return the setup timings default dict.""" + if DATA_SETUP_TIME not in hass.data: + hass.data[DATA_SETUP_TIME] = defaultdict( + lambda: defaultdict(lambda: defaultdict(float)) + ) + return hass.data[DATA_SETUP_TIME] # type: ignore[no-any-return] + + @contextlib.contextmanager def async_start_setup( - hass: core.HomeAssistant, components: Iterable[str] + hass: core.HomeAssistant, + integration: str, + phase: SetupPhases, + group: str | None = None, ) -> Generator[None, None, None]: - """Keep track of when setup starts and finishes.""" + """Keep track of when setup starts and finishes. + + :param hass: Home Assistant instance + :param integration: The integration that is being setup + :param phase: The phase of setup + :param group: The group (config entry/platform instance) that is being setup + + A group is a group of setups that run in parallel. + + """ + if hass.is_stopping or hass.state is core.CoreState.running: + # Don't track setup times when we are shutting down or already running + # as we present the timings as "Integration startup time", and we + # don't want to add all the setup retry times to that. + yield + return + + setup_started: dict[tuple[str, str | None], float] setup_started = hass.data.setdefault(DATA_SETUP_STARTED, {}) + current = (integration, group) + if current in setup_started: + # We are already inside another async_start_setup, this like means we + # are setting up a platform inside async_setup_entry so we should not + # record this as a new setup + yield + return + started = time.monotonic() - unique_components: dict[str, str] = {} - for domain in components: - unique = ensure_unique_string(domain, setup_started) - unique_components[unique] = domain - setup_started[unique] = started + current_setup_group.set(current) + setup_started[current] = started - yield + try: + yield + finally: + time_taken = time.monotonic() - started + del setup_started[current] + _setup_times(hass)[integration][group][phase] = time_taken - setup_time: dict[str, float] = hass.data.setdefault(DATA_SETUP_TIME, {}) - time_taken = time.monotonic() - started - for unique, domain in unique_components.items(): - del setup_started[unique] - integration = domain.partition(".")[0] - if integration in setup_time: - setup_time[integration] += time_taken - else: - setup_time[integration] = time_taken + +@callback +def async_get_setup_timings(hass: core.HomeAssistant) -> dict[str, float]: + """Return timing data for each integration.""" + setup_time = _setup_times(hass) + domain_timings: dict[str, float] = {} + top_level_timings: Mapping[SetupPhases, float] + for domain, timings in setup_time.items(): + top_level_timings = timings.get(None, {}) + total_top_level = sum(top_level_timings.values()) + # Groups (config entries/platform instance) are setup in parallel so we + # take the max of the group timings and add it to the top level + group_totals = { + group: sum(group_timings.values()) + for group, group_timings in timings.items() + if group is not None + } + group_max = max(group_totals.values(), default=0) + domain_timings[domain] = total_top_level + group_max + + return domain_timings diff --git a/tests/components/config/test_scene.py b/tests/components/config/test_scene.py index b270ac26a9b..dfb7cdad8c6 100644 --- a/tests/components/config/test_scene.py +++ b/tests/components/config/test_scene.py @@ -19,6 +19,7 @@ from tests.typing import ClientSessionGenerator async def setup_scene(hass, scene_config): """Set up scene integration.""" assert await async_setup_component(hass, "scene", {"scene": scene_config}) + await hass.async_block_till_done() @pytest.mark.parametrize("scene_config", ({},)) diff --git a/tests/components/homeassistant/test_scene.py b/tests/components/homeassistant/test_scene.py index 033d414d4a9..a1a532db162 100644 --- a/tests/components/homeassistant/test_scene.py +++ b/tests/components/homeassistant/test_scene.py @@ -18,6 +18,7 @@ from tests.common import async_capture_events, async_mock_service async def test_reload_config_service(hass: HomeAssistant) -> None: """Test the reload config service.""" assert await async_setup_component(hass, "scene", {}) + await hass.async_block_till_done() test_reloaded_event = async_capture_events(hass, EVENT_SCENE_RELOADED) @@ -175,6 +176,7 @@ async def test_delete_service( "scene", {"scene": {"name": "hallo_2", "entities": {"light.kitchen": "on"}}}, ) + await hass.async_block_till_done() await hass.services.async_call( "scene", diff --git a/tests/components/scene/test_init.py b/tests/components/scene/test_init.py index c797c26f35a..660be91dca2 100644 --- a/tests/components/scene/test_init.py +++ b/tests/components/scene/test_init.py @@ -228,6 +228,7 @@ async def activate(hass, entity_id=ENTITY_MATCH_ALL): async def test_services_registered(hass: HomeAssistant) -> None: """Test we register services with empty config.""" assert await async_setup_component(hass, "scene", {}) + await hass.async_block_till_done() assert hass.services.has_service("scene", "reload") assert hass.services.has_service("scene", "turn_on") assert hass.services.has_service("scene", "apply") diff --git a/tests/components/websocket_api/test_commands.py b/tests/components/websocket_api/test_commands.py index 7eee2261a26..5f10451799b 100644 --- a/tests/components/websocket_api/test_commands.py +++ b/tests/components/websocket_api/test_commands.py @@ -23,7 +23,7 @@ from homeassistant.exceptions import HomeAssistantError, ServiceValidationError from homeassistant.helpers import device_registry as dr from homeassistant.helpers.dispatcher import async_dispatcher_send from homeassistant.loader import async_get_integration -from homeassistant.setup import DATA_SETUP_TIME, async_setup_component +from homeassistant.setup import async_setup_component from homeassistant.util.json import json_loads from tests.common import ( @@ -2491,13 +2491,16 @@ async def test_integration_setup_info( hass_admin_user: MockUser, ) -> None: """Test subscribe/unsubscribe bootstrap_integrations.""" - hass.data[DATA_SETUP_TIME] = { - "august": 12.5, - "isy994": 12.8, - } - await websocket_client.send_json({"id": 7, "type": "integration/setup_info"}) + with patch( + "homeassistant.components.websocket_api.commands.async_get_setup_timings", + return_value={ + "august": 12.5, + "isy994": 12.8, + }, + ): + await websocket_client.send_json({"id": 7, "type": "integration/setup_info"}) + msg = await websocket_client.receive_json() - msg = await websocket_client.receive_json() assert msg["id"] == 7 assert msg["type"] == const.TYPE_RESULT assert msg["success"] diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index 996126ad1b6..4dc322c5a29 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -14,7 +14,7 @@ from homeassistant import bootstrap, loader, runner import homeassistant.config as config_util from homeassistant.config_entries import HANDLERS, ConfigEntry from homeassistant.const import SIGNAL_BOOTSTRAP_INTEGRATIONS -from homeassistant.core import HomeAssistant, async_get_hass, callback +from homeassistant.core import CoreState, HomeAssistant, async_get_hass, callback from homeassistant.exceptions import HomeAssistantError from homeassistant.helpers.dispatcher import async_dispatcher_connect from homeassistant.helpers.typing import ConfigType @@ -869,6 +869,9 @@ async def test_empty_integrations_list_is_only_sent_at_the_end_of_bootstrap( hass: HomeAssistant, ) -> None: """Test empty integrations list is only sent at the end of bootstrap.""" + # setup times only tracked when not running + hass.set_state(CoreState.not_running) + order = [] def gen_domain_setup(domain): diff --git a/tests/test_loader.py b/tests/test_loader.py index ae21d75a6e1..c8a8905cdef 100644 --- a/tests/test_loader.py +++ b/tests/test_loader.py @@ -1520,6 +1520,9 @@ async def test_platforms_exists( assert integration.platforms_exists(["group"]) == ["group"] + assert integration.platforms_are_loaded(["group"]) is True + assert integration.platforms_are_loaded(["other"]) is False + async def test_async_get_platforms_loads_loop_if_already_in_sys_modules( hass: HomeAssistant, diff --git a/tests/test_setup.py b/tests/test_setup.py index c54c02fd880..28366a50a82 100644 --- a/tests/test_setup.py +++ b/tests/test_setup.py @@ -2,14 +2,14 @@ import asyncio import threading -from unittest.mock import AsyncMock, Mock, patch +from unittest.mock import ANY, AsyncMock, Mock, patch import pytest import voluptuous as vol from homeassistant import config_entries, loader, setup from homeassistant.const import EVENT_COMPONENT_LOADED, EVENT_HOMEASSISTANT_START -from homeassistant.core import HomeAssistant, callback +from homeassistant.core import CoreState, HomeAssistant, callback from homeassistant.exceptions import HomeAssistantError from homeassistant.helpers import discovery, translation from homeassistant.helpers.config_validation import ( @@ -727,26 +727,244 @@ async def test_integration_only_setup_entry(hass: HomeAssistant) -> None: assert await setup.async_setup_component(hass, "test_integration_only_entry", {}) -async def test_async_start_setup(hass: HomeAssistant) -> None: - """Test setup started context manager keeps track of setup times.""" - with setup.async_start_setup(hass, ["august"]): - assert isinstance(hass.data[setup.DATA_SETUP_STARTED]["august"], float) - with setup.async_start_setup(hass, ["august"]): - assert isinstance(hass.data[setup.DATA_SETUP_STARTED]["august_2"], float) +async def test_async_start_setup_running(hass: HomeAssistant) -> None: + """Test setup started context manager does nothing when running.""" + assert hass.state is CoreState.running + setup_started: dict[tuple[str, str | None], float] + setup_started = hass.data.setdefault(setup.DATA_SETUP_STARTED, {}) - assert "august" not in hass.data[setup.DATA_SETUP_STARTED] - assert isinstance(hass.data[setup.DATA_SETUP_TIME]["august"], float) - assert "august_2" not in hass.data[setup.DATA_SETUP_TIME] + with setup.async_start_setup( + hass, integration="august", phase=setup.SetupPhases.SETUP + ): + assert not setup_started -async def test_async_start_setup_platforms(hass: HomeAssistant) -> None: - """Test setup started context manager keeps track of setup times for platforms.""" - with setup.async_start_setup(hass, ["august.sensor"]): - assert isinstance(hass.data[setup.DATA_SETUP_STARTED]["august.sensor"], float) +async def test_async_start_setup_config_entry(hass: HomeAssistant) -> None: + """Test setup started keeps track of setup times with a config entry.""" + hass.set_state(CoreState.not_running) + setup_started: dict[tuple[str, str | None], float] + setup_started = hass.data.setdefault(setup.DATA_SETUP_STARTED, {}) + setup_time = setup._setup_times(hass) - assert "august" not in hass.data[setup.DATA_SETUP_STARTED] - assert isinstance(hass.data[setup.DATA_SETUP_TIME]["august"], float) - assert "sensor" not in hass.data[setup.DATA_SETUP_TIME] + with setup.async_start_setup( + hass, integration="august", phase=setup.SetupPhases.SETUP + ): + assert isinstance(setup_started[("august", None)], float) + + with setup.async_start_setup( + hass, + integration="august", + group="entry_id", + phase=setup.SetupPhases.CONFIG_ENTRY_SETUP, + ): + assert isinstance(setup_started[("august", "entry_id")], float) + with setup.async_start_setup( + hass, + integration="august", + group="entry_id", + phase=setup.SetupPhases.CONFIG_ENTRY_PLATFORM_SETUP, + ): + assert isinstance(setup_started[("august", "entry_id")], float) + + # CONFIG_ENTRY_PLATFORM_SETUP inside of CONFIG_ENTRY_SETUP should not be tracked + assert setup_time["august"] == { + None: {setup.SetupPhases.SETUP: ANY}, + "entry_id": {setup.SetupPhases.CONFIG_ENTRY_SETUP: ANY}, + } + with setup.async_start_setup( + hass, + integration="august", + group="entry_id", + phase=setup.SetupPhases.CONFIG_ENTRY_PLATFORM_SETUP, + ): + assert isinstance(setup_started[("august", "entry_id")], float) + # Platforms outside of CONFIG_ENTRY_SETUP should be tracked + # This simulates a late platform forward + assert setup_time["august"] == { + None: {setup.SetupPhases.SETUP: ANY}, + "entry_id": { + setup.SetupPhases.CONFIG_ENTRY_SETUP: ANY, + setup.SetupPhases.CONFIG_ENTRY_PLATFORM_SETUP: ANY, + }, + } + + with setup.async_start_setup( + hass, + integration="august", + group="entry_id2", + phase=setup.SetupPhases.CONFIG_ENTRY_SETUP, + ): + assert isinstance(setup_started[("august", "entry_id2")], float) + # We wrap places where we wait for other components + # or the import of a module with async_freeze_setup + # so we can subtract the time waited from the total setup time + with setup.async_pause_setup(hass, setup.SetupPhases.WAIT_BASE_PLATFORM_SETUP): + await asyncio.sleep(0) + + # Wait time should be added if freeze_setup is used + assert setup_time["august"] == { + None: {setup.SetupPhases.SETUP: ANY}, + "entry_id": { + setup.SetupPhases.CONFIG_ENTRY_SETUP: ANY, + setup.SetupPhases.CONFIG_ENTRY_PLATFORM_SETUP: ANY, + }, + "entry_id2": { + setup.SetupPhases.CONFIG_ENTRY_SETUP: ANY, + setup.SetupPhases.WAIT_BASE_PLATFORM_SETUP: ANY, + }, + } + + +async def test_async_start_setup_top_level_yaml(hass: HomeAssistant) -> None: + """Test setup started context manager keeps track of setup times with modern yaml.""" + hass.set_state(CoreState.not_running) + setup_started: dict[tuple[str, str | None], float] + setup_started = hass.data.setdefault(setup.DATA_SETUP_STARTED, {}) + setup_time = setup._setup_times(hass) + + with setup.async_start_setup( + hass, integration="command_line", phase=setup.SetupPhases.SETUP + ): + assert isinstance(setup_started[("command_line", None)], float) + + assert setup_time["command_line"] == { + None: {setup.SetupPhases.SETUP: ANY}, + } + + +async def test_async_start_setup_platform_integration(hass: HomeAssistant) -> None: + """Test setup started keeps track of setup times a platform integration.""" + hass.set_state(CoreState.not_running) + setup_started: dict[tuple[str, str | None], float] + setup_started = hass.data.setdefault(setup.DATA_SETUP_STARTED, {}) + setup_time = setup._setup_times(hass) + + with setup.async_start_setup( + hass, integration="sensor", phase=setup.SetupPhases.SETUP + ): + assert isinstance(setup_started[("sensor", None)], float) + + # Platform integration setups happen in another task + with setup.async_start_setup( + hass, + integration="filter", + group="123456", + phase=setup.SetupPhases.PLATFORM_SETUP, + ): + assert isinstance(setup_started[("filter", "123456")], float) + + assert setup_time["sensor"] == { + None: { + setup.SetupPhases.SETUP: ANY, + }, + } + assert setup_time["filter"] == { + "123456": { + setup.SetupPhases.PLATFORM_SETUP: ANY, + }, + } + + +async def test_async_start_setup_legacy_platform_integration( + hass: HomeAssistant, +) -> None: + """Test setup started keeps track of setup times for a legacy platform integration.""" + hass.set_state(CoreState.not_running) + setup_started: dict[tuple[str, str | None], float] + setup_started = hass.data.setdefault(setup.DATA_SETUP_STARTED, {}) + setup_time = setup._setup_times(hass) + + with setup.async_start_setup( + hass, integration="notify", phase=setup.SetupPhases.SETUP + ): + assert isinstance(setup_started[("notify", None)], float) + + with setup.async_start_setup( + hass, + integration="legacy_notify_integration", + group="123456", + phase=setup.SetupPhases.PLATFORM_SETUP, + ): + assert isinstance(setup_started[("legacy_notify_integration", "123456")], float) + + assert setup_time["notify"] == { + None: { + setup.SetupPhases.SETUP: ANY, + }, + } + assert setup_time["legacy_notify_integration"] == { + "123456": { + setup.SetupPhases.PLATFORM_SETUP: ANY, + }, + } + + +async def test_async_start_setup_simple_integration_end_to_end( + hass: HomeAssistant, +) -> None: + """Test end to end timings for a simple integration with no platforms.""" + hass.set_state(CoreState.not_running) + mock_integration( + hass, + MockModule( + "test_integration_no_platforms", + setup=False, + async_setup_entry=AsyncMock(return_value=True), + ), + ) + assert await setup.async_setup_component(hass, "test_integration_no_platforms", {}) + await hass.async_block_till_done() + assert setup.async_get_setup_timings(hass) == { + "test_integration_no_platforms": ANY, + } + + +async def test_async_get_setup_timings(hass) -> None: + """Test we can get the setup timings from the setup time data.""" + setup_time = setup._setup_times(hass) + # Mock setup time data + setup_time.update( + { + "august": { + None: {setup.SetupPhases.SETUP: 1}, + "entry_id": { + setup.SetupPhases.CONFIG_ENTRY_SETUP: 1, + setup.SetupPhases.CONFIG_ENTRY_PLATFORM_SETUP: 4, + }, + "entry_id2": { + setup.SetupPhases.CONFIG_ENTRY_SETUP: 7, + setup.SetupPhases.WAIT_BASE_PLATFORM_SETUP: -5, + }, + }, + "notify": { + None: { + setup.SetupPhases.SETUP: 2, + }, + }, + "legacy_notify_integration": { + "123456": { + setup.SetupPhases.PLATFORM_SETUP: 3, + }, + }, + "sensor": { + None: { + setup.SetupPhases.SETUP: 1, + }, + }, + "filter": { + "123456": { + setup.SetupPhases.PLATFORM_SETUP: 2, + }, + }, + } + ) + assert setup.async_get_setup_timings(hass) == { + "august": 6, + "notify": 2, + "legacy_notify_integration": 3, + "sensor": 1, + "filter": 2, + } async def test_setup_config_entry_from_yaml(