test_timeout_rounding() of test_asyncio fails on "x86 Ubuntu Shared 3.x" buildbot

[vstinner]

BPO	20452
Nosy	@gvanrossum, @vstinner
Files	loop_run_once.patch selector_resolution.patch test_base_events.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.21:59:18.188>
created_at = <Date 2014-01-31.08:26:29.987>
labels = ['tests']
title = 'test_timeout_rounding() of test_asyncio fails on "x86 Ubuntu Shared 3.x" buildbot'
updated_at = <Date 2014-02-02.21:59:18.187>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2014-02-02.21:59:18.187>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2014-02-02.21:59:18.188>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2014-01-31.08:26:29.987>
creator = 'vstinner'
dependencies = []
files = ['33821', '33825', '33830']
hgrepos = []
issue_num = 20452
keywords = ['patch']
message_count = 21.0
messages = ['209749', '209750', '209751', '209754', '209757', '209758', '209760', '209762', '209763', '209767', '209768', '209772', '209773', '209776', '209781', '209796', '209799', '209800', '209857', '209859', '210025']
nosy_count = 4.0
nosy_names = ['gvanrossum', 'vstinner', 'neologix', 'python-dev']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = None
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue20452'
versions = ['Python 3.4']

[vstinner]

The failure is minor, it's just a suboptimal code. Calling _run_once() 4 times instead of 3.

http://buildbot.python.org/all/builders/x86%20Ubuntu%20Shared%203.x/builds/9630/steps/test/logs/stdio

