classification
Title: select.select(timeout) and select.kqueue.control(timeout) must round the timeout to the upper bound
Type: Stage:
Components: Versions: Python 3.4
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: belopolsky, jcea, neologix, pitrou, python-dev, serhiy.storchaka, skrah, vstinner
Priority: normal Keywords: patch

Created on 2014-01-21 00:34 by vstinner, last changed 2014-09-26 02:00 by jcea. This issue is now closed.

Files
File name Uploaded Description Edit
time_rouding.patch vstinner, 2014-01-21 00:34 review
time_rouding-2.patch vstinner, 2014-02-11 09:55 review
time_rouding-3.patch vstinner, 2014-02-11 23:33 review
Messages (13)
msg208594 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-01-21 00:34
Rounding issue causes performance bug in asyncio, see issue #20311 for the rationale. This issue address bugs for select and kqueue because their implementation is different.

OS multiplexer:

- select: microsecond resolution (10^-6), timeout converted by _PyTime_ObjectToTimeval() which converts 1e-7 to zero => BUG!
- kqueue: nanosecond resolution (10^-9), timeout converted by _PyTime_ObjectToTimespec() which converts 1e-10 to zero => BUG!

_PyTime_ObjectToTimeval() is used in various places:

- datetime.datetime.fromtimestamp(), datetime.datetime.utcfromtimestamp()
- select.select(), 

_PyTime_ObjectToTimespec() is used in various places:

- posix.utime()
- signal.sigtimedwait()
- select.kqueue.control()
- time.clock_settime()

Attached patch adds a new round parameter to _PyTime_ObjectToTimeval() and _PyTime_ObjectToTimespec() to choose the rounding method:

* _PyTime_ROUND_DOWN: Round towards zero. (current implementation)
* _PyTime_ROUND_UP: Round away from zero. (new rounding method)

The patch changes the rounding method for select, kqueue but also for sigtimedwait().
msg208622 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2014-01-21 07:49
Just so it's clear, those bugs are theoretical: whether you pass 1e-7/1e-10 or 0 to select/kqueue is exactly the same (entering/leaving the syscall takes some time)...
msg208638 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-01-21 10:40
Timings on my laptop:

>>> import time, select
>>> t0=time.perf_counter(); select.select([], [], [], 1e-6); dt=time.perf_counter()-t0; dt
([], [], [])
0.00012494399561546743
>>> t0=time.perf_counter(); select.select([], [], [], 0); dt=time.perf_counter()-t0; dt
([], [], [])
4.965400148648769e-05

A call to select.select() with a timeout of 1 microsecond (10^-6) takes 124 microesconds.

A non-blocking call to select.select() (timeout of 0 microsecond) takes 50 microseconds.

> Just so it's clear, those bugs are theoretical: whether you pass 1e-7/1e-10 or 0 to select/kqueue is exactly the same (entering/leaving the syscall takes some time)...

Yes, the problem of asyncio (explained in issue #20311) is that selector.select(timeout) took *less* than timeout seconds even when no new event was found, and so the loop restarted again and again.

According to the timings above, selector.select(1e-7) (which calls currently select.select() in non blocking mode, with a timeout of 0 second) takes longer than 1e-7 second: at least 500e-7 seconds. So yes, the problem cannot be reproduced on my current hardware.

It may be fine to only fix these bugs in Python 3.5.
msg209200 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-01-25 14:42
I reverted my changes on poll and epoll: the kernel may "round" the timeout differently because it uses a different clock, so Python cannot guarantee that it will wait "at least" timeout seconds.

My initial concern was a performance issue in asyncio, I fixed the issue differently: see issue #20311.
msg210909 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-02-11 08:53
According to my last tests, we should still round select and kqueue timeout away from zero.
http://bugs.python.org/issue20505#msg210908
msg210916 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-02-11 09:55
> Just so it's clear, those bugs are theoretical: whether you pass 1e-7/1e-10 or 0 to select/kqueue is exactly the same (entering/leaving the syscall takes some time)...

After many many tests with asyncio (last issue: #20505), I disagree with you. It has a real impact.

Can someone please review my new patch?

I now think that select.select() should also be fixed in Python 3.4 to be consistent with the new select.poll() and select.epoll.poll() behaviour (timeout rounding).

See msg210914 and msg210915 ( http://bugs.python.org/issue20505#msg210914 ): IocpSelector sleeps at least 0.5 ms (of perf counter) even with a timeout of 1 nanosecond, whereas SelectSelector sleeps sometimes 0.030 ms which looks like a non-blocking call.

I tested asyncio with the patch to round select timeout away from zero:

* With HPET disabled, SelectSelector sleeps at least 15 ms according to the monotonic clock (FYI: at least 2 ms according to the perfomance counter)

* With HPET enabled, SelectSelector sleeps at least 15 ms according to the monotonic clock (FYI: at least 6.3 ms according to the perfomance counter)

These results are the expected behaviour: selectors should at least one unit of the monotonic time (15.6 ms).
msg210920 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2014-02-11 11:23
> STINNER Victor added the comment:
>
>> Just so it's clear, those bugs are theoretical: whether you pass
>> 1e-7/1e-10 or 0 to select/kqueue is exactly the same (entering/leaving the
>> syscall takes some time)...
>
> After many many tests with asyncio (last issue: #20505), I disagree with
> you. It has a real impact.

And I stand by my claim. Quoting your test results:
"""
asyncio: IocpProactor.select(10.0000 ms) took 9.486 ms
(monotonic=0.000 ms, clock res=15.600 ms)
asyncio: IocpProactor.select(0.0010 ms) took 0.942 ms (monotonic=0.000
ms, clock  res=15.600 ms)
asyncio: IocpProactor.select(0.0000 ms) took 0.553 ms (monotonic=0.000
ms, clock res=15.600 ms)
asyncio: IocpProactor.select(0.0000 ms) took 0.517 ms (monotonic=0.000
ms, clock res=15.600 ms)

asyncio: SelectSelector.select(0.1000 ms) took 2.276 ms
(monotonic=0.000 ms, clock res=15.600 ms)
asyncio: SelectSelector.select(1.0000 us) took 30.810 us
(monotonic=0.000 us, clock res=15600.100 us)
asyncio: SelectSelector.select(0.0100 us) took 30.350 us
(monotonic=0.000 us, clock res=15600.100 us)
asyncio: SelectSelector.select(0.0001 us) took 28.930 us
(monotonic=0.000 us, clock res=15600.100 us)
"""

As one can see, when passed a timeout lower than the resolution, e.g.
0.01 usec, select() takes around 30usec, *which is above the timeout*
(0.01usec), which is exactly what I claimed.

> These results are the expected behaviour: selectors should at least one unit of the monotonic time (15.6 ms).

That's just wrong.
The expected bahavior is that selector.select() should wait at least
the *timeout passed*, not the "unit of monotonic time" (which doesn't
mean anything by the way).

Now, rounding away from zero for select/kqueue is fine to me, just to
be consistent.
msg210929 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-02-11 12:03
> Now, rounding away from zero for select/kqueue is fine to me, 
> just to be consistent.

Did you take a look at time_rouding-2.patch?
msg211036 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-02-11 23:17
Antoine asks me on Rietveld why I chose to round up in signal.sigtimedwait().

I consider that sigtimedwait() is similar to select and kqueue: it's a function to wait for an event with a timeout. IMO it should use the same rounding method. Don't you think so?

I don't really care how sigtimedwait() rounds its timeout, I just tried to be consistent.
msg211037 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2014-02-11 23:19
> I consider that sigtimedwait() is similar to select and kqueue: it's a
> function to wait for an event with a timeout. IMO it should use the
> same rounding method. Don't you think so?
> 
> I don't really care how sigtimedwait() rounds its timeout, I just
> tried to be consistent.

We have lots of "waiting for an event" with a timeout function (e.g.
Lock.acquire()), so if we want to be consistent we have to change all of
them.
But originally this issue only "affects" event loops, so presumably it'd
be reasonable to stick to select()-alikes.
msg211040 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-02-11 23:33
> But originally this issue only "affects" event loops, so
> presumably it'd be reasonable to stick to select()-alikes.

Ok, here is a new patch which doesn't change signal.sigtimedwait() (still round down, towards zero).
msg211155 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-02-13 13:40
Can I commit time_rouding-3.patch?
msg211371 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2014-02-16 23:08
New changeset 180e4b678003 by Victor Stinner in branch 'default':
Issue #20320: select.select() and select.kqueue.control() now round the timeout
http://hg.python.org/cpython/rev/180e4b678003
History
Date User Action Args
2014-09-26 02:00:24jceasetnosy: + jcea
2014-02-16 23:09:32vstinnersetstatus: open -> closed
resolution: fixed
2014-02-16 23:08:27python-devsetnosy: + python-dev
messages: + msg211371
2014-02-13 13:40:28vstinnersetmessages: + msg211155
2014-02-11 23:33:29vstinnersetfiles: + time_rouding-3.patch

messages: + msg211040
2014-02-11 23:19:18pitrousetmessages: + msg211037
2014-02-11 23:17:33vstinnersetmessages: + msg211036
2014-02-11 12:03:11vstinnersetmessages: + msg210929
2014-02-11 11:23:05neologixsetmessages: + msg210920
2014-02-11 09:55:58vstinnersetfiles: + time_rouding-2.patch

messages: + msg210916
versions: + Python 3.4, - Python 3.5
2014-02-11 08:53:30vstinnersetstatus: closed -> open
resolution: not a bug -> (no value)
messages: + msg210909
2014-01-25 14:42:16vstinnersetstatus: open -> closed
resolution: not a bug
messages: + msg209200
2014-01-21 10:40:09vstinnersetmessages: + msg208638
versions: + Python 3.5, - Python 3.3, Python 3.4
2014-01-21 07:49:29neologixsetmessages: + msg208622
2014-01-21 00:34:16vstinnercreate