Rework timer delays (#16650)

* Calibrate timer for each tick

* Return of timer out of sync detection

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())

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