This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: test_sched failures on Windows buildbot
Type: behavior Stage: resolved
Components: Tests Versions: Python 3.2, Python 3.3, Python 2.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: giampaolo.rodola, nadeem.vawda, neologix, python-dev
Priority: normal Keywords: needs review, patch

Created on 2012-01-26 16:57 by nadeem.vawda, last changed 2022-04-11 14:57 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
test_sched_race.diff neologix, 2012-02-06 21:59 review
Messages (9)
msg152022 - (view) Author: Nadeem Vawda (nadeem.vawda) * (Python committer) Date: 2012-01-26 16:57
http://www.python.org/dev/buildbot/all/builders/x86%20XP-5%203.x/builds/4072/steps/test/logs/stdio:

    FAIL: test_enter (test.test_sched.TestCase)
    ----------------------------------------------------------------------
    Traceback (most recent call last):
      File "D:\Buildslave\3.x.moore-windows\build\lib\test\test_sched.py", line 18, in test_enter
        self.assertEqual(l, [0.01, 0.02, 0.03, 0.04, 0.05])
    AssertionError: Lists differ: [0.01, 0.02, 0.03, 0.05, 0.04] != [0.01, 0.02, 0.03, 0.04, 0.05]

    First differing element 3:
    0.05
    0.04

    - [0.01, 0.02, 0.03, 0.05, 0.04]
    ?                        ------

    + [0.01, 0.02, 0.03, 0.04, 0.05]
    ?                    ++++++


http://www.python.org/dev/buildbot/all/builders/x86%20XP-5%203.x/builds/4062/steps/test/logs/stdio:

    FAIL: test_queue (test.test_sched.TestCase)
    ----------------------------------------------------------------------
    Traceback (most recent call last):
      File "D:\Buildslave\3.x.moore-windows\build\lib\test\test_sched.py", line 74, in test_queue
        self.assertEqual(list(scheduler.queue), [e1, e2, e3, e4, e5])
    AssertionError: Lists differ: [Event(time=1327366698.525, pr... != [Event(time=1327366698.525, pr...

    First differing element 3:
    Event(time=1327366698.565, priority=1, action=<function TestCase.test_queue.<locals>.<lambda> at 0x03419158>, argument=[], kwargs={})
    Event(time=1327366698.5709999, priority=1, action=<function TestCase.test_queue.<locals>.<lambda> at 0x03419158>, argument=[], kwargs={})

    Diff is 1268 characters long. Set self.maxDiff to None to see it.
msg152023 - (view) Author: Nadeem Vawda (nadeem.vawda) * (Python committer) Date: 2012-01-26 16:58
Oops, those links should be:
  http://www.python.org/dev/buildbot/all/builders/x86%20XP-5%203.x/builds/4072/steps/test/logs/stdio
and:
  http://www.python.org/dev/buildbot/all/builders/x86%20XP-5%203.x/builds/4062/steps/test/logs/stdio
msg152625 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2012-02-04 15:10
"""
for x in [0.05, 0.04, 0.03, 0.02, 0.01]:
    z = scheduler.enter(x, 1, fun, (x,))
"""

Since the test uses relative times, if the process is preempted more than 0.01s between two calls to enter (or if the clock goes backwards), the absolute times won't be monotonic:

time.time() -> t
scheduler.enter(0.05, 1, fun, (0.05,)) -> scheduler.enterabs(t+0.05, 1, fun, (0,))
<preempted for 0.02s/clock goes backwards>
time.time() -> t+0.02
scheduler.enter(0.04, 1, fun, (0.04,)) -> scheduler.enterabs(t+0.02+0.04=t+0.06, 1, fun, (0,))
and 0.04 would end up after 0.05 in the queue.

Changing the sequence for [0.5, 0.4, 0.3, 0.2, 0.1] should make the test more robust (other tests seem to have the same problem).
msg152786 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2012-02-06 21:59
Here's another failure due to the same type of race:

"""
======================================================================
FAIL: test_queue (test.test_sched.TestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\Buildslave\3.x.moore-windows\build\lib\test\test_sched.py", line 74, in test_queue
    self.assertEqual(list(scheduler.queue), [e1, e2, e3, e4, e5])
AssertionError: Lists differ: [Event(time=1328544857.025, pr... != [Event(time=1328544857.025, pr...

First differing element 2:
Event(time=1328544857.055, priority=1, action=<function TestCase.test_queue.<locals>.<lambda> at 0x04C072D8>, argument=[], kwargs={})
Event(time=1328544857.0609999, priority=1, action=<function TestCase.test_queue.<locals>.<lambda> at 0x04C072D8>, argument=[], kwargs={})

Diff is 836 characters long. Set self.maxDiff to None to see it.
"""

Here's a patch that:
- increases the timeouts for test_enter
- converts other tests to use enterabs() instead of enter()

It should fix all those failures.
msg153132 - (view) Author: Nadeem Vawda (nadeem.vawda) * (Python committer) Date: 2012-02-11 19:18
Patch looks good, but you might want to make this change to test_priority:

             l = []
             fun = lambda x: l.append(x)
             scheduler = sched.scheduler(time.time, time.sleep)
    +        now = time.time()
             for priority in [1, 2, 3, 4, 5]:
    -            z = scheduler.enterabs(0.01, priority, fun, (priority,))
    +            z = scheduler.enterabs(now + 0.01, priority, fun, (priority,))
             scheduler.run()
             self.assertEqual(l, [1, 2, 3, 4, 5])
msg153357 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2012-02-14 18:43
Well, it's not really needed, as long as scheduler deals correctly
with expired deadlines.
msg153366 - (view) Author: Nadeem Vawda (nadeem.vawda) * (Python committer) Date: 2012-02-14 19:33
Ah, I suppose that makes sense.
msg153492 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2012-02-16 18:55
New changeset 662c60d26183 by Charles-François Natali in branch '3.2':
Issue #13878: Fix random test_sched failures.
http://hg.python.org/cpython/rev/662c60d26183

New changeset e35091b95813 by Charles-François Natali in branch 'default':
Issue #13878: Fix random test_sched failures.
http://hg.python.org/cpython/rev/e35091b95813
msg153496 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2012-02-16 19:44
Should be fixed now, thanks.
History
Date User Action Args
2022-04-11 14:57:26adminsetgithub: 58086
2012-02-16 19:44:59neologixsetstatus: open -> closed
resolution: fixed
messages: + msg153496

stage: needs patch -> resolved
2012-02-16 18:55:18python-devsetnosy: + python-dev
messages: + msg153492
2012-02-14 19:33:55nadeem.vawdasetmessages: + msg153366
2012-02-14 18:43:05neologixsetmessages: + msg153357
2012-02-11 19:18:31nadeem.vawdasetmessages: + msg153132
2012-02-06 21:59:43neologixsetfiles: + test_sched_race.diff
versions: + Python 2.7, Python 3.2, Python 3.3
messages: + msg152786

components: + Tests
keywords: + patch, needs review
2012-02-04 15:10:10neologixsetnosy: + neologix
messages: + msg152625
2012-01-26 16:58:20nadeem.vawdasetmessages: + msg152023
2012-01-26 16:57:18nadeem.vawdacreate