Originally faced here:
https://stackoverflow.com/q/46306660/1113207

Simple code to reproduce:

    import asyncio 
    import time


    async def main():
        while True:
            asyncio.ensure_future(asyncio.sleep(1))

            t0 = time.time()
            await asyncio.sleep(0.1)
            t1 = time.time()

            print(t1 - t0)
            if t1 - t0 < 0.1:
                print('bug ^')
                break


    loop = asyncio.get_event_loop()
    loop.run_until_complete(main())

I thought that it may be related to event loop's internal clock, but changing time.time() with asyncio.get_event_loop().time() doesn't help.

Tested on Windows 10 x64, Python 3.6.2.

I can't reproduce this on a linux VM with 3.7 tip. I don't currently have a windows instance to test against.

AFAIR the Windows clock has a 15ms granularity, so I'm not really surprised. In other words, I don't think asyncio.sleep sleeps less than expected, but that it's the imprecision of time.time() which gives you that impression.

What happens if you replace time.time() with time.perf_counter() in the code above?

Clocks is a very complex topic, especially when you care of portability. See my PEP-418.

asyncio uses time.monotonic() clock to not be impacted when the system clock ("wall clock") is updated by the administrator or automatically by NTP.

On Windows, time.monotonic() is implemented with GetTickCount64() which has a bad resolution: around 15 ms. The exact resolution depends on the hardware.

See my PEP-418 which added time.monotonic() for Python 3.3 for much more information:
https://www.python.org/dev/peps/pep-0418/#monotonic-clocks

To get the clock resolution, use:

>> import time; print(time.get_clock_info('monotonic'))

Example on Linux:

>>> import time; print(time.get_clock_info('monotonic'))
namespace(adjustable=False, implementation='clock_gettime(CLOCK_MONOTONIC)', monotonic=True, resolution=1e-09)

Well, the announced resolution is 1 nanosecond, but in practice it's more around 500 ns. At least, it's better than 15 ms :-)

--

asyncio rounds timings using the clock resolution, time.get_clock_info('monotonic').resolution. Search for self._clock_resolution in Lib/asyncio/base_events.py.

asyncio is not designed for real time.

STINNER Victor, thanks for explanation!

I don't know if this issue has practical disadvantages, but such behavior seems to be confusing, especially, since it can be reproduced with event_loop.time() and asyncio doc says nothing about resolution -
https://docs.python.org/3/library/asyncio-eventloop.html#delayed-calls

Do you think this issue should be closed?
Should I make PR to add info about clock's resolution to asyncio documentation?

Technically, asyncio cannot wait exactly 100 ms on Windows. It will be more
likely a sleep between 100-15 ms and 100+15 ms. Real time is really a
complex topic. CPython with its stop-the-world garbage collector is not
designed for real time.

I don't think the bug is about real time here, rather about minimal sleep time expectations; i.e. it's expected that the sleep time may be *more* than asked for, but not less than.

(and I would share that expectation myself)

it's expected that the sleep time may be *more* than asked for, but not less than.

Exactly, and asyncio tries to ensure that. It looks like "time.get_clock_info('monotonic').resolution" lies about monotonic clock resolution on Windows so that might be the actual issue we want to address.

IMHO we should either just close the issue, ir document the bad clock
resolution on Windows in the asyncio doc.

Yury: asyncio can trigger events earlier than scheduled for performance
reasons. See end_time in asyncio core loop.

Le 21/09/2017 à 23:31, STINNER Victor a écrit :

Yury: asyncio can trigger events earlier than scheduled for performance
reasons.

If that's true, then it sounds like a bug. If there is a rationale for
a "fast and imprecise" API, then it would seem ok to add such an API.
But the default API for event scheduling should not take such shortcuts
IMHO. Most users don't schedule thousands of events at a time, however
they expect timeouts to be observed as rigorously as is possible given
the usual implementation constraints such as GC pauses.

So here's the relevant piece of code:

        end_time = self.time() + self._clock_resolution
        while self._scheduled:
            handle = self._scheduled[0]
            if handle._when >= end_time:
                break
            handle = heapq.heappop(self._scheduled)
            handle._scheduled = False
            self._ready.append(handle)

As I see it, currently we peek into the future time. Why don't we do

        end_time = self.time() - self._clock_resolution

to guarantee that timeouts will always be triggered *after* the requested time, not before? I don't see how the performance can become worse if we do this.

Issues:

• bpo-20320
• bpo-20452
• bpo-20505
• bpo-20311

The performance issue was that the asyncio core loop was running in a loop
but did nothing because of time rounding. When the next event was in a few
nanoseconds, the e event burnt the CPU during <clock resolution> seconds.
It can be 15 ms on Windows or 1 ms when using poll() for example. It's not
just clock resolution, also the resolution of the selector.

