From 9b157f974d80b4d5e98562b85f846d5f9ea4ea73 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 14 Jun 2022 07:46:00 -1000 Subject: [PATCH] Reduce overhead to refire events from async_track_point_in_utc_time when an asyncio timer fires early (#73295) * Reduce overhead to refire events - asyncio timers can fire early for a varity of reasons including poor clock resolution and performance. To solve this problem we re-arm async_track_point_in_utc_time and try again later when this happens. - On some platforms this means the async_track_point_in_utc_time can end up trying many times to prevent firing the timer early since as soon as it rearms it fires again and this repeats until we reach the appointed time. While there is not much we can do to prevent asyncio from firing the timer callback early, we can reduce the overhead when this happens by using avoiding creating datetime objects * tweak mocking * -vvv * fix time freeze being too broad in litterrobot * adjust --- homeassistant/helpers/event.py | 7 +++---- tests/common.py | 12 +++++++++--- tests/components/litterrobot/test_button.py | 14 +++++++------- 3 files changed, 19 insertions(+), 14 deletions(-) diff --git a/homeassistant/helpers/event.py b/homeassistant/helpers/event.py index c9b569c6601..85cd684fca1 100644 --- a/homeassistant/helpers/event.py +++ b/homeassistant/helpers/event.py @@ -1286,6 +1286,7 @@ def async_track_point_in_utc_time( """Add a listener that fires once after a specific point in UTC time.""" # Ensure point_in_time is UTC utc_point_in_time = dt_util.as_utc(point_in_time) + expected_fire_timestamp = dt_util.utc_to_timestamp(utc_point_in_time) # Since this is called once, we accept a HassJob so we can avoid # having to figure out how to call the action every time its called. @@ -1295,15 +1296,12 @@ def async_track_point_in_utc_time( def run_action(job: HassJob[[datetime], Awaitable[None] | None]) -> None: """Call the action.""" nonlocal cancel_callback - - now = time_tracker_utcnow() - # Depending on the available clock support (including timer hardware # and the OS kernel) it can happen that we fire a little bit too early # as measured by utcnow(). That is bad when callbacks have assumptions # about the current time. Thus, we rearm the timer for the remaining # time. - if (delta := (utc_point_in_time - now).total_seconds()) > 0: + if (delta := (expected_fire_timestamp - time_tracker_timestamp())) > 0: _LOGGER.debug("Called %f seconds too early, rearming", delta) cancel_callback = hass.loop.call_later(delta, run_action, job) @@ -1474,6 +1472,7 @@ track_sunset = threaded_listener_factory(async_track_sunset) # For targeted patching in tests time_tracker_utcnow = dt_util.utcnow +time_tracker_timestamp = time.time @callback diff --git a/tests/common.py b/tests/common.py index bd0b828737b..1a29d0d6dc4 100644 --- a/tests/common.py +++ b/tests/common.py @@ -378,7 +378,10 @@ def async_fire_time_changed( ) -> None: """Fire a time changed event.""" if datetime_ is None: - datetime_ = date_util.utcnow() + utc_datetime = date_util.utcnow() + else: + utc_datetime = date_util.as_utc(datetime_) + timestamp = date_util.utc_to_timestamp(utc_datetime) for task in list(hass.loop._scheduled): if not isinstance(task, asyncio.TimerHandle): @@ -386,13 +389,16 @@ def async_fire_time_changed( if task.cancelled(): continue - mock_seconds_into_future = datetime_.timestamp() - time.time() + mock_seconds_into_future = timestamp - time.time() future_seconds = task.when() - hass.loop.time() if fire_all or mock_seconds_into_future >= future_seconds: with patch( "homeassistant.helpers.event.time_tracker_utcnow", - return_value=date_util.as_utc(datetime_), + return_value=utc_datetime, + ), patch( + "homeassistant.helpers.event.time_tracker_timestamp", + return_value=timestamp, ): task._run() task.cancel() diff --git a/tests/components/litterrobot/test_button.py b/tests/components/litterrobot/test_button.py index 3f802d0e6b2..6291558c832 100644 --- a/tests/components/litterrobot/test_button.py +++ b/tests/components/litterrobot/test_button.py @@ -14,7 +14,6 @@ from .conftest import setup_integration BUTTON_ENTITY = "button.test_reset_waste_drawer" -@freeze_time("2021-11-15 17:37:00", tz_offset=-7) async def test_button(hass: HomeAssistant, mock_account: MagicMock) -> None: """Test the creation and values of the Litter-Robot button.""" await setup_integration(hass, mock_account, BUTTON_DOMAIN) @@ -29,12 +28,13 @@ async def test_button(hass: HomeAssistant, mock_account: MagicMock) -> None: assert entry assert entry.entity_category is EntityCategory.CONFIG - await hass.services.async_call( - BUTTON_DOMAIN, - SERVICE_PRESS, - {ATTR_ENTITY_ID: BUTTON_ENTITY}, - blocking=True, - ) + with freeze_time("2021-11-15 17:37:00", tz_offset=-7): + await hass.services.async_call( + BUTTON_DOMAIN, + SERVICE_PRESS, + {ATTR_ENTITY_ID: BUTTON_ENTITY}, + blocking=True, + ) await hass.async_block_till_done() assert mock_account.robots[0].reset_waste_drawer.call_count == 1 mock_account.robots[0].reset_waste_drawer.assert_called_with()