[2.7] test_weakref hangs on Python 2.7 on Windows

[zware]

BPO	29796
Nosy	@pfmoore, @pitrou, @vstinner, @tjguk, @zware, @zooba
PRs	[2.7] bpo-29796: test_weakref: Fix collect_in_thread() on Windows #2553

^{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 2020-04-26.04:32:57.384>
created_at = <Date 2017-03-12.01:01:35.578>
labels = ['type-bug', 'tests', 'OS-windows']
title = '[2.7] test_weakref hangs on Python 2.7 on Windows'
updated_at = <Date 2020-04-27.12:17:59.788>
user = 'https://github.com/zware'

bugs.python.org fields:

activity = <Date 2020-04-27.12:17:59.788>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2020-04-26.04:32:57.384>
closer = 'zach.ware'
components = ['Tests', 'Windows']
creation = <Date 2017-03-12.01:01:35.578>
creator = 'zach.ware'
dependencies = []
files = []
hgrepos = []
issue_num = 29796
keywords = []
message_count = 12.0
messages = ['289461', '297614', '297615', '297616', '297617', '297632', '297634', '297635', '297638', '297647', '367292', '367411']
nosy_count = 6.0
nosy_names = ['paul.moore', 'pitrou', 'vstinner', 'tim.golden', 'zach.ware', 'steve.dower']
pr_nums = ['2553']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue29796'
versions = ['Python 2.7']

[zware]

See PR493 (https://ci.appveyor.com/project/python/cpython/build/2.7.13+.184) for an example. I'd rather not merge PR493, which adds AppVeyor to 2.7, until this is resolved.

[vstinner]

Another example (I checked, all tests are run except of test_weakref):

http://buildbot.python.org/all/builders/AMD64%20Windows7%20SP1%202.7/builds/148/steps/test/logs/stdio

...
0:05:30 [400/403] test_file_eintr passed
0:05:30 [401/403] test_glob passed
0:05:54 [402/403] test_mmap passed (41 sec)

command timed out: 1200 seconds without output, attempting to kill
program finished with exit code 1
elapsedTime=1556.477000

[vstinner]

The problem are the 3 tests of test_weakref which uses collect_in_thread():

• test_threaded_weak_valued_setdefault(): 50k iterations
• test_threaded_weak_valued_pop(): 50k iterations
• test_threaded_weak_valued_consistency(): 200k iterations

On my Linux with Python 2.7 compiled in debug mode, the two first tests take 1 second, but the last test takes 10 seconds.

[vstinner]

On Python 3, time.sleep(seconds) rounds seconds towards +Infinity: see bpo-22117, commot cb29f01. time.sleep(0.0001) sleeps 15.6 ms on Windows.

On Python 2.7, time.sleep(seconds) rounds towards zero. time.sleep(0.0001) sleeps 0 ms on Windows, and so the collect_in_thread() thread calls gc.collect() in a sleep.

[vstinner]

@antoine: Another example of performance issue caused by rounding ;-)

See also my article on pytime and timestamp rounding, https://haypo.github.io/pytime.html

[vstinner]

Another option is to change time.sleep() rounding, but it would impact all Python2 code using sleep()... I dislike this option. I expect many complains from users about such backward incompatible change in a minor
release.

[vstinner]

New changeset 1fef015 by Victor Stinner in branch '2.7':
bpo-29796: test_weakref: Fix collect_in_thread() on Windows (bpo-2553)
1fef015

[vstinner]

I looked at test_weakref duration on buildbots before my change:

• AMD64 Windows7 SP1 2.7: (less than 30 seconds)
• AMD64 Windows8 2.7: 36 sec
• AMD64 Windows8.1 Non-Debug 2.7: 450.6 sec

Hum. That's strange. I don't understand why sometimes test_weakref hangs, whereaas sometimes it pass in less than 60 seconds?

[vstinner]

Oh wow! The commit 1fef015 fixed PGO compilation on Python 2.7: http://buildbot.python.org/all/builders/AMD64%20Debian%20PGO%202.7/builds/227 is the first successful build since June 20. I didn't notice that the PGO buildbot was also stuck in running test_weakref in the compile step: job killed after 30 min.
---
...
0:06:01 [380/400] test_warnings
0:06:02 [381/400] test_wave
0:06:02 [382/400] test_weakref

command timed out: 1200 seconds without output running ['make', 'all'], attempting to kill
process killed by signal 9
program finished with exit code -1
elapsedTime=1699.111100
---

While build 206 was green, the buildbot started to fail in build 207:

http://buildbot.python.org/all/builders/AMD64%20Debian%20PGO%202.7/builds/207

The strange thing is that this change only contains two small changes:

• commit b39a748
• commit d4324ba

I fail to understand how these changes make test_weakref hangs.

Well, at least the good news is that it's now fixed ;-)

[vstinner]

With commit 1fef015, test_weakref takes 11 seconds on my Windows VM.

Without this fix, test_weakref runs for longer than 2 hour and 19 min on my Windows VM. I decided to kill the test, I don't want to burn my CPU too long :-)

So at least, on my Windows VM, the bug is trivial to reproduce!

[zware]

Looks like we forgot to close this one; as far as I can tell it was fixed. Being 2.7-only, it's time to be closed anyway :)

[vstinner]

Yep, I didn't see any test_weakref hang anymore since this commit.