Hopefully, select and selectors now round towards +inf (rather than
rounding down, towards zero or -inf) and so the selector resolution is no
more an issue if I recall correctly.

The performance issue was that the asyncio core loop was running in a loop
but did nothing because of time rounding. When the next event was in a few
nanoseconds, the e event burnt the CPU during <clock resolution> seconds.
It can be 15 ms on Windows or 1 ms when using poll() for example. It's not
just clock resolution, also the resolution of the selector.

Hm. I glanced through the issues you linked, and it looks like it's a valid concern for a micro-benchmark. But I don't see how a performance of a real-world application can be affected here. IOW, the "self.time() + self._clock_resolution" line looks like an optimization for a particular micro-benchmark. I'm sure we can construct another micro-benchmark that would benefit from "self.time() - self._clock_resolution".

I think we should value correctness more than micro-benchmarks.

When the fine tuning options for install-directories are set, the default directories "lib", "bin" and "include" are still created with essential content. Even if options like --libdir are set.

Markus, your comment does not seem relevant to this issue. Maybe you meant to add it to a different issue, or you meant to create a new issue?

On Windows time.perf_counter has better resolution than time.monotonic.

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

I suppose one possible fix is to use time.perf_counter on Windows.

But should we do that? Or can we provide a recipe to users? IIUC there's a way to change the clock used by asyncio.

It is possible by subclassing but it doesn't work out of box with asyncio.run which ideally we want the users to use. Also changing the clock is harmless, at worst it will give more precise value so not really a problem since both clocks are monotonic. It is just a python float with more precision at the end of day.

Okay, go for it. But let's treat it as a new feature.

PR #97027 uses time.perf_counter since it's precision is always better or equal to that of time.monotonic on all platforms.

If someone's looking to pursue this, zooba left recommendations here: #97027 (comment)

@kumaraditya303 What are your thoughts on possibly closing this issue? I'm not seeing a clear path forward with this issue.

I close the issue. It's fixed in Python 3.13 thanks to clocks with better resolution on Windows!

Tested on Windows 10 x64, Python 3.6.2.

This issue was reported on Windows with Python 3.6. Python 3.6 uses GetTickCount64() clock with a resolution of 15.6 ms for the asyncio loop, and GetSystemTimeAsFileTime() for time.time(). The reproducer uses the two clocks which may not be synchronized.

What changes is that clocks on Windows on Python 3.13 have a way better resolution: https://docs.python.org/dev/whatsnew/3.13.html#time

• time.monotonic() now uses the QueryPerformanceCounter() clock to have a resolution better than 1 us, instead of the GetTickCount64() clock which has a resolution of 15.6 ms.
• time.time() now uses the GetSystemTimePreciseAsFileTime() clock to have a resolution better than 1 μs, instead of the GetSystemTimeAsFileTime() clock which has a resolution of 15.6 ms.

asyncio uses time.monotonic(). So even if there is still a rounding issue in asyncio, the delta should now be lower than 1 µs and so it should matter way less :-)

@pitrou:

AFAIR the Windows clock has a 15ms granularity, so I'm not really surprised. In other words, I don't think asyncio.sleep sleeps less than expected, but that it's the imprecision of time.time() which gives you that impression.

I agree that this issue can be closed.

I can no longer reproduce the issue on Python 3.6 using the reproducer.

I cannot reproduce the "bug ^" neither with my modified reproducer:

import asyncio
import time

async def main():
    while True:
        print(time.time())

        task = asyncio.ensure_future(asyncio.sleep(1))

        t0 = time.time()
        await asyncio.sleep(0.1)
        t1 = time.time()

        print(t1 - t0, f"diff {(t1 - t0 - 0.1) * 1e3:+.1f} ms")
        if t1 - t0 < 0.1:
            print('bug ^')
            break

        await task

start = time.time()
try:
    asyncio.run(main())
except KeyboardInterrupt:
    print("run for %.1f sec" % (time.time() - start))

I ran this script for 30 seconds. Example of output:

...
0.11087536811828613 diff +10.9 ms
1718899484.414009
0.10867047309875488 diff +8.7 ms
1718899485.4162643
0.10914826393127441 diff +9.1 ms
1718899486.4320083
0.10909795761108398 diff +9.1 ms
1718899487.4477282
0.10911035537719727 diff +9.1 ms
1718899488.4633076
0.1091463565826416 diff +9.1 ms
1718899489.4789627
0.1087486743927002 diff +8.7 ms
1718899490.4806302
0.10907554626464844 diff +9.1 ms
1718899491.486012
...

The difference is now always positive. The error is between +8 and +10 ms, but at least it's no longer negative.

Internally, asyncio event loop now uses a "clock resolution" of 100 ns (1e-07 sec).