classification
Title: test_files() of test_tools.test_unparse.DirectoryTestCase leaks references
Type: Stage: resolved
Components: Tests Versions: Python 3.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: louielu, npatel, vstinner, zvyn
Priority: normal Keywords:

Created on 2017-06-01 20:42 by vstinner, last changed 2017-06-28 00:34 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
bug.py vstinner, 2017-06-07 16:53
test_unparse.py vstinner, 2017-06-07 21:52
Messages (14)
msg294963 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-01 20:42
haypo@selma$ ./python -m test -R 3:3 test_tools -m test_files
Run tests sequentially
0:00:00 load avg: 0.57 [1/1] test_tools
beginning 6 repetitions
123456
......
test_tools leaked [0, 4, 0] references, sum=4
test_tools leaked [0, 3, 0] memory blocks, sum=3
test_tools failed

1 test failed:
    test_tools

Total duration: 12 sec
Tests result: FAILURE

Note: I found it using Zachary's x86 Gentoo Refleaks buildbot and bpo-29512.
msg294996 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-02 09:07
I tagged this issue as easy. I consider that it's a good exercice for new contributors. Core developers: please let new contributors try to fix it since this issue is not critical, try to explain how to fix it rather than writing the fix ;-)
msg295002 - (view) Author: Louie Lu (louielu) * Date: 2017-06-02 10:16
Haypo: How do you know that this is leaked at test_files() of test_tools.test_unparse.DirectoryTestCase? The result of your command didn't reveal that is leaked at which test case or function.
msg295003 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-02 10:36
> Haypo: How do you know that this is leaked at test_files() of test_tools.test_unparse.DirectoryTestCase? The result of your command didn't reveal that is leaked at which test case or function.

Using the script I wrote which is attached to issue29512.
msg295060 - (view) Author: Milan Oberkirch (zvyn) * Date: 2017-06-02 23:00
I tried to pin this leak down and got to the point where I suspect the compile call:

    def check_roundtrip(self, code1, filename="internal"):
        ast1 = compile(code1, filename, "exec", ast.PyCF_ONLY_AST)

the leaks occur with only that line in the function and do not occur without it.

To me it looks like a direct result of some leak somewhere in the tested code?

Garrett: I'm happy for you to take over (please leave a comment if you do)!
msg295250 - (view) Author: Louie Lu (louielu) * Date: 2017-06-06 11:19
Briefly speaking, I think this is not a *easy* issue. There is two things need to concern in this issue. 

First, it that the test case is *randomize*, lineno 282 randomly choice 10 file to test. So you will need to stabilize this first.

Second, the minimize range is inside `self.check_roundtrip`'s `compile`, the main reason that this issue can not be *easy issue* is at here, test_unparse read the test file and put it into compile, so generally, you can't find the bug inside the compile function, is the result after compile it. So the main ref leak is in other test files, not this one.
msg295355 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-07 16:51
I isolated the leak to attached bug.py script. Output:
---
haypo@selma$ ./python bug.py 
[ Top 10 differences ]
bug.py:40: size=6728 B (+6728 B), count=80 (+80), average=84 B
bug.py:46: size=2464 B (+2464 B), count=28 (+28), average=88 B
bug.py:43: size=2464 B (+2464 B), count=28 (+28), average=88 B
---

It seems like compiling a Python source to AST causes the leak. The Python source uses the following bytecodes:

 25         170 LOAD_DEREF               0 (trace)
            172 LOAD_METHOD              0 (append)
            174 LOAD_CONST               0 (None)
            176 CALL_METHOD              1
            178 POP_TOP

AST of the code:

Expr(value=Call(func=Attribute(value=Name(id='trace', ctx=Load()), attr='append', ctx=Load()), args=[NameConstant(value=None)], keywords=[]))
msg295356 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-07 16:53
(Oops, I modified the file while uploading here. I reuploaded the correct bug.py.)
msg295357 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-07 17:07
It seems like compile() only leaks when using PyCF_ONLY_AST:

compile(source, "filename", "exec", ast.PyCF_ONLY_AST)

It's maybe a leak in the PyAST_mod2obj() function when creating dictionaries of created AST objects. But in ast_dealloc() of Python/Python-ast.c, I see that a "DECREF" (Py_CLEAR) for the dict. Maybe it's something else.
msg295367 - (view) Author: Nikhil Patel (npatel) * Date: 2017-06-07 20:23
I'd like to respectfully disagree with the suggestions/conclusions mentioned here. I'll explain my reasoning and conclusions below.

First the short version - I'm fairly confident the leak actually has to do with: https://github.com/python/cpython/blob/master/Lib/test/test_tools/test_unparse.py#L282


my approach:

It was initially implied that we can begin to pinpoint the leak from within the test_files() method in test_tools.test_unparse.DirectoryTestCase.

I ran the tests using the command:
python_d -m test -R 3:3 test_tools.test_unparse -m test_files

