python / cpython

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

time.sleep regression in 3.11 onwards #125997

Open charles-cooper opened 1 month ago

charles-cooper commented 1 month ago

Bug report

Bug description:

the following script runs 100x slower on python 3.11 and python 3.12:

# relax.py

import time

def main():
    for _ in range(1_000_000):
        time.sleep(0.0)

main()
~ $ time python3.10 relax.py 

real    0m0.643s
user    0m0.345s
sys 0m0.314s
~ $ time python3.11 relax.py 

real    0m52.212s
user    0m0.744s
sys 0m1.115s
~ $ time python3.12 relax.py 

real    0m52.826s
user    0m1.317s
sys 0m0.997s

here is my system+python information:

~ $ uname -r
5.15.0-122-generic
~ $ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 22.04.5 LTS
Release:    22.04
Codename:   jammy
~ $ python3.10 -VV
Python 3.10.12 (main, Sep 11 2024, 15:47:36) [GCC 11.4.0]
~ $ python3.11 -VV
Python 3.11.10 (main, Sep  7 2024, 18:35:41) [GCC 11.4.0]
~ $ python3.12 -VV
Python 3.12.7 (main, Oct  1 2024, 08:52:12) [GCC 11.4.0]

CPython versions tested on:

3.10, 3.11, 3.12, 3.13

Operating systems tested on:

Linux

dg-pb commented 1 month ago

A while ago did some benchmarking on 3.11 and 3.12 with sleep (on OSX) and it did seem unreasonably slow.

Was expecting nano-seconds, but was in micro-second order.

Just assumed that this is how it should be. But if this is actually a fixable regression, it would be great.

ZeroIntensity commented 1 month ago

I wasn't able to reproduce this on my end:

$ time python3.11 relax.py
python3.11 relax.py  1.07s user 1.54s system 4% cpu 55.396 total
$ time python3.12 relax.py
python3.12 relax.py  2.04s user 0.47s system 4% cpu 55.842 total

Though, timeit does pick up a tiny slowdown:

$ cat relax.py | python3.11 -m timeit
20000000 loops, best of 5: 10.8 nsec per loop
$ cat relax.py | python3.12 -m timeit
50000000 loops, best of 5: 7.47 nsec per loop

Unfortunately, 3.11 is security-only, so there's nothing that can get fixed here unless this is somehow causing a security issue somewhere.

dg-pb commented 1 month ago

Can not reproduce on OSX either:

python -m timeit -s 'import time' '[time.sleep(0) for _ in range(1_000_000)]'
# 3.10: 1 loop, best of 5: 631 msec per loop
# 3.11: 1 loop, best of 5: 550 msec per loop
# 3.12: 1 loop, best of 5: 556 msec per loop
charles-cooper commented 1 month ago

hmm -- fwiw, here is my CPU info (from cat /proc/cpuinfo):

vendor_id   : GenuineIntel
cpu family  : 6
model       : 166
model name  : Intel(R) Core(TM) i7-10710U CPU @ 1.10GHz
stepping    : 0
microcode   : 0xfe
cpu MHz     : 1600.000
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 4
cpu cores   : 6
apicid      : 9
initial apicid  : 9
fpu     : yes
fpu_exception   : yes

i am reproducing this in python3.13 as well.

~ $ python3.13 -VV
Python 3.13.0 (main, Oct  8 2024, 08:51:28) [GCC 11.4.0]
~ $ time python3.13 relax.py

real    0m52.886s
user    0m1.305s
sys 0m1.023s

and using timeit:

~ $ python3.10 -m timeit -s 'import time' 'time.sleep(0)'
500000 loops, best of 5: 404 nsec per loop
~ $ python3.11 -m timeit -s 'import time' 'time.sleep(0)'
5000 loops, best of 5: 51.9 usec per loop
~ $ python3.12 -m timeit -s 'import time' 'time.sleep(0)'
5000 loops, best of 5: 51.9 usec per loop
~ $ python3.13 -m timeit -s 'import time' 'time.sleep(0)'
5000 loops, best of 5: 51.9 usec per loop
charles-cooper commented 1 month ago

i am reproducing on another linux machine, too - this time with ubuntu 24.04

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 24.04.1 LTS
Release:    24.04
Codename:   noble
$ python -m timeit -s 'import time' 'time.sleep(0)'
5000 loops, best of 5: 51.8 usec per loop
hauntsaninja commented 1 month ago

I can reproduce on Linux (but not on macOS) — sleep goes from comfortably under 1us to >50us

I'm assuming this is caused by this change: https://github.com/python/cpython/issues/65501 (it's also mentioned in the docs for time.sleep). Reading online, it sounds like you could get a lower interval by fiddling with the Linux scheduler.

Unfortunately, 3.11 is security-only, so there's nothing that can get fixed here

The change is present in Python 3.11 onwards, so it's possible we could change something here. That said, unless someone has a concrete change to suggest, this issue probably isn't going to go anywhere.

ZeroIntensity commented 1 month ago

The change is present in Python 3.11 onwards, so it's possible we could change something here. That said, unless someone has a concrete change to suggest, this issue probably isn't going to go anywhere.

Oh, I do see that in the original report now. I thought this only affected 3.11, my bad! But yeah, I doubt there's anything that can be done here. Maybe this is somehow an upstream Linux problem.

charles-cooper commented 1 month ago

I'm assuming this is caused by this change: #65501 (it's also mentioned in the docs for time.sleep). Reading online, it sounds like you could get a lower interval by fiddling with the Linux scheduler.

@hauntsaninja what is the connection with that change? is it that linux defaults to clock_nanosleep() instead of select()?

charles-cooper commented 1 month ago

just an update -- i can reproduce 3.10 behavior with the following code:

#!/usr/bin/env python
import select

#import time  # 259ms

def main():
    poll = select.poll()
    for _ in range(1_000_000):
        #time.sleep(0.0)
        #select.select([],[],[],0)
        poll.poll(0)

main()  # 408ms