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
This commit is contained in:
J. Nick Koston 2022-06-14 07:46:00 -10:00 committed by GitHub
parent f69ea6017d
commit 9b157f974d
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 19 additions and 14 deletions

View File

@ -1286,6 +1286,7 @@ def async_track_point_in_utc_time(
"""Add a listener that fires once after a specific point in UTC time.""" """Add a listener that fires once after a specific point in UTC time."""
# Ensure point_in_time is UTC # Ensure point_in_time is UTC
utc_point_in_time = dt_util.as_utc(point_in_time) 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 # 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. # 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: def run_action(job: HassJob[[datetime], Awaitable[None] | None]) -> None:
"""Call the action.""" """Call the action."""
nonlocal cancel_callback nonlocal cancel_callback
now = time_tracker_utcnow()
# Depending on the available clock support (including timer hardware # Depending on the available clock support (including timer hardware
# and the OS kernel) it can happen that we fire a little bit too early # 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 # as measured by utcnow(). That is bad when callbacks have assumptions
# about the current time. Thus, we rearm the timer for the remaining # about the current time. Thus, we rearm the timer for the remaining
# time. # 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) _LOGGER.debug("Called %f seconds too early, rearming", delta)
cancel_callback = hass.loop.call_later(delta, run_action, job) 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 # For targeted patching in tests
time_tracker_utcnow = dt_util.utcnow time_tracker_utcnow = dt_util.utcnow
time_tracker_timestamp = time.time
@callback @callback

View File

@ -378,7 +378,10 @@ def async_fire_time_changed(
) -> None: ) -> None:
"""Fire a time changed event.""" """Fire a time changed event."""
if datetime_ is None: 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): for task in list(hass.loop._scheduled):
if not isinstance(task, asyncio.TimerHandle): if not isinstance(task, asyncio.TimerHandle):
@ -386,13 +389,16 @@ def async_fire_time_changed(
if task.cancelled(): if task.cancelled():
continue continue
mock_seconds_into_future = datetime_.timestamp() - time.time() mock_seconds_into_future = timestamp - time.time()
future_seconds = task.when() - hass.loop.time() future_seconds = task.when() - hass.loop.time()
if fire_all or mock_seconds_into_future >= future_seconds: if fire_all or mock_seconds_into_future >= future_seconds:
with patch( with patch(
"homeassistant.helpers.event.time_tracker_utcnow", "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._run()
task.cancel() task.cancel()

View File

@ -14,7 +14,6 @@ from .conftest import setup_integration
BUTTON_ENTITY = "button.test_reset_waste_drawer" 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: async def test_button(hass: HomeAssistant, mock_account: MagicMock) -> None:
"""Test the creation and values of the Litter-Robot button.""" """Test the creation and values of the Litter-Robot button."""
await setup_integration(hass, mock_account, BUTTON_DOMAIN) 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
assert entry.entity_category is EntityCategory.CONFIG assert entry.entity_category is EntityCategory.CONFIG
await hass.services.async_call( with freeze_time("2021-11-15 17:37:00", tz_offset=-7):
BUTTON_DOMAIN, await hass.services.async_call(
SERVICE_PRESS, BUTTON_DOMAIN,
{ATTR_ENTITY_ID: BUTTON_ENTITY}, SERVICE_PRESS,
blocking=True, {ATTR_ENTITY_ID: BUTTON_ENTITY},
) blocking=True,
)
await hass.async_block_till_done() await hass.async_block_till_done()
assert mock_account.robots[0].reset_waste_drawer.call_count == 1 assert mock_account.robots[0].reset_waste_drawer.call_count == 1
mock_account.robots[0].reset_waste_drawer.assert_called_with() mock_account.robots[0].reset_waste_drawer.assert_called_with()