epoll.poll(timeout) and PollSelector.select(timeout) must round the timeout to the upper bound

[vstinner]

BPO	20311
Nosy	@gvanrossum, @birkenfeld, @pitrou, @vstinner, @ericsnowcurrently
Files	epoll_timeout.patch select_round_timeout.patch asyncio_granularity.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2014-02-02.20:24:02.306>
created_at = <Date 2014-01-20.10:33:28.464>
labels = []
title = 'epoll.poll(timeout) and PollSelector.select(timeout) must round the timeout to the upper bound'
updated_at = <Date 2014-02-10.21:04:38.598>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2014-02-10.21:04:38.598>
actor = 'python-dev'
assignee = 'none'
closed = True
closed_date = <Date 2014-02-02.20:24:02.306>
closer = 'vstinner'
components = []
creation = <Date 2014-01-20.10:33:28.464>
creator = 'vstinner'
dependencies = []
files = ['33563', '33564', '33680']
hgrepos = []
issue_num = 20311
keywords = ['patch']
message_count = 54.0
messages = ['208532', '208533', '208534', '208539', '208540', '208588', '208595', '208596', '208597', '208599', '208601', '208602', '208696', '208927', '208928', '208976', '209001', '209005', '209006', '209008', '209015', '209016', '209019', '209021', '209039', '209040', '209056', '209164', '209197', '209198', '209199', '209201', '209213', '209238', '209245', '209247', '209248', '209249', '209250', '209251', '209252', '209253', '209286', '209340', '209774', '210008', '210023', '210024', '210029', '210034', '210042', '210058', '210060', '210865']
nosy_count = 7.0
nosy_names = ['gvanrossum', 'georg.brandl', 'pitrou', 'vstinner', 'neologix', 'python-dev', 'eric.snow']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = None
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue20311'
versions = ['Python 3.3', 'Python 3.4']

[vstinner]

Hi, while comparing performances of Tulip and Trollius projects (asyncio module), I found a bug. The event loop is called too many times when a callback is scheduled with a timeout and the epoll selector is used, especially for timeout close to one millisecond.

In my opinion, it's a bug in epoll.poll(): it should wait *at least* timeout seconds if no event is received, not shorter.

Pseudo-code of Tulip:
---

timeout = scheduled[0].when - time.monotonic()
events = selector.select(timeout)
process_events(events)
while scheduled:
   if scheduled[0].when > time.monotonic():
      break
   ...

---

The problem is that "scheduled[0].when > time.monotonic()" test fails because epoll.poll() returns in less than timeout seconds.

The difference between the timeout and elapsed time is very small, less than 1 millisecond.

Attached patch fixes this issue by rounding the timeout to the upper bound.

The rounding is different than datetime.timedelta constructor for example, because the usecase is different. epoll.poll(0.0001) calls epoll_wait() with a timemout of 1 millisecond (1e-4 rounded to 1e-3).

epoll.poll(0.0) still calls epoll_wait() with a timeout of 0 millisecond. I don't think that it's possible to write a reliable unit test for that on our slow buildbots.

[vstinner]

Bug report in Tulip project, the bug affects also the new asyncio module of Python 3.4:
http://code.google.com/p/tulip/issues/detail?id=106

[pitrou]

Looks good to me on the principle.

[neologix]

AFAICT, this also affects poll().
Although it's supposed to be passed an integer, passing a float will result
in a truncation towards 0:
"""
$ strace -e poll python -c "import select; p = select.poll(); p.poll(0.9)"
poll(0x23321b0, 0, 0) = 0 (Timeout)
"""

See also this line in PollSelector:
"""
def select(self, timeout=None):
timeout = None if timeout is None else max(int(1000 * timeout),
0)
"""

This will round timeout=1e-4 to 0.

[vstinner]

select.select(), selectors.PollSelector.select(), select.epoll.poll(), select.kqueue.control() have the bug.

OS multiplexers:

• select: microsecond resolution (10^-6), timeout converted by _PyTime_ObjectToTimeval() which converts 1e-7 to zero => BUG!
• poll: millisecond resolution (10^-3) but expects int type, select is ok, selectors uses int(1000 * timeout) which converts 1e-4 to zero => BUG!
• epoll: millisecond resolution (10^-3), select uses (int)(dtimeout * 1000.0) which converts 1e-4 to zero => BUG!
• devpoll: millisecond resolution (10^-3) but expects int type, select is ok, selectors doesn't support it yet => ok
• 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()

A new parameter should be added to _PyTime_ObjectToTimeval() and _PyTime_ObjectToTimespec() to choose the rounding method.

