Refactor integration startup time tracking to reduce overhead (#110136)

* Refactor integration startup time tracking to reduce overhead

- Use monotonic time for watching integration startup time as it avoids incorrect values if time moves backwards because of ntp during startup and reduces many time conversions since we want durations in seconds and not local time

- Use loop scheduling instead of a task

- Moves all the dispatcher logic into the new _WatchPendingSetups

* websocket as well

* tweaks

* simplify logic

* preserve logic

* preserve logic

* lint

* adjust

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:
+class _WatchPendingSetups:
-    """Periodic log of setups that are pending.
+    """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()
+            domain: (now - start_time)
-            for domain in setup_started
+            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:
+        if remaining_with_setup_started or not self._previous_was_empty:
-            async_dispatcher_send(
+            self._async_dispatch(remaining_with_setup_started)
-                hass, SIGNAL_BOOTSTRAP_INTEGRATIONS, remaining_with_setup_started
+        self._previous_was_empty = not 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 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()
+    watcher.async_stop()
-    async_dispatcher_send(hass, SIGNAL_BOOTSTRAP_INTEGRATIONS, {})
 
     _LOGGER.debug(
         "Integration setup times: %s",
-        {
+        dict(sorted(setup_time.items(), key=itemgetter(1))),
-            integration: timedelta.total_seconds()
-            for integration, timedelta in sorted(
-                setup_time.items(), key=lambda item: item[1].total_seconds()
-            )
-        },
     )

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()}
+            {"domain": integration, "seconds": seconds}
-            for integration, timedelta in cast(
+            for integration, seconds in setup_time.items()
-                dict[str, dt.timedelta], hass.data[DATA_SETUP_TIME]
-            ).items()
         ],
     )
 

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, {})
+    setup_time: dict[str, float] = hass.data.setdefault(DATA_SETUP_TIME, {})
-    time_taken = dt_util.utcnow() - started
+    time_taken = time.monotonic() - started
     for unique, domain in unique_components.items():
         del setup_started[unique]
         integration = domain.partition(".")[0]

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),
+        "august": 12.5,
-        "isy994": datetime.timedelta(seconds=12.8),
+        "isy994": 12.8,
     }
     await websocket_client.send_json({"id": 7, "type": "integration/setup_info"})
 

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(
+        assert isinstance(hass.data[setup.DATA_SETUP_STARTED]["august"], float)
-            hass.data[setup.DATA_SETUP_STARTED]["august"], datetime.datetime
-        )
         with setup.async_start_setup(hass, ["august"]):
-            assert isinstance(
+            assert isinstance(hass.data[setup.DATA_SETUP_STARTED]["august_2"], float)
-                hass.data[setup.DATA_SETUP_STARTED]["august_2"], datetime.datetime
-            )
 
     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(
+        assert isinstance(hass.data[setup.DATA_SETUP_STARTED]["august.sensor"], float)
-            hass.data[setup.DATA_SETUP_STARTED]["august.sensor"], datetime.datetime
-        )
 
     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]