python / cpython

The Python programming language
https://www.python.org
Other
62.16k stars 29.88k forks source link

asyncio.BaseEventLoop _clock_resolution has no effect #116342

Open KholdStare opened 6 months ago

KholdStare commented 6 months ago

Bug report

Bug description:

Short Version

Adding _clock_resolution in this line has no effect (at least on linux): https://github.com/python/cpython/blob/88b5c665ee1624af1bc5097d3eb2af090b9cabed/Lib/asyncio/base_events.py#L1987

Because time() returns a float of the current epoch time, and clock resolution is 1e-9, self.time() == self.time() + self._clock_resolution, due to floating point precision loss. In a corner case where self.time() matches the next scheduled timer exactly, it would have to wait for the next iteration of the event loop to get run.

Longer Version

I was writing deterministic unittests involving timers and asyncio. I used a VirtualClock which would mock out loop.time() and loop.select():

https://aiotools.readthedocs.io/en/latest/_modules/aiotools/timer.html#VirtualClock

The internal time does not advance unless a timer is awaited.

Unfortunately when using realistic timestamps, because of the precision loss described above, the event loop gets permanently stuck at the exact time of the next timer, and never advances.

In the snippet below, the problem is that handle._when >= end_time is always true:

https://github.com/python/cpython/blob/88b5c665ee1624af1bc5097d3eb2af090b9cabed/Lib/asyncio/base_events.py#L1986-L1994

This was introduced in this change: https://github.com/python/cpython/commit/ed1654fa3ea1c05c7397334b09396675f3c3aeaf

CPython versions tested on:

3.10

Operating systems tested on:

Linux

KholdStare commented 6 months ago

Some thoughts I had - ideally timestamps would be 64bit ints with nanosecond precision - then the above calculation would work out. However, since we are dealing with 64bit floats, there's only 53 bits of precision. Perhaps when _clock_resolution is stored in the event loop, it should be "bumped up" to the smallest increment that would not lead to precision loss. I.e. a floating point with the same exponent as a typical epoch time, but the mantissa being 1.

zware commented 6 months ago

Note that the loop uses time.monotonic(), not time.time(), so time since the Unix epoch is irrelevant here. time.monotonic() does not have a defined reference point (it's generally probably related to system uptime, but no guarantees). My personal system currently gives something around 192187.52431901, which is happily affected by adding 1e-09.

I don't think there's a real bug here; the likelihood of a time.monotonic() timestamp getting big enough to cause this kind of problem seems remote. It might still be a good idea to migrate to time.monotonic_ns() just to make the issue impossible, but that's going to take some serious consideration in all time-related asyncio APIs to avoid breaking things with the change.

KholdStare commented 6 months ago

Thank you for the quick response. This makes sense to me. Feel free to close the issue. Would a comment be useful in the code to warn of this behavior? I'm not sure if there is an environment out there where the monotonic clock acts as epoch time - but if there is, then this issue would apply.