======================================================================
FAIL: test_timeout_rounding (test.test_asyncio.test_events.EPollEventLoopTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/srv/buildbot/buildarea/3.x.bolen-ubuntu/build/Lib/test/test_asyncio/test_events.py", line 1180, in test_timeout_rounding
    self.assertEqual(calls, [1, 3, 5, 6])
AssertionError: Lists differ: [1, 4, 6, 7] != [1, 3, 5, 6]

First differing element 1:
4
3

• [1, 4, 6, 7]
  + [1, 3, 5, 6]

I'm unable to reproduce the error on my Linux box. When we had the rounding away from zero in epoll directly, the epoll test failed on the same buildbot:
http://bugs.python.org/issue20311#msg208601

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 5545634d98a1 by Victor Stinner in branch 'default':
Issue bpo-20452: add more info in case of test_asyncio failure to try to debug the
http://hg.python.org/cpython/rev/5545634d98a1

[vstinner]

_run_once() can be called more than expected if selector.select() was interrupted by a signal or because the granularity is wrong. If we want to avoid that, a simple fix is just to loop again in this case. Attached patch implements that (I wrote it for Tulip, it cannot applied cleanly on Python because I added debug code to investigate this issue).

The patch should also fix the sporadic issue of signal interrupting _run_once(). The unit test should not be interrupted by a signal, but it can occur on a real application. For example when your resize a terminal.

[python-dev]

New changeset 83e110399f3c by Victor Stinner in branch 'default':
Issue bpo-20452: Oops, fix debug code :-/
http://hg.python.org/cpython/rev/83e110399f3c

[vstinner]

It looks like select() and poll() in Linux < 2.6.28 has a resolution of 1/HZ, where HZ can be retrieved from os.sysconf('SC_CLK_TCK'). Since Linux 2.6.28, hrtimers are now used for timeouts.

"High- (but not too high-) resolution timeouts"
http://lwn.net/Articles/296578/

"What's in hrtimer.git for 2.6.28"
https://lkml.org/lkml/2008/9/20/136

Attached patch improves the resolution field of selectors.BaseSelector.

By the way, resolution should be a method (selector.resolution()) rather than a property, because we may query the kernel to compute the resolution, as shown in the patch.

[vstinner]

Platform of "x86 Ubuntu Shared 3.x" buildbot: "Linux-2.6.31.5-linode21-i686-with-debian-lenny-sid little-endian", so a Linux kernel 2.6.31.

It looks common on this buildbot that selector.select(timeout) takes less timeout seconds (without returning any event). "dt+granularity > timeout" test is False and so _run_once() does nothing, a new call is required.

Debug output of test_asyncio on "x86 Ubuntu Shared 3.x" (build 9632, test_asyncio passed):
---
[ 75/389] test_asyncio
WARNING: selector.select(timeout=0.09994344785809516907) took dt=0.09897190984338521957 sec (dt-timeout=-0.00097153801470994949)
WARNING: dt+0.00100000000000000002 > timeout? True
WARNING: selector.select(timeout=0.09991932008415460587) took dt=0.09855401515960693359 sec (dt-timeout=-0.00136530492454767227)
WARNING: dt+0.00100000000000000002 > timeout? False
WARNING: selector.select(timeout=0.00097305513918399811) took dt=0.00002539902925491333 sec (dt-timeout=-0.00094765610992908478)
WARNING: dt+0.00100000000000000002 > timeout? True
WARNING: selector.select(timeout=0.49995081406086683273) took dt=0.10032826289534568787 sec (dt-timeout=-0.39962255116552114487)
WARNING: dt+0.00100000000000000002 > timeout? False
WARNING: selector.select(timeout=0.39888287801295518875) took dt=0.39831575006246566772 sec (dt-timeout=-0.00056712795048952103)
WARNING: dt+0.00100000000000000002 > timeout? True
WARNING: selector.select(timeout=None) took dt=0.01029967889189720154 sec
WARNING: selector.select(timeout=None) took dt=0.07110145408660173416 sec
WARNING: selector.select(timeout=None) took dt=0.00214391853660345078 sec
WARNING: selector.select(timeout=None) took dt=0.00361407827585935593 sec
WARNING: selector.select(timeout=0.00991696026176214218) took dt=0.00975166168063879013 sec (dt-timeout=-0.00016529858112335205)
WARNING: dt+0.00100000000000000002 > timeout? True
WARNING: selector.select(timeout=0.49995493795722723007) took dt=0.10188415739685297012 sec (dt-timeout=-0.39807078056037425995)
WARNING: dt+0.00100000000000000002 > timeout? False
WARNING: selector.select(timeout=None) took dt=0.01038167160004377365 sec
WARNING: selector.select(timeout=None) took dt=0.00922694429755210876 sec
WARNING: selector.select(timeout=None) took dt=0.00215751212090253830 sec
WARNING: selector.select(timeout=None) took dt=0.01459381356835365295 sec
WARNING: selector.select(timeout=0.49995700363069772720) took dt=0.10038192663341760635 sec (dt-timeout=-0.39957507699728012085)
WARNING: dt+0.00000100000000000000 > timeout? False
WARNING: selector.select(timeout=None) took dt=0.01037232112139463425 sec
WARNING: selector.select(timeout=None) took dt=0.00168939027935266495 sec
WARNING: selector.select(timeout=None) took dt=0.00139459036290645599 sec
WARNING: selector.select(timeout=None) took dt=0.00180943403393030167 sec
WARNING: selector.select(timeout=None) took dt=0.00000000000000000000 sec
WARNING: selector.select(timeout=None) took dt=0.00000000000000000000 sec
WARNING: selector.select(timeout=None) took dt=0.00000000000000000000 sec
WARNING: selector.select(timeout=None) took dt=0.00000000000000000000 sec
WARNING: selector.select(timeout=None) took dt=0.00000000000000000000 sec
WARNING: selector.select(timeout=None) took dt=0.00000000000000000000 sec
WARNING: selector.select(timeout=None) took dt=0.00000000000000000000 sec
WARNING: selector.select(timeout=None) took dt=0.00000000000000000000 sec
WARNING: selector.select(timeout=None) took dt=0.00000000000000000000 sec
---

[neologix]

It looks like select() and poll() in Linux < 2.6.28 has a resolution
of 1/HZ, where HZ can be retrieved from os.sysconf('SC_CLK_TCK'). Since
Linux 2.6.28, hrtimers are now used for timeouts.

Attached patch improves the resolution field of selectors.BaseSelector.
By the way, resolution should be a method (selector.resolution())
rather than a property, because we may query the kernel to compute the
resolution, as shown in the patch.

That's exactly why I said that an explicit resolution is a bad idea:

• it's an implementation detail
• it's fragile (just look at your latest patch)
• it's useless

Just round the timeout away from 0 and be happy: this will fix the busy-wait problem, and that's all we want.
Once again, I know I keep repeating myself, but having select/epoll/whatever wake up 10usec before the timeout isn't an issue: *all* async-IO frameworks out there work just fine with this.

So please, revert all this granuarity complexity, and re-apply the timeout rounding.

[vstinner]

Just round the timeout away from 0 and be happy: this will fix the busy-wait problem, and that's all we want.

I didn't work, see:
http://bugs.python.org/issue20311#msg208601

Once again, I know I keep repeating myself, but having select/epoll/whatever wake up 10usec before the timeout isn't an issue: *all* async-IO frameworks out there work just fine with this.

The previous issue bpo-20311 and this one are not critical bug, just performance issues. I would prefer to not call _run_once() and epoll_wait() too many times if it's useless (if it can be avoided).

So please, revert all this granuarity complexity, and re-apply the timeout rounding.

*If* we come back to the rounding aways zero option and granularity is removed from asyncio.BaseEventLoop, the issue should also be fixed in the IOCP selector used by the proactor event loop in Python.

--

If we decide that it's not an issue that _run_once() is called too many times, the unit test can be changed to ensure that _run_once() is called less than 10 times, instead of expecting an exact number of calls (7 at the end): so tolerate 3 useless calls.

[vstinner]

More debug info on a new failure: test_timeout_rounding failed because once EPollSelector.select(timeout=0.0099) took dt=0.0086 seconds. dt-timeout=-0.0014 and dt+granularity > timeout is False (granularity=0.001, 1 millisecond).

• Buildbot: "x86 Gentoo Non-Debug 3.x"
• Linux kernel 2.6.35 (i686)
• clock_getres(CLOCK_MONOTONIC) = 1e-9 (1 nanosecond)
• os.sysconf('SC_CLK_TCK') = 100 (1/HZ => 10 ms ?)

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

Re-running test 'test_asyncio' in verbose mode

test_call_later (test.test_asyncio.test_events.EPollEventLoopTests) ...
WARNING: selector.select(timeout=0.09998385910876095295) took dt=0.09878822183236479759 sec (dt-timeout=-0.00119563727639615536)
WARNING: dt+0.00100000000000000002 > timeout? False
WARNING: selector.select(timeout=0.00106247211806476116) took dt=0.00085310707800090313 sec (dt-timeout=-0.00020936504006385803)
WARNING: dt+0.00100000000000000002 > timeout? True
ok

test_run_until_complete (test.test_asyncio.test_events.EPollEventLoopTests) ...
WARNING: selector.select(timeout=0.09997870912775397301) took dt=0.09859465109184384346 sec (dt-timeout=-0.00138405803591012955)
WARNING: dt+0.00100000000000000002 > timeout? False
WARNING: selector.select(timeout=0.00126257794909179211) took dt=0.00086452695541083813 sec (dt-timeout=-0.00039805099368095398)
WARNING: dt+0.00100000000000000002 > timeout? True
ok

test_signal_handling_args (test.test_asyncio.test_events.EPollEventLoopTests) ...
WARNING: selector.select(timeout=0.49998698616400361061) took dt=0.10008734907023608685 sec (dt-timeout=-0.39989963709376752377)
WARNING: dt+0.00100000000000000002 > timeout? False

WARNING: selector.select(timeout=0.39968195999972522259) took dt=0.39848947990685701370 sec (dt-timeout=-0.00119248009286820889)
WARNING: dt+0.00100000000000000002 > timeout? False

WARNING: selector.select(timeout=0.00107327196747064590) took dt=0.00087298289872705936 sec (dt-timeout=-0.00020028906874358654)
WARNING: dt+0.00100000000000000002 > timeout? True
ok

test_signal_handling_while_selecting (test.test_asyncio.test_events.EPollEventLoopTests) ...
WARNING: selector.select(timeout=None) took dt=0.01009305310435593128 sec
ok

test_subprocess_close_after_finish (test.test_asyncio.test_events.EPollEventLoopTests) ...
WARNING: selector.select(timeout=None) took dt=0.00544960913248360157 sec
ok

test_timeout_rounding (test.test_asyncio.test_events.EPollEventLoopTests) ...
WARNING: selector.select(timeout=0.00997558492235839367) took dt=0.00856216903775930405 sec (dt-timeout=-0.00141341588459908962)
WARNING: dt+0.00100000000000000002 > timeout? False

WARNING: selector.select(timeout=0.00129276583902537823) took dt=0.00085931317880749702 sec (dt-timeout=-0.00043345266021788120)
WARNING: dt+0.00100000000000000002 > timeout? True

WARNING: selector.select(timeout=0.00007506809197366238) took dt=0.00000555603764951229 sec (dt-timeout=-0.00006951205432415009)
WARNING: dt+0.00100000000000000002 > timeout? True
FAIL

test_signal_handling_args (test.test_asyncio.test_events.PollEventLoopTests) ... WARNING: selector.select(timeout=0.49998601293191313744) took dt=0.10008832695893943310 sec (dt-timeout=-0.39989768597297370434)
WARNING: dt+0.00100000000000000002 > timeout? False
ok

(...)

======================================================================
FAIL: test_timeout_rounding (test.test_asyncio.test_events.EPollEventLoopTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/var/lib/buildslave/3.x.murray-gentoo-wide/build/Lib/test/test_asyncio/test_events.py", line 1195, in test_timeout_rounding
    platform.platform()))