--

I saw the bug with poll and epoll because these functions have the worst resolution (millisecond). Attached patch fixes poll and epoll, and add a generic test on all selectors: select_round_timeout.patch.

According to my test, select.select() has an effective resolution of 0.1 ms (10^4) on my Fedora 19 (Linux kernel 3.12), so I don't think that the select rounding issue is important. Tell me if you consider that _PyTime_ObjectToTime*() (select, kqueue) should be fixed. If yes, I will open a separated issue (because the implementation is different and it may impact other unrelated functions).

[pitrou]

A new parameter should be added to _PyTime_ObjectToTimeval() and
_PyTime_ObjectToTimespec() to choose the rounding method.

That doesn't sound necessary. Just fix the select and selectors module so that the final (OS-level) timeout is always > 0 when the user timeout is > 0.

[python-dev]

New changeset 033137c12d88 by Victor Stinner in branch '3.3':
Issue bpo-20311: select.epoll.poll() now rounds the timeout away from zero,
http://hg.python.org/cpython/rev/033137c12d88

New changeset 02f9db3e684e by Victor Stinner in branch 'default':
(Merge 3.3) Issue bpo-20311: select.epoll.poll() now rounds the timeout away from
http://hg.python.org/cpython/rev/02f9db3e684e

[python-dev]

New changeset e042ea77a152 by Victor Stinner in branch 'default':
Issue bpo-20311: selector.PollSelector.select() now rounds the timeout away from
http://hg.python.org/cpython/rev/e042ea77a152

[vstinner]

Rounding issues with poll() and epoll() have been fixed in Python 3.3 and 3.4. I'm now waiting for buildbots before closing the issue.

I created a new issue bpo-20320 to address the rounding issue with select() and kqueue (and signal.sigtimedwait).

[vstinner]

The epoll test failed on a buildbot. The test uses a short delay (10 milliseconds) and compare two different clocks: time.perf_counter() and select.epoll.poll(). I didn't expect a failure very the greatest delay, the test uses even shorter delay (the shortest is 0.1 ms).

The best would be to trace syscalls to check if epoll_wait() is called with a non-zero timeout, but tracing syscalls is overkill and too low level for such test.

It's maybe better to drop this unstable test? Unstable on our slow buildbots.

http://buildbot.python.org/all/builders/x86%20Gentoo%20Non-Debug%203.3/builds/1392/steps/test/logs/stdio

======================================================================
FAIL: test_timeout_rounding (test.test_epoll.TestEPoll)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/var/lib/buildslave/3.3.murray-gentoo-wide/build/Lib/test/test_epoll.py", line 58, in test_timeout_rounding
    self.assertGreaterEqual(dt, timeout)
AssertionError: 0.008995789801701903 not greater than or equal to 0.01

[vstinner]

Another failure:

http://buildbot.python.org/all/builders/x86%20Ubuntu%20Shared%203.3/builds/1360/steps/test/logs/stdio

======================================================================
FAIL: test_timeout_rounding (test.test_epoll.TestEPoll)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/srv/buildbot/buildarea/3.3.bolen-ubuntu/build/Lib/test/test_epoll.py", line 58, in test_timeout_rounding
    self.assertGreaterEqual(dt, timeout)
AssertionError: 0.009388947859406471 not greater than or equal to 0.01

[python-dev]

New changeset e1619465c49d by Victor Stinner in branch '3.3':
Issue bpo-20311: Try to fix the unit test, use time.monotonic() instead of
http://hg.python.org/cpython/rev/e1619465c49d

New changeset 26c54e9a933b by Victor Stinner in branch 'default':
(Merge 3.3) Issue bpo-20311: Try to fix the unit test, use time.monotonic()
http://hg.python.org/cpython/rev/26c54e9a933b

[python-dev]

New changeset 7ce7295393c2 by Victor Stinner in branch 'default':
Issue bpo-20311: EpollSelector now also rounds the timeout towards zero, as
http://hg.python.org/cpython/rev/7ce7295393c2

[vstinner]

http://buildbot.python.org/all/builders/x86%20Ubuntu%20Shared%203.x/builds/9552

======================================================================
FAIL: test_timeout_rounding (test.test_epoll.TestEPoll)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/srv/buildbot/buildarea/3.x.bolen-ubuntu/build/Lib/test/test_epoll.py", line 59, in test_timeout_rounding
    self.assertGreaterEqual(dt, timeout)
AssertionError: 0.009316698648035526 not greater than or equal to 0.01