test_sched failures on Windows buildbot

[nadeemvawda]

BPO	13878
Nosy	@giampaolo
Files	test_sched_race.diff

^{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 2012-02-16.19:44:59.346>
created_at = <Date 2012-01-26.16:57:18.193>
labels = ['type-bug', 'tests']
title = 'test_sched failures on Windows buildbot'
updated_at = <Date 2012-02-16.19:44:59.345>
user = 'https://bugs.python.org/nadeemvawda'

bugs.python.org fields:

activity = <Date 2012-02-16.19:44:59.345>
actor = 'neologix'
assignee = 'none'
closed = True
closed_date = <Date 2012-02-16.19:44:59.346>
closer = 'neologix'
components = ['Tests']
creation = <Date 2012-01-26.16:57:18.193>
creator = 'nadeem.vawda'
dependencies = []
files = ['24439']
hgrepos = []
issue_num = 13878
keywords = ['patch', 'needs review']
message_count = 9.0
messages = ['152022', '152023', '152625', '152786', '153132', '153357', '153366', '153492', '153496']
nosy_count = 4.0
nosy_names = ['giampaolo.rodola', 'nadeem.vawda', 'neologix', 'python-dev']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue13878'
versions = ['Python 2.7', 'Python 3.2', 'Python 3.3']

[nadeemvawda]

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.

[nadeemvawda]

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

[neologix]

"""
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).

[neologix]

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.

[nadeemvawda]

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])

[neologix]

Well, it's not really needed, as long as scheduler deals correctly
with expired deadlines.

[nadeemvawda]

Ah, I suppose that makes sense.

[python-dev]

New changeset 662c60d26183 by Charles-François Natali in branch '3.2':
Issue bpo-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 bpo-13878: Fix random test_sched failures.
http://hg.python.org/cpython/rev/e35091b95813

[neologix]

Should be fixed now, thanks.