Fix setup timings when config entry platform loads are not awaited (h…

…ome-assistant#113959)

* Move setup time logging into the context manager

We were fetching the time twice but since the context
manager already has the timing, move it there

* remove log setup assertions from integration test

* tweak logging to give us better data for tracking issues

* redundant

* adjust

* preen

* fixes

* adjust

* make api change internal so nobody uses it

* coverage

* fix test

* fix more tests

* coverage

* more tests assuming internal calls

* fix more

* adjust

* adjust

* fix axis tests

* fix broadlink -- it does not call async_forward_entry_setup

* missed some

* remove useless patch

* rename, detect it both ways

* clear

* debug

* try to fix

* handle phase finishing out while paused

* where its set does not need to know its late as that is an implemenation detail of setup

* where its set does not need to know its late as that is an implemenation detail of setup

* tweak

* simplify

* reduce complexity

* revert order change as it makes review harder

* revert naming changes as it makes review harder

* improve comment

* improve debug

* late dispatch test

* test the other way as well

* Update setup.py

* Update setup.py

* Update setup.py

* simplify

* reduce

homeassistant/config_entries.py

@@ -1858,7 +1858,7 @@ async def async_forward_entry_setups(
         await asyncio.gather(
             *(
                 create_eager_task(
-                    self.async_forward_entry_setup(entry, platform),
+                    self._async_forward_entry_setup(entry, platform, False),
                     name=f"config entry forward setup {entry.title} {entry.domain} {entry.entry_id} {platform}",
                 )
                 for platform in platforms
@@ -1874,6 +1874,12 @@ async def async_forward_entry_setup(
         component also has related platforms, the component will have to
         forward the entry to be setup by that component.
         """
+        return await self._async_forward_entry_setup(entry, domain, True)
+
+    async def _async_forward_entry_setup(
+        self, entry: ConfigEntry, domain: Platform | str, preload_platform: bool
+    ) -> bool:
+        """Forward the setup of an entry to a different component."""
         # Setup Component if not set up yet
         if domain not in self.hass.config.components:
             with async_pause_setup(self.hass, SetupPhases.WAIT_BASE_PLATFORM_SETUP):
@@ -1884,8 +1890,16 @@ async def async_forward_entry_setup(
             if not result:
                 return False
 
-        integration = await loader.async_get_integration(self.hass, domain)
+        if preload_platform:
+            # If this is a late setup, we need to make sure the platform is loaded
+            # so we do not end up waiting for when the EntityComponent calls
+            # async_prepare_setup_platform
+            integration = await loader.async_get_integration(self.hass, entry.domain)
+            if not integration.platforms_are_loaded((domain,)):
+                with async_pause_setup(self.hass, SetupPhases.WAIT_IMPORT_PLATFORMS):
+                    await integration.async_get_platform(domain)
 
+        integration = await loader.async_get_integration(self.hass, domain)
         await entry.async_setup(self.hass, integration=integration)
         return True
 

homeassistant/setup.py

@@ -10,7 +10,6 @@
 from enum import StrEnum
 import logging.handlers
 import time
-from timeit import default_timer as timer
 from types import ModuleType
 from typing import Any, Final, TypedDict
 
@@ -351,7 +350,6 @@ def log_error(msg: str, exc_info: Exception | None = None) -> None:
             },
         )
 
-    start = timer()
     _LOGGER.info("Setting up %s", domain)
     integration_set = {domain}
 
@@ -412,11 +410,8 @@ def log_error(msg: str, exc_info: Exception | None = None) -> None:
             async_notify_setup_error(hass, domain, integration.documentation)
             return False
         finally:
-            end = timer()
             if warn_task:
                 warn_task.cancel()
-        _LOGGER.info("Setup of domain %s took %.1f seconds", domain, end - start)
-
         if result is False:
             log_error("Integration failed to initialize.")
             return False
@@ -663,6 +658,15 @@ class SetupPhases(StrEnum):
     """Wait time for the packages to import."""
 
 
+def _setup_started(
+    hass: core.HomeAssistant,
+) -> dict[tuple[str, str | None], float]:
+    """Return the setup started dict."""
+    if DATA_SETUP_STARTED not in hass.data:
+        hass.data[DATA_SETUP_STARTED] = {}
+    return hass.data[DATA_SETUP_STARTED]  # type: ignore[no-any-return]
+
+
 @contextlib.contextmanager
 def async_pause_setup(
     hass: core.HomeAssistant, phase: SetupPhases
@@ -673,7 +677,9 @@ def async_pause_setup(
     setting up the base components so we can subtract it
     from the total setup time.
     """
-    if not (running := current_setup_group.get()):
+    if not (running := current_setup_group.get()) or running not in _setup_started(
+        hass
+    ):
         # 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
@@ -689,6 +695,13 @@ def async_pause_setup(
         integration, group = running
         # Add negative time for the time we waited
         _setup_times(hass)[integration][group][phase] = -time_taken
+        _LOGGER.debug(
+            "Adding wait for %s for %s (%s) of %.2f",
+            phase,
+            integration,
+            group,
+            time_taken,
+        )
 
 
 def _setup_times(
@@ -726,8 +739,7 @@ def async_start_setup(
         yield
         return
 
-    setup_started: dict[tuple[str, str | None], float]
-    setup_started = hass.data.setdefault(DATA_SETUP_STARTED, {})
+    setup_started = _setup_started(hass)
     current = (integration, group)
     if current in setup_started:
         # We are already inside another async_start_setup, this like means we
@@ -745,7 +757,26 @@ def async_start_setup(
     finally:
         time_taken = time.monotonic() - started
         del setup_started[current]
-        _setup_times(hass)[integration][group][phase] = time_taken
+        group_setup_times = _setup_times(hass)[integration][group]
+        # We may see the phase multiple times if there are multiple
+        # platforms, but we only care about the longest time.
+        group_setup_times[phase] = max(group_setup_times[phase], time_taken)
+        if group is None:
+            _LOGGER.info(
+                "Setup of domain %s took %.2f seconds", integration, time_taken
+            )
+        elif _LOGGER.isEnabledFor(logging.DEBUG):
+            wait_time = -sum(value for value in group_setup_times.values() if value < 0)
+            calculated_time = time_taken - wait_time
+            _LOGGER.debug(
+                "Phase %s for %s (%s) took %.2fs (elapsed=%.2fs) (wait_time=%.2fs)",
+                phase,
+                integration,
+                group,
+                calculated_time,
+                time_taken,
+                wait_time,
+            )
 
 
 @callback

tests/components/axis/test_hub.py

@@ -35,16 +35,18 @@
 from tests.typing import MqttMockHAClient
 
 
-@pytest.fixture(name="forward_entry_setup")
+@pytest.fixture(name="forward_entry_setups")
 def hass_mock_forward_entry_setup(hass):
-    """Mock async_forward_entry_setup."""
-    with patch.object(hass.config_entries, "async_forward_entry_setup") as forward_mock:
+    """Mock async_forward_entry_setups."""
+    with patch.object(
+        hass.config_entries, "async_forward_entry_setups"
+    ) as forward_mock:
         yield forward_mock
 
 
 async def test_device_setup(
     hass: HomeAssistant,
-    forward_entry_setup,
+    forward_entry_setups,
     config_entry_data,
     setup_config_entry,
     device_registry: dr.DeviceRegistry,
@@ -57,11 +59,9 @@ async def test_device_setup(
     assert hub.api.vapix.product_type == "Network Camera"
     assert hub.api.vapix.serial_number == "00408C123456"
 
-    assert len(forward_entry_setup.mock_calls) == 4
-    assert forward_entry_setup.mock_calls[0][1][1] == "binary_sensor"
-    assert forward_entry_setup.mock_calls[1][1][1] == "camera"
-    assert forward_entry_setup.mock_calls[2][1][1] == "light"
-    assert forward_entry_setup.mock_calls[3][1][1] == "switch"
+    assert len(forward_entry_setups.mock_calls) == 1
+    platforms = set(forward_entry_setups.mock_calls[0][1][1])
+    assert platforms == {"binary_sensor", "camera", "light", "switch"}
 
     assert hub.config.host == config_entry_data[CONF_HOST]
     assert hub.config.model == config_entry_data[CONF_MODEL]

tests/components/broadlink/test_device.py

@@ -21,7 +21,7 @@ async def test_device_setup(hass: HomeAssistant) -> None:
     device = get_device("Office")
 
     with patch.object(
-        hass.config_entries, "async_forward_entry_setup"
+        hass.config_entries, "async_forward_entry_setups"
     ) as mock_forward, patch.object(
         hass.config_entries.flow, "async_init"
     ) as mock_init:
@@ -32,9 +32,9 @@ async def test_device_setup(hass: HomeAssistant) -> None:
     assert mock_setup.api.get_fwversion.call_count == 1
     assert mock_setup.factory.call_count == 1
 
-    forward_entries = {c[1][1] for c in mock_forward.mock_calls}
+    forward_entries = set(mock_forward.mock_calls[0][1][1])
     domains = get_domains(mock_setup.api.type)
-    assert mock_forward.call_count == len(domains)
+    assert mock_forward.call_count == 1
     assert forward_entries == domains
     assert mock_init.call_count == 0
 
@@ -46,7 +46,7 @@ async def test_device_setup_authentication_error(hass: HomeAssistant) -> None:
     mock_api.auth.side_effect = blke.AuthenticationError()
 
     with patch.object(
-        hass.config_entries, "async_forward_entry_setup"
+        hass.config_entries, "async_forward_entry_setups"
     ) as mock_forward, patch.object(
         hass.config_entries.flow, "async_init"
     ) as mock_init:
@@ -70,7 +70,7 @@ async def test_device_setup_network_timeout(hass: HomeAssistant) -> None:
     mock_api.auth.side_effect = blke.NetworkTimeoutError()
 
     with patch.object(
-        hass.config_entries, "async_forward_entry_setup"
+        hass.config_entries, "async_forward_entry_setups"
     ) as mock_forward, patch.object(
         hass.config_entries.flow, "async_init"
     ) as mock_init:
@@ -89,7 +89,7 @@ async def test_device_setup_os_error(hass: HomeAssistant) -> None:
     mock_api.auth.side_effect = OSError()
 
     with patch.object(
-        hass.config_entries, "async_forward_entry_setup"
+        hass.config_entries, "async_forward_entry_setups"
     ) as mock_forward, patch.object(
         hass.config_entries.flow, "async_init"
     ) as mock_init:
@@ -108,7 +108,7 @@ async def test_device_setup_broadlink_exception(hass: HomeAssistant) -> None:
     mock_api.auth.side_effect = blke.BroadlinkException()
 
     with patch.object(
-        hass.config_entries, "async_forward_entry_setup"
+        hass.config_entries, "async_forward_entry_setups"
     ) as mock_forward, patch.object(
         hass.config_entries.flow, "async_init"
     ) as mock_init:
@@ -127,7 +127,7 @@ async def test_device_setup_update_network_timeout(hass: HomeAssistant) -> None:
     mock_api.check_sensors.side_effect = blke.NetworkTimeoutError()
 
     with patch.object(
-        hass.config_entries, "async_forward_entry_setup"
+        hass.config_entries, "async_forward_entry_setups"
     ) as mock_forward, patch.object(
         hass.config_entries.flow, "async_init"
     ) as mock_init:
@@ -150,7 +150,7 @@ async def test_device_setup_update_authorization_error(hass: HomeAssistant) -> N
     )
 
     with patch.object(
-        hass.config_entries, "async_forward_entry_setup"
+        hass.config_entries, "async_forward_entry_setups"
     ) as mock_forward, patch.object(
         hass.config_entries.flow, "async_init"
     ) as mock_init:
@@ -160,9 +160,9 @@ async def test_device_setup_update_authorization_error(hass: HomeAssistant) -> N
     assert mock_setup.api.auth.call_count == 2
     assert mock_setup.api.check_sensors.call_count == 2
 
-    forward_entries = {c[1][1] for c in mock_forward.mock_calls}
+    forward_entries = set(mock_forward.mock_calls[0][1][1])
     domains = get_domains(mock_api.type)
-    assert mock_forward.call_count == len(domains)
+    assert mock_forward.call_count == 1
     assert forward_entries == domains
     assert mock_init.call_count == 0
 
@@ -175,7 +175,7 @@ async def test_device_setup_update_authentication_error(hass: HomeAssistant) ->
     mock_api.auth.side_effect = (None, blke.AuthenticationError())
 
     with patch.object(
-        hass.config_entries, "async_forward_entry_setup"
+        hass.config_entries, "async_forward_entry_setups"
     ) as mock_forward, patch.object(
         hass.config_entries.flow, "async_init"
     ) as mock_init:
@@ -200,7 +200,7 @@ async def test_device_setup_update_broadlink_exception(hass: HomeAssistant) -> N
     mock_api.check_sensors.side_effect = blke.BroadlinkException()
 
     with patch.object(
-        hass.config_entries, "async_forward_entry_setup"
+        hass.config_entries, "async_forward_entry_setups"
     ) as mock_forward, patch.object(
         hass.config_entries.flow, "async_init"
     ) as mock_init:
@@ -221,13 +221,15 @@ async def test_device_setup_get_fwversion_broadlink_exception(
     mock_api = device.get_mock_api()
     mock_api.get_fwversion.side_effect = blke.BroadlinkException()
 
-    with patch.object(hass.config_entries, "async_forward_entry_setup") as mock_forward:
+    with patch.object(
+        hass.config_entries, "async_forward_entry_setups"
+    ) as mock_forward:
         mock_setup = await device.setup_entry(hass, mock_api=mock_api)
 
     assert mock_setup.entry.state is ConfigEntryState.LOADED
-    forward_entries = {c[1][1] for c in mock_forward.mock_calls}
+    forward_entries = set(mock_forward.mock_calls[0][1][1])
     domains = get_domains(mock_setup.api.type)
-    assert mock_forward.call_count == len(domains)
+    assert mock_forward.call_count == 1
     assert forward_entries == domains
 
 
@@ -237,13 +239,15 @@ async def test_device_setup_get_fwversion_os_error(hass: HomeAssistant) -> None:
     mock_api = device.get_mock_api()
     mock_api.get_fwversion.side_effect = OSError()
 
-    with patch.object(hass.config_entries, "async_forward_entry_setup") as mock_forward:
+    with patch.object(
+        hass.config_entries, "async_forward_entry_setups"
+    ) as mock_forward:
         mock_setup = await device.setup_entry(hass, mock_api=mock_api)
 
     assert mock_setup.entry.state is ConfigEntryState.LOADED
-    forward_entries = {c[1][1] for c in mock_forward.mock_calls}
+    forward_entries = set(mock_forward.mock_calls[0][1][1])
     domains = get_domains(mock_setup.api.type)
-    assert mock_forward.call_count == len(domains)
+    assert mock_forward.call_count == 1
     assert forward_entries == domains
 
 
@@ -281,7 +285,7 @@ async def test_device_unload_works(hass: HomeAssistant) -> None:
     """Test we unload the device."""
     device = get_device("Office")
 
-    with patch.object(hass.config_entries, "async_forward_entry_setup"):
+    with patch.object(hass.config_entries, "async_forward_entry_setups"):
         mock_setup = await device.setup_entry(hass)
 
     with patch.object(
@@ -302,7 +306,7 @@ async def test_device_unload_authentication_error(hass: HomeAssistant) -> None:
     mock_api = device.get_mock_api()
     mock_api.auth.side_effect = blke.AuthenticationError()
 
-    with patch.object(hass.config_entries, "async_forward_entry_setup"), patch.object(
+    with patch.object(hass.config_entries, "async_forward_entry_setups"), patch.object(
         hass.config_entries.flow, "async_init"
     ):
         mock_setup = await device.setup_entry(hass, mock_api=mock_api)
@@ -322,7 +326,7 @@ async def test_device_unload_update_failed(hass: HomeAssistant) -> None:
     mock_api = device.get_mock_api()
     mock_api.check_sensors.side_effect = blke.NetworkTimeoutError()
 
-    with patch.object(hass.config_entries, "async_forward_entry_setup"):
+    with patch.object(hass.config_entries, "async_forward_entry_setups"):
         mock_setup = await device.setup_entry(hass, mock_api=mock_api)
 
     with patch.object(