From 3e0c6c176a739f4b4507a309f59384f59a3b8e96 Mon Sep 17 00:00:00 2001 From: Anders Melchiorsen Date: Mon, 17 Sep 2018 10:10:50 +0200 Subject: [PATCH] Rework timer delays (#16650) * Calibrate timer for each tick * Return of timer out of sync detection --- homeassistant/core.py | 27 ++++++++++++++----------- tests/test_core.py | 47 ++++++++++++++++++++++++------------------- 2 files changed, 41 insertions(+), 33 deletions(-) diff --git a/homeassistant/core.py b/homeassistant/core.py index 18520ed5d0c..e8d50e003d9 100644 --- a/homeassistant/core.py +++ b/homeassistant/core.py @@ -1230,22 +1230,26 @@ def _async_create_timer(hass: HomeAssistant) -> None: """Create a timer that will start on HOMEASSISTANT_START.""" handle = None - @callback - def fire_time_event(nxt: float) -> None: - """Fire next time event.""" + def schedule_tick(now: datetime.datetime) -> None: + """Schedule a timer tick when the next second rolls around.""" nonlocal handle + slp_seconds = 1 - (now.microsecond / 10**6) + target = monotonic() + slp_seconds + handle = hass.loop.call_later(slp_seconds, fire_time_event, target) + + @callback + def fire_time_event(target: float) -> None: + """Fire next time event.""" + now = dt_util.utcnow() + hass.bus.async_fire(EVENT_TIME_CHANGED, - {ATTR_NOW: dt_util.utcnow()}) - nxt += 1 - slp_seconds = nxt - monotonic() + {ATTR_NOW: now}) - if slp_seconds < 0: + if monotonic() > target + 1: _LOGGER.error('Timer got out of sync. Resetting') - nxt = monotonic() + 1 - slp_seconds = 1 - handle = hass.loop.call_later(slp_seconds, fire_time_event, nxt) + schedule_tick(now) @callback def stop_timer(_: Event) -> None: @@ -1256,5 +1260,4 @@ def _async_create_timer(hass: HomeAssistant) -> None: hass.bus.async_listen_once(EVENT_HOMEASSISTANT_STOP, stop_timer) _LOGGER.info("Timer:starting") - slp_seconds = 1 - (dt_util.utcnow().microsecond / 10**6) - hass.loop.call_later(slp_seconds, lambda: fire_time_event(monotonic())) + schedule_tick(dt_util.utcnow()) diff --git a/tests/test_core.py b/tests/test_core.py index 4eecf995811..d88257abfb4 100644 --- a/tests/test_core.py +++ b/tests/test_core.py @@ -4,7 +4,7 @@ import asyncio import logging import os import unittest -from unittest.mock import patch, MagicMock, sentinel +from unittest.mock import patch, MagicMock from datetime import datetime, timedelta from tempfile import TemporaryDirectory @@ -858,23 +858,25 @@ def test_create_timer(mock_monotonic, loop): funcs.append(func) return orig_callback(func) - mock_monotonic.side_effect = 10.2, 10.3 + mock_monotonic.side_effect = 10.2, 10.8, 11.3 with patch.object(ha, 'callback', mock_callback), \ patch('homeassistant.core.dt_util.utcnow', return_value=datetime(2018, 12, 31, 3, 4, 5, 333333)): ha._async_create_timer(hass) + assert len(funcs) == 2 + fire_time_event, stop_timer = funcs + assert len(hass.loop.call_later.mock_calls) == 1 - slp_seconds, action = hass.loop.call_later.mock_calls[0][1] - assert abs(slp_seconds - 0.666667) < 0.001 + delay, callback, target = hass.loop.call_later.mock_calls[0][1] + assert abs(delay - 0.666667) < 0.001 + assert callback is fire_time_event + assert abs(target - 10.866667) < 0.001 with patch('homeassistant.core.dt_util.utcnow', - return_value=sentinel.mock_date): - action() - - assert len(funcs) == 2 - fire_time_event, stop_timer = funcs + return_value=datetime(2018, 12, 31, 3, 4, 6, 100000)): + callback(target) assert len(hass.bus.async_listen_once.mock_calls) == 1 assert len(hass.bus.async_fire.mock_calls) == 1 @@ -884,14 +886,14 @@ def test_create_timer(mock_monotonic, loop): assert event_type == EVENT_HOMEASSISTANT_STOP assert callback is stop_timer - slp_seconds, callback, nxt = hass.loop.call_later.mock_calls[1][1] - assert abs(slp_seconds - 0.9) < 0.001 + delay, callback, target = hass.loop.call_later.mock_calls[1][1] + assert abs(delay - 0.9) < 0.001 assert callback is fire_time_event - assert abs(nxt - 11.2) < 0.001 + assert abs(target - 12.2) < 0.001 event_type, event_data = hass.bus.async_fire.mock_calls[0][1] assert event_type == EVENT_TIME_CHANGED - assert event_data[ATTR_NOW] is sentinel.mock_date + assert event_data[ATTR_NOW] == datetime(2018, 12, 31, 3, 4, 6, 100000) @patch('homeassistant.core.monotonic') @@ -905,28 +907,31 @@ def test_timer_out_of_sync(mock_monotonic, loop): funcs.append(func) return orig_callback(func) - mock_monotonic.side_effect = 10.2, 11.3, 11.3 + mock_monotonic.side_effect = 10.2, 13.3, 13.4 with patch.object(ha, 'callback', mock_callback), \ patch('homeassistant.core.dt_util.utcnow', return_value=datetime(2018, 12, 31, 3, 4, 5, 333333)): ha._async_create_timer(hass) - _, action = hass.loop.call_later.mock_calls[0][1] + delay, callback, target = hass.loop.call_later.mock_calls[0][1] - with patch('homeassistant.core.dt_util.utcnow', - return_value=sentinel.mock_date): - action() + with patch.object(ha, '_LOGGER', MagicMock()) as mock_logger, \ + patch('homeassistant.core.dt_util.utcnow', + return_value=datetime(2018, 12, 31, 3, 4, 8, 200000)): + callback(target) + + assert len(mock_logger.error.mock_calls) == 1 assert len(funcs) == 2 fire_time_event, stop_timer = funcs assert len(hass.loop.call_later.mock_calls) == 2 - slp_seconds, callback, nxt = hass.loop.call_later.mock_calls[1][1] - assert slp_seconds == 1 + delay, callback, target = hass.loop.call_later.mock_calls[1][1] + assert abs(delay - 0.8) < 0.001 assert callback is fire_time_event - assert abs(nxt - 12.3) < 0.001 + assert abs(target - 14.2) < 0.001 @asyncio.coroutine