AssertionError: Lists differ: [1, 4, 6, 7] != [1, 3, 5, 6]

First differing element 1:
4
3

• [1, 4, 6, 7]
  + [1, 3, 5, 6] : (0.001, 0.001, namespace(adjustable=False, implementation='clock_gettime(CLOCK_MONOTONIC)', monotonic=True, resolution=1e-09), 100, 'Linux-2.6.35-vs2.3.0.36.32-gentoo-i686-Intel-R-Core-TM-2_CPU_6600@_2.40GHz-with-gentoo-2.1')

[python-dev]

New changeset 827d948ac6aa by Victor Stinner in branch 'default':
Issue bpo-20452: select and selectors round (again) timeout away from zero for
http://hg.python.org/cpython/rev/827d948ac6aa

[vstinner]

New changeset 827d948ac6aa by Victor Stinner in branch 'default':
Issue bpo-20452: select and selectors round (again) timeout away from zero

Let's test Charles-Francois option.

test_timeout_rounding failed because once EPollSelector.select(timeout=0.0099) took dt=0.0086 seconds

We asked to wait 9.9 ms, which was rounding to 9 ms. But epoll_wait() took 8.6 seconds: 8.6 is smaller than 9 ms.

In my opinion, rounding away from zero is not enough. We should probably round away from zero for selectors *and* compare times using the granularity.

