diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index d9a83aa2485..7f2280e481e 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -4,9 +4,10 @@ from __future__ import annotations import asyncio from collections.abc import Coroutine import contextlib -from datetime import datetime, timedelta +from datetime import timedelta import logging import logging.handlers +from operator import itemgetter import os import platform import sys @@ -49,7 +50,6 @@ from .setup import ( async_set_domains_to_be_loaded, async_setup_component, ) -from .util import dt as dt_util from .util.logging import async_activate_log_queue_handler from .util.package import async_get_user_site, is_virtual_env @@ -545,36 +545,70 @@ def _get_domains(hass: core.HomeAssistant, config: dict[str, Any]) -> set[str]: return domains -async def _async_watch_pending_setups(hass: core.HomeAssistant) -> None: - """Periodic log of setups that are pending. +class _WatchPendingSetups: + """Periodic log and dispatch of setups that are pending.""" + + def __init__( + self, hass: core.HomeAssistant, setup_started: dict[str, float] + ) -> None: + """Initialize the WatchPendingSetups class.""" + self._hass = hass + self._setup_started = setup_started + self._duration_count = 0 + self._handle: asyncio.TimerHandle | None = None + self._previous_was_empty = True + self._loop = hass.loop + + def _async_watch(self) -> None: + """Periodic log of setups that are pending.""" + now = monotonic() + self._duration_count += SLOW_STARTUP_CHECK_INTERVAL - Pending for longer than LOG_SLOW_STARTUP_INTERVAL. - """ - loop_count = 0 - setup_started: dict[str, datetime] = hass.data[DATA_SETUP_STARTED] - previous_was_empty = True - while True: - now = dt_util.utcnow() remaining_with_setup_started = { - domain: (now - setup_started[domain]).total_seconds() - for domain in setup_started + domain: (now - start_time) + for domain, start_time in self._setup_started.items() } _LOGGER.debug("Integration remaining: %s", remaining_with_setup_started) - if remaining_with_setup_started or not previous_was_empty: - async_dispatcher_send( - hass, SIGNAL_BOOTSTRAP_INTEGRATIONS, remaining_with_setup_started - ) - previous_was_empty = not remaining_with_setup_started - await asyncio.sleep(SLOW_STARTUP_CHECK_INTERVAL) - loop_count += SLOW_STARTUP_CHECK_INTERVAL + if remaining_with_setup_started or not self._previous_was_empty: + self._async_dispatch(remaining_with_setup_started) + self._previous_was_empty = not remaining_with_setup_started - if loop_count >= LOG_SLOW_STARTUP_INTERVAL and setup_started: + if ( + self._setup_started + and self._duration_count % LOG_SLOW_STARTUP_INTERVAL == 0 + ): + # We log every LOG_SLOW_STARTUP_INTERVAL until all integrations are done + # once we take over LOG_SLOW_STARTUP_INTERVAL (60s) to start up _LOGGER.warning( "Waiting on integrations to complete setup: %s", - ", ".join(setup_started), + ", ".join(self._setup_started), ) - loop_count = 0 - _LOGGER.debug("Running timeout Zones: %s", hass.timeout.zones) + + _LOGGER.debug("Running timeout Zones: %s", self._hass.timeout.zones) + self._async_schedule_next() + + def _async_dispatch(self, remaining_with_setup_started: dict[str, float]) -> None: + """Dispatch the signal.""" + async_dispatcher_send( + self._hass, SIGNAL_BOOTSTRAP_INTEGRATIONS, remaining_with_setup_started + ) + + def _async_schedule_next(self) -> None: + """Schedule the next call.""" + self._handle = self._loop.call_later( + SLOW_STARTUP_CHECK_INTERVAL, self._async_watch + ) + + def async_start(self) -> None: + """Start watching.""" + self._async_schedule_next() + + def async_stop(self) -> None: + """Stop watching.""" + self._async_dispatch({}) + if self._handle: + self._handle.cancel() + self._handle = None async def async_setup_multi_components( @@ -683,10 +717,12 @@ async def _async_set_up_integrations( hass: core.HomeAssistant, config: dict[str, Any] ) -> None: """Set up all the integrations.""" - hass.data[DATA_SETUP_STARTED] = {} + setup_started: dict[str, float] = {} + hass.data[DATA_SETUP_STARTED] = setup_started setup_time: dict[str, timedelta] = hass.data.setdefault(DATA_SETUP_TIME, {}) - watch_task = asyncio.create_task(_async_watch_pending_setups(hass)) + watcher = _WatchPendingSetups(hass, setup_started) + watcher.async_start() domains_to_setup, integration_cache = await _async_resolve_domains_to_setup( hass, config @@ -782,15 +818,9 @@ async def _async_set_up_integrations( except TimeoutError: _LOGGER.warning("Setup timed out for bootstrap - moving forward") - watch_task.cancel() - async_dispatcher_send(hass, SIGNAL_BOOTSTRAP_INTEGRATIONS, {}) + watcher.async_stop() _LOGGER.debug( "Integration setup times: %s", - { - integration: timedelta.total_seconds() - for integration, timedelta in sorted( - setup_time.items(), key=lambda item: item[1].total_seconds() - ) - }, + dict(sorted(setup_time.items(), key=itemgetter(1))), ) diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index c2f7a8ce669..368785c17bc 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -2,7 +2,6 @@ from __future__ import annotations from collections.abc import Callable -import datetime as dt from functools import lru_cache, partial import json import logging @@ -540,13 +539,12 @@ 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": timedelta.total_seconds()} - for integration, timedelta in cast( - dict[str, dt.timedelta], hass.data[DATA_SETUP_TIME] - ).items() + {"domain": integration, "seconds": seconds} + for integration, seconds in setup_time.items() ], ) diff --git a/homeassistant/setup.py b/homeassistant/setup.py index 7850f1c1db3..238f3bf3ac7 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -4,8 +4,8 @@ from __future__ import annotations import asyncio from collections.abc import Awaitable, Callable, Generator, Iterable import contextlib -from datetime import timedelta import logging.handlers +import time from timeit import default_timer as timer from types import ModuleType from typing import Any, Final, TypedDict @@ -21,7 +21,7 @@ from .core import CALLBACK_TYPE, DOMAIN as HOMEASSISTANT_DOMAIN, HomeAssistant, from .exceptions import DependencyError, HomeAssistantError from .helpers.issue_registry import IssueSeverity, async_create_issue from .helpers.typing import ConfigType, EventType -from .util import dt as dt_util, ensure_unique_string +from .util import ensure_unique_string _LOGGER = logging.getLogger(__name__) @@ -566,7 +566,7 @@ def async_start_setup( ) -> Generator[None, None, None]: """Keep track of when setup starts and finishes.""" setup_started = hass.data.setdefault(DATA_SETUP_STARTED, {}) - started = dt_util.utcnow() + started = time.monotonic() unique_components: dict[str, str] = {} for domain in components: unique = ensure_unique_string(domain, setup_started) @@ -575,8 +575,8 @@ def async_start_setup( yield - setup_time: dict[str, timedelta] = hass.data.setdefault(DATA_SETUP_TIME, {}) - time_taken = dt_util.utcnow() - started + 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] diff --git a/tests/components/websocket_api/test_commands.py b/tests/components/websocket_api/test_commands.py index 88fa914f5a7..a6a2fb06d7b 100644 --- a/tests/components/websocket_api/test_commands.py +++ b/tests/components/websocket_api/test_commands.py @@ -1,7 +1,6 @@ """Tests for WebSocket API commands.""" import asyncio from copy import deepcopy -import datetime import logging from unittest.mock import ANY, AsyncMock, Mock, patch @@ -2494,8 +2493,8 @@ async def test_integration_setup_info( ) -> None: """Test subscribe/unsubscribe bootstrap_integrations.""" hass.data[DATA_SETUP_TIME] = { - "august": datetime.timedelta(seconds=12.5), - "isy994": datetime.timedelta(seconds=12.8), + "august": 12.5, + "isy994": 12.8, } await websocket_client.send_json({"id": 7, "type": "integration/setup_info"}) diff --git a/tests/test_setup.py b/tests/test_setup.py index 14c56d39a5a..bdf27cb7d8a 100644 --- a/tests/test_setup.py +++ b/tests/test_setup.py @@ -1,7 +1,6 @@ """Test component/platform setup.""" import asyncio -import datetime import threading from unittest.mock import AsyncMock, Mock, patch @@ -714,28 +713,22 @@ async def test_integration_only_setup_entry(hass: HomeAssistant) -> None: 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"], datetime.datetime - ) + 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"], datetime.datetime - ) + assert isinstance(hass.data[setup.DATA_SETUP_STARTED]["august_2"], float) assert "august" not in hass.data[setup.DATA_SETUP_STARTED] - assert isinstance(hass.data[setup.DATA_SETUP_TIME]["august"], datetime.timedelta) + assert isinstance(hass.data[setup.DATA_SETUP_TIME]["august"], float) assert "august_2" not in hass.data[setup.DATA_SETUP_TIME] 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"], datetime.datetime - ) + assert isinstance(hass.data[setup.DATA_SETUP_STARTED]["august.sensor"], float) assert "august" not in hass.data[setup.DATA_SETUP_STARTED] - assert isinstance(hass.data[setup.DATA_SETUP_TIME]["august"], datetime.timedelta) + assert isinstance(hass.data[setup.DATA_SETUP_TIME]["august"], float) assert "sensor" not in hass.data[setup.DATA_SETUP_TIME]