classification
Title: asyncio.sleep may sleep less time then it should
Type: behavior Stage:
Components: asyncio Versions: Python 3.7, Python 3.6
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: CatorCanulis, germn, gvanrossum, pitrou, r.david.murray, vstinner, yselivanov
Priority: normal Keywords:

Created on 2017-09-21 07:52 by germn, last changed 2020-02-25 15:02 by gvanrossum.

Messages (15)
msg302671 - (view) Author: Mikhail Gerasimov (germn) Date: 2017-09-21 07:52
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.
msg302693 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2017-09-21 14:55
I can't reproduce this on a linux VM with 3.7 tip.  I don't currently have a windows instance to test against.
msg302698 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2017-09-21 15:47
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?
msg302699 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-09-21 16:07
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.
msg302708 - (view) Author: Mikhail Gerasimov (germn) Date: 2017-09-21 16:28
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?
msg302722 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-09-21 21:01
Technically, asyncii 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 are not
designed for real time.
msg302723 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2017-09-21 21:03
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)
msg302725 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-09-21 21:15
> 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.
msg302726 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-09-21 21:31
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.
msg302727 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2017-09-21 21:35
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.
msg302729 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-09-21 21:41
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.
msg302730 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-09-21 21:43
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.
msg302731 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-09-21 21:47
> 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.
msg362639 - (view) Author: Markus Roth (CatorCanulis) Date: 2020-02-25 12:29
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.
msg362644 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2020-02-25 15:02
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?
History
Date User Action Args
2020-02-25 15:02:04gvanrossumsetmessages: + msg362644
2020-02-25 12:29:34CatorCanulissetnosy: + CatorCanulis
messages: + msg362639
2017-09-21 21:47:26yselivanovsetmessages: + msg302731
2017-09-21 21:43:03vstinnersetmessages: + msg302730
2017-09-21 21:41:54yselivanovsetmessages: + msg302729
2017-09-21 21:35:14pitrousetnosy: + gvanrossum
2017-09-21 21:35:06pitrousetmessages: + msg302727
2017-09-21 21:31:41vstinnersetmessages: + msg302726
2017-09-21 21:15:16yselivanovsetmessages: + msg302725
2017-09-21 21:03:20pitrousetversions: + Python 3.7
2017-09-21 21:03:16pitrousetmessages: + msg302723
2017-09-21 21:01:39vstinnersetmessages: + msg302722
2017-09-21 16:28:16germnsetmessages: + msg302708
2017-09-21 16:07:58vstinnersetnosy: + vstinner
messages: + msg302699
2017-09-21 15:47:04pitrousetnosy: + pitrou
messages: + msg302698
2017-09-21 14:55:34r.david.murraysetnosy: + r.david.murray
messages: + msg302693
2017-09-21 07:52:58germncreate