Description
Recently, I modified asyncio tests to add a CLOCK_RES constant. Example of test_time_and_call_at() change:
+CLOCK_RES = 0.020
(...)
- self.assertGreaterEqual(dt, delay - 0.050, dt)
+ self.assertGreaterEqual(dt, delay - test_utils.CLOCK_RES)
So the test now tolerates only 20 ms difference instead of 50 ms. Problem, the test failed on GHA Windows x64 CI :-(
asyncio uses time.monotonic() as loop.time(). test.pythoninfo reports a clock resolution of 15.6 ms.
call_at() creates a TimerHandle . _run_once() uses self._scheduled[0]._when - self.time() timeout to call self._selector.select(timeout). asyncio uses self._clock_resolution = time.get_clock_info('monotonic').resolution to decide in _run_once() if an event should be scheduled or not.
# Handle 'later' callbacks that are ready.
end_time = self.time() + self._clock_resolution
while self._scheduled:
handle = self._scheduled[0]
if handle._when >= end_time:
breakMaybe there is a rounding issue and sometimes a callback scheduled in 100 ms is actually run in 78 ms.
A timeout of 100 ms should wait 6 or 7 monotonic clock ticks, whereas 78 ms is around 5 clock ticks:
>>> k=0.015625
>>> 0.07799999999997453 / k
4.99199999999837
>>> 0.100 / k
6.4The test reads the clock twice, maybe t0 is 1 tick ahead of when:
when = self.loop.time() + delay
self.loop.call_at(when, cb)
t0 = self.loop.time()
It seems like the callback was called 2 ticks before the expected timeout when taking rounding issue in account:
>>> (0.100//k-1)*k, (0.100//k+1)*k
(0.078125, 0.109375)
The callback should be called between 78.1 ms (2 clicks before) and 109.4 ms (1 click after). It would be nice to only have an error of a maximum of 1 click:
>>> (0.100//k)*k, (0.100//k+1)*k
(0.09375, 0.109375)
Between 93.8 ms (1 click before) and 109.4 ms (1 click after).
I'm not sure what's going on.
GHA Windows x64:
FAIL: test_time_and_call_at (test.test_asyncio.test_base_events.BaseEventLoopTests.test_time_and_call_at)
----------------------------------------------------------------------
Traceback (most recent call last):
File "D:\a\cpython\cpython\Lib\test\test_asyncio\test_base_events.py", line 285, in test_time_and_call_at
self.assertGreaterEqual(dt, delay - test_utils.CLOCK_RES)
AssertionError: 0.07799999999997453 not greater than or equal to 0.08
test.pythoninfo:
time.altzone: -3600
time.daylight: 0
time.get_clock_info(monotonic): namespace(implementation='GetTickCount64()', monotonic=True, adjustable=False, resolution=0.015625)
time.get_clock_info(perf_counter): namespace(implementation='QueryPerformanceCounter()', monotonic=True, adjustable=False, resolution=1e-07)
time.get_clock_info(process_time): namespace(implementation='GetProcessTimes()', monotonic=True, adjustable=False, resolution=1e-07)
time.get_clock_info(thread_time): namespace(implementation='GetThreadTimes()', monotonic=True, adjustable=False, resolution=1e-07)
time.get_clock_info(time): namespace(implementation='GetSystemTimeAsFileTime()', monotonic=False, adjustable=True, resolution=0.015625)
time.time: 1696993710.9453082
time.timezone: 0
time.tzname: ('Coordinated Universal Time', 'Coordinated Universal Time')
build: https://github.com/python/cpython/actions/runs/6477453109/job/17587684818?pr=110677
Linked PRs
Metadata
Metadata
Assignees
Projects
Status