Let's see what buildbots say :-)

[vstinner]

Results on "x86 Gentoo 3.x" buildbot:

[136/389] test_asyncio
WARNING: selector.select(timeout=0.09997069113887846470) took dt=0.09961039200425148010 sec (dt-timeout=-0.00036029913462698460)
WARNING: dt+0.00100000000000000002 > timeout? True
WARNING: selector.select(timeout=0.09995610709302127361) took dt=0.09992253710515797138 sec (dt-timeout=-0.00003356998786330223)
WARNING: dt+0.00100000000000000002 > timeout? True
WARNING: selector.select(timeout=0.00994763919152319431) took dt=0.00972709804773330688 sec (dt-timeout=-0.00022054114378988743)
WARNING: dt+0.00100000000000000002 > timeout? True

Ok, it looks better: waiting 99.9 ms took 99.6 ms and 99.9 ms, and waiting 9.9 ms took 9.7 ms. So as I said, the granularity (of 1 ms) is still needed in asyncio (dt < timeout is sometimes False, but dt+granulary >= timeout is always True).

We could round the timeout by adding 2 ms in epoll.poll(), but it would be inefficient: it reduces the accurary of 1 ms, whereas the change would only be needed by asyncio. IMO the granularity rounding is better because it uses also the resolution of the clock, which matters a lot on Windows whereas time.monotonic() has a resolution of 15.6 ms.

There are same results on "x86 Gentoo Non-Debug 3.x" and "x86 Ubuntu Shared 3.x" buildbots.

--

In test_signal_handling_args, dt+granularity > timeout is still True, because the selector was interrupted by a signal. For this case, loop_run_once.patch avoids a second call to _run_once(), but in fact it doesn't optimize anything (calling _run_once() again is just the same). Calling _run_once() again if selector was interrupted is just fine IMO. Example of interrupted selector:

WARNING: selector.select(timeout=0.49998722597956657410) took dt=0.10003586183302104473 sec (dt-timeout=-0.39995136414654552937)
WARNING: dt+0.00100000000000000002 > timeout? False

--

For time handling on Linux, see also:
http://www.python.org/dev/peps/pep-0418/#linux-clocksource

[python-dev]

New changeset 21aa1a224049 by Victor Stinner in branch 'default':
Issue bpo-20452: Remove debug code, no more needed
http://hg.python.org/cpython/rev/21aa1a224049

New changeset f9a09b40bc17 by Victor Stinner in branch 'default':
Issue bpo-20311, bpo-20452: poll and epoll now round the timeout away from zero,
http://hg.python.org/cpython/rev/f9a09b40bc17

[vstinner]

Summary of this issue:

• test_asyncio was still failing because BaseEventLoop._granularity was not enough to round correctly timeouts, deadlines and times. poll/epoll rounded towards zero, whereas asyncio rounds away from zero. So the maximum difference in _run_once() was 2 x resolution (2 ms), not resolution (1 ms)
• I modified poll and epoll in select and selectors modules in Python 3.4 to round the timeout away from zero. So the maximum difference is now resolution (1 ms for poll/epoll).

Now the question is: should we backport the rounding changes in select and selectors in Python 3.3? It's not required for asyncio, since Tulip has its backport of selectors.py which has the fix. For avoid any regression, it's safer to leave Python 3.3 unchanged, since nobody complained. It looks like only asyncio is affected by this issue. In fact, I don't think that any large application relies on select for its event loop: C libraries like libev, libevent and libuv are usually preferred.

So I prefer to leave Python 3.3 unchanged.

Note: I removed my debug mode.