test_code leaked [1, 1, 1] memory blocks on x86 Gentoo Refleaks 3.6/3.x

[vstinner]

BPO	31217
Nosy	@brettcannon, @pitrou, @vstinner, @zware
PRs	bpo-31217: Fix regrtest -R for small integer #3258 bpo-31217: Fix regrtest -R for small integer #3260 [3.6] bpo-31217: Fix regrtest -R for small integer (#3260) #3261
Files	test_leak.py leak.py test_haypoleak.py leak2.py

^{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 2017-09-01.13:13:53.099>
created_at = <Date 2017-08-16.09:41:40.492>
labels = ['3.7', 'tests', 'performance']
title = 'test_code leaked [1, 1, 1] memory blocks on x86 Gentoo Refleaks 3.6/3.x'
updated_at = <Date 2017-09-01.13:13:53.098>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2017-09-01.13:13:53.098>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2017-09-01.13:13:53.099>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2017-08-16.09:41:40.492>
creator = 'vstinner'
dependencies = []
files = ['47110', '47112', '47113', '47114']
hgrepos = []
issue_num = 31217
keywords = []
message_count = 24.0
messages = ['300344', '300442', '300443', '300689', '301049', '301051', '301054', '301055', '301059', '301069', '301070', '301072', '301073', '301074', '301075', '301076', '301077', '301079', '301081', '301082', '301090', '301094', '301100', '301101']
nosy_count = 4.0
nosy_names = ['brett.cannon', 'pitrou', 'vstinner', 'zach.ware']
pr_nums = ['3258', '3260', '3261']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'resource usage'
url = 'https://bugs.python.org/issue31217'
versions = ['Python 3.6', 'Python 3.7']

[vstinner]

http://buildbot.python.org/all/builders/x86%20Gentoo%20Refleaks%203.6/builds/58/steps/test/logs/stdio

test_code leaked [1, 1, 1] memory blocks, sum=3
(...)
Re-running test 'test_code' in verbose mode
(...)
test_code leaked [1, 1, 1] memory blocks, sum=3

I'm unable to reproduce the bug:

haypo@selma$ ./python -m test -R 3:3 test_code
(...)
1 test OK.

[vstinner]

It's even worse, many tests fail with 1 to 3 memory blocks on x86 Gentoo Refleaks 3.x... but then pass when run again.

I created bpo-31227 "regrtest: reseed random with the same seed before running a test file" which might help (or not?) this issue.

http://buildbot.python.org/all/builders/x86%20Gentoo%20Refleaks%203.x/builds/62

test_sys leaked [1, 1, 1] memory blocks, sum=3
test_robotparser leaked [1, 1, 1] memory blocks, sum=3
test_nntplib leaked [1, 1, 1] memory blocks, sum=3
test_tools leaked [3, 2, 1] memory blocks, sum=6
test_fork1 leaked [1, 1, 1] memory blocks, sum=3
test_poll leaked [1, 1, 1] memory blocks, sum=3
test_asyncio leaked [2, 1, 1] memory blocks, sum=4

Re-running failed tests in verbose mode
Re-running test 'test_sys' in verbose mode
Re-running test 'test_robotparser' in verbose mode
Re-running test 'test_nntplib' in verbose mode
Re-running test 'test_tools' in verbose mode
test_tools leaked [1, 3, 1] memory blocks, sum=5
Re-running test 'test_fork1' in verbose mode
Re-running test 'test_poll' in verbose mode
Re-running test 'test_asyncio' in verbose mode

[vstinner]

regrtest also has an issue: when tests are run again, they should be run in a fresh process, especially when tests are run in parallel (-jN).

[vstinner]

I succeeded to reproduce a leak on the x86 Gentoo Refleaks 3.x buildbot using the following command. I'm unable to reproduce the bug on my Fedora 25.

pydev@stormageddon ~/cpython $ ./python -m test -R 3:3 -j1 -m test.test_code.CoExtra.test_free_different_thread test_code -F
Run tests in parallel using 1 child processes
0:00:00 load avg: 2.26 [ 1/1] test_code failed
beginning 6 repetitions
123456
......
test_code leaked [1, 1, 1] memory blocks, sum=3
0:00:01 load avg: 2.26 [ 2/2] test_code failed
beginning 6 repetitions
123456
......
test_code leaked [1, 1, 1] memory blocks, sum=3

2 tests failed:
test_code test_code

Total duration: 2 sec
Tests result: FAILURE

[vstinner]

Another command to reproduce a leak:

./python -m test -R 3:3 -j1 test_sys -F -m test.test_sys.SysModuleTest.test_current_frames

[vstinner]

Current status of my analysis. I'm able to reproduce the bug using this modified Lib/test/test_sys.py:
---

import unittest, test.support
from test.support.script_helper import assert_python_ok
import threading

def f123():
    pass

class SysModuleTest(unittest.TestCase):
    def test_current_frames(self):
        t = threading.Thread(target=f123)
        t.start()
        t.join()

---

And this shell script:
---
set -x
while true; do PYTHONHASHSEED=$RANDOM ./python -m test -R 3:3 -j1 test_sys -m test_current_frames || break; done
---

With this command, when the test fail, it's possible to reproduce the bug 100% of times using the written PYTHONHASHSEED. Example:
---
pydev@stormageddon ~/cpython $ ./bug.sh
++ true
++ PYTHONHASHSEED=23016
++ ./python -m test -R 3:3 -j1 test_sys -m test_current_frames
Run tests in parallel using 1 child processes
0:00:00 load avg: 0.15 [1/1] test_sys passed
beginning 6 repetitions
123456
......
1 test OK.

Total duration: 982 ms
Tests result: SUCCESS
++ true
++ PYTHONHASHSEED=9197
++ ./python -m test -R 3:3 -j1 test_sys -m test_current_frames
Run tests in parallel using 1 child processes
0:00:00 load avg: 0.22 [1/1/1] test_sys failed
beginning 6 repetitions
123456
......
test_sys leaked [1, 1, 1] memory blocks, sum=3

1 test failed:
test_sys

Total duration: 1000 ms
Tests result: FAILURE
++ break

pydev@stormageddon ~/cpython $ PYTHONHASHSEED=9197 ./python -m test -R 3:3 -j1 test_sys -m test_current_frames
Run tests in parallel using 1 child processes
0:00:00 load avg: 0.20 [1/1/1] test_sys failed
beginning 6 repetitions
123456
......
test_sys leaked [1, 1, 1] memory blocks, sum=3

1 test failed:
test_sys

Total duration: 987 ms
Tests result: FAILURE
---

[vstinner]

Ok, I succeeded to reproduce the issue on my amd64 laptop using gcc -m32. I'm now sure that the issue can be reproduced on 32-bit. Maybe the issue can be reproduced on 64-bit but is more unlikely?

[vstinner]

Copy attached test_leak.py to Lib/test/ and run:

set -x
while true; do PYTHONHASHSEED=$RANDOM ./python -m test -R 3:30 -j1 test_leak || break; done

[vstinner]

I created bpo-31317: Memory leak in dict with shared keys.

[vstinner]

I'm still able to reproduce the bug using attached leak.py script which is now 100 lines long, but has to import logging, socket and pickle. Without these imports, the bug hides (maybe the hardcoded hash values must be recomputed, but I failed to find hash values in that case).

[pitrou]

Attached test script still fails even though the objects are pre-allocated, and without setting a hash seed.

$ ./python -m test -R 3:6 test_haypoleak
Run tests sequentially
0:00:00 load avg: 0.23 [1/1] test_haypoleak
beginning 9 repetitions
123456789
.........
test_haypoleak leaked [1, 1, 1, 1, 1, 1] memory blocks, sum=6
test_haypoleak failed