I had test_files() print the files selected in line 282 (and limited sample size to 1).

Result:
(note: i shortened printed pathnames manually after the fact, as it printed the absolute paths)

python_d -m test -R 3:3 test_tools.test_unparse -m test_files
Run tests sequentially
0:00:00 [1/1] test_tools.test_unparse
Testing cpython\Lib\test\test_spwd.py
beginning 6 repetitions
123456
Testing cpython\Lib\copy.py
.Testing cpython\Lib\test\test_isinstance.py
.Testing cpython\Lib\test\test_bytes.py
.Testing cpython\Lib\test\test_csv.py
.Testing cpython\Lib\test\test_dynamic.py
.Testing cpython\Lib\test\test_xml_etree.py
.
test_tools.test_unparse leaked [3, 0, 13] references, sum=16
test_tools.test_unparse leaked [6, 2, 4] memory blocks, sum=12
test_tools.test_unparse failed

1 test failed:
    test_tools.test_unparse

Total duration: 4 sec
Tests result: FAILURE

Then I made a slight modification: I replaced random.sample(names,1) on line 282 with a list containing the absolute paths to each of those files it tested in the run I described above. That means each of those files would be loaded, compiled and their tests run 6 times.

Result:

python_d -m test -R 3:3 test_tools.test_unparse -m test_files
Run tests sequentially
0:00:00 [1/1] test_tools.test_unparse
beginning 6 repetitions
123456
......
1 test OK.

Total duration: 24 sec
Tests result: SUCCESS


Conclusion:
If the same source files are being read, compiled, and their tests run - with different results - then I do not believe the leak can be associated with the self.checkRoundTrip() method or the compile() method


I don't have an in-depth explanation why this is the case. But removing the call to random.sample() fixes the issue, I am reasonably sure of it. 

I presume to say this because I commented out lines 280-282 and instead I made it instead iterate through subsets of size 50 using slicing (so names[:50] etc) in line 284. I went through the entire set of files, 50 at a time. All ran successfully.
msg295371 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-07 21:12
Sorry, I tagged the issue too early as "[EASY]" while it's a super complex bug... I'm unable to say if the issue is a real leak or not...
msg295375 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-07 21:52
Attached test_unparse.py file should be copied to Lib/test/test_tools/test_unparse.py to run:

./python -m test -R 1:2 -m test_files test_tools

With this change, I get this output:
---
haypo@selma$ ./python -m test -R 1:2 -m test_files test_tools
Run tests sequentially
0:00:00 load avg: 0.12 [1/1] test_tools
beginning 3 repetitions
123
...
test_tools leaked [6, 19] references, sum=25
test_tools leaked [3, 5] memory blocks, sum=8
test_tools failed

1 test failed:
    test_tools

Total duration: 223 ms
Tests result: FAILURE
---
msg296973 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-26 23:16
Example of 3 runs:

test_tools leaked [10, 15, 0] references, sum=25
test_tools leaked [2, 13, 0] references, sum=15
test_tools leaked [180, 0, 0] references, sum=180

The bpo-30776 should fix this issue by ignoring the result, since it's a false positive in pratice.
msg297084 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-28 00:34
test_tools leak was a false alarm which has been fixed in regrtest by bpo-30776.
History
Date User Action Args
2017-06-28 00:34:54vstinnersetstatus: open -> closed
resolution: not a bug
messages: + msg297084

stage: resolved
2017-06-26 23:16:16vstinnersetmessages: + msg296973
2017-06-07 21:52:15vstinnersetfiles: + test_unparse.py

messages: + msg295375
2017-06-07 21:13:06vstinnersetkeywords: - easy (C)
2017-06-07 21:12:42vstinnersetmessages: + msg295371
title: [EASY] test_files() of test_tools.test_unparse.DirectoryTestCase leaks references -> test_files() of test_tools.test_unparse.DirectoryTestCase leaks references
2017-06-07 20:23:44npatelsetnosy: + npatel
messages: + msg295367
2017-06-07 17:07:00vstinnersetmessages: + msg295357
2017-06-07 16:53:50vstinnersetfiles: + bug.py

messages: + msg295356
2017-06-07 16:53:17vstinnersetfiles: - bug.py
2017-06-07 16:51:07vstinnersetfiles: + bug.py

messages: + msg295355
2017-06-06 11:19:31louielusetmessages: + msg295250
2017-06-02 23:00:25zvynsetnosy: + zvyn
messages: + msg295060
2017-06-02 10:36:09vstinnersetmessages: + msg295003
2017-06-02 10:16:28louielusetnosy: + louielu
messages: + msg295002
2017-06-02 09:07:33vstinnersetkeywords: + easy (C)

messages: + msg294996
title: test_files() of test_tools.test_unparse.DirectoryTestCase leaks references -> [EASY] test_files() of test_tools.test_unparse.DirectoryTestCase leaks references
2017-06-01 20:42:40vstinnercreate