msg208594 - (view) |
Author: STINNER Victor (vstinner) * |
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) * |
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) * |
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) * |
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) * |
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) * |
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) * |
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) * |
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) * |
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) * |
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) * |
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) * |
Date: 2014-02-13 13:40 |
Can I commit time_rouding-3.patch?
|
msg211371 - (view) |
Author: Roundup Robot (python-dev) |
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
|
|
Date |
User |
Action |
Args |
2022-04-11 14:57:57 | admin | set | github: 64519 |
2014-09-26 02:00:24 | jcea | set | nosy:
+ jcea
|
2014-02-16 23:09:32 | vstinner | set | status: open -> closed resolution: fixed |
2014-02-16 23:08:27 | python-dev | set | nosy:
+ python-dev messages:
+ msg211371
|
2014-02-13 13:40:28 | vstinner | set | messages:
+ msg211155 |
2014-02-11 23:33:29 | vstinner | set | files:
+ time_rouding-3.patch
messages:
+ msg211040 |
2014-02-11 23:19:18 | pitrou | set | messages:
+ msg211037 |
2014-02-11 23:17:33 | vstinner | set | messages:
+ msg211036 |
2014-02-11 12:03:11 | vstinner | set | messages:
+ msg210929 |
2014-02-11 11:23:05 | neologix | set | messages:
+ msg210920 |
2014-02-11 09:55:58 | vstinner | set | files:
+ time_rouding-2.patch
messages:
+ msg210916 versions:
+ Python 3.4, - Python 3.5 |
2014-02-11 08:53:30 | vstinner | set | status: closed -> open resolution: not a bug -> (no value) messages:
+ msg210909
|
2014-01-25 14:42:16 | vstinner | set | status: open -> closed resolution: not a bug messages:
+ msg209200
|
2014-01-21 10:40:09 | vstinner | set | messages:
+ msg208638 versions:
+ Python 3.5, - Python 3.3, Python 3.4 |
2014-01-21 07:49:29 | neologix | set | messages:
+ msg208622 |
2014-01-21 00:34:16 | vstinner | create | |