test_functools leaks randomly 1 memory block

[vstinner]

BPO	36560
Nosy	@vstinner, @methane, @serhiy-storchaka, @ilevkivskyi, @Fidget-Spinner
PRs	[WIP] bpo-36560: _abc now uses weakref.WeakSet type #12743 bpo-36560: Fix reference leak huting in regrtest #12744 [2.7] bpo-36560: Fix reference leak hunting in regrtest (GH-12744) #12745 bpo-36560: regrtest: don't collect the GC twice #12747 [3.7] bpo-36560: regrtest: don't collect the GC twice (GH-12747) #12749
Files	test_functools.py test_functools2.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 2021-05-26.22:40:21.672>
created_at = <Date 2019-04-08.14:22:16.492>
labels = ['3.8', 'tests']
title = 'test_functools leaks randomly 1 memory block'
updated_at = <Date 2021-08-31.16:05:56.040>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2021-08-31.16:05:56.040>
actor = 'kj'
assignee = 'none'
closed = True
closed_date = <Date 2021-05-26.22:40:21.672>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2019-04-08.14:22:16.492>
creator = 'vstinner'
dependencies = []
files = ['48246', '48250']
hgrepos = []
issue_num = 36560
keywords = ['patch']
message_count = 21.0
messages = ['339643', '339651', '339662', '339663', '339731', '339732', '339733', '339735', '339738', '339768', '339772', '339777', '339781', '339965', '340386', '353071', '371286', '394485', '400739', '400742', '400754']
nosy_count = 5.0
nosy_names = ['vstinner', 'methane', 'serhiy.storchaka', 'levkivskyi', 'kj']
pr_nums = ['12743', '12744', '12745', '12747', '12749']
priority = 'normal'
resolution = 'out of date'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue36560'
versions = ['Python 3.8']

[vstinner]

Sometimes, each run of test_functools leaks exactly 1 memory block, even when the whole test is "re-run in verbose mode". Sometimes, it doesn't leak.

https://buildbot.python.org/all/#/builders/80/builds/550

test_functools leaked [1, 1, 1] memory blocks, sum=3
Re-running test 'test_functools' in verbose mode
test_functools leaked [1, 1, 1] memory blocks, sum=3

Maybe the problem comes from

Example on Linux:

$ ./python -m test -F -r -j1 -R 3:3 test_functools  
Using random seed 3891892
Run tests in parallel using 1 child processes
0:00:01 load avg: 2.38 [  1] test_functools passed
beginning 6 repetitions
123456
......
(...)
0:00:06 load avg: 2.27 [  6] test_functools passed
beginning 6 repetitions
123456
......
0:00:07 load avg: 2.27 [  7/1] test_functools failed
beginning 6 repetitions
123456
......
test_functools leaked [1, 2, 1] memory blocks, sum=4
0:00:08 load avg: 2.27 [  8/1] test_functools passed
beginning 6 repetitions
123456
......

== Tests result: FAILURE ==

7 tests OK.

1 test failed:
test_functools

Total duration: 8 sec 333 ms
Tests result: FAILURE

[vstinner]

Current bisection progress: I'm able to reproduce a failure with attached test_functools.py (211 lines) using:

./python -m test -F -j5 -R 3:3 test_functools

It takes between 4 and 200 runs to reproduce the failure, I don't understand what triggers the bug.

I failed to identify if the bug is more likely when the system is idle or when the system is busy. It looks purely random.

[vstinner]

Some progress.

I'm now able to reproduce the issue with attached test_functools2.py (103 lines, a single test method):

$ cp (...)test_functools2.py Lib/test/
$ ./configure -C --with-pydebug CFLAGS=-O0
$ make
$ ./python -m test -F -j5 -R 3:3 test_functools2
(...)
0:00:02 load avg: 0.95 [ 19/1] test_functools failed
beginning 6 repetitions
123456
......
test_functools leaked [1, 1, 1] memory blocks, sum=3
(...)
Tests result: FAILURE

I disabled the C accelerator _functools.

I'm now trying to disable the C accelerator of abc, but I had a small issue: bpo-36565.

[vstinner]

The issue comes maybe from the complex code in Lib/test/libregrtest/refleak.py to handle the ABC cache:

    abcs = {}
    for abc in [getattr(collections.abc, a) for a in collections.abc.__all__]:
        if not isabstract(abc):
            continue
        for obj in abc.__subclasses__() + [abc]:
            abcs[obj] = _get_dump(obj)[0]

...

    # clear type cache
    sys._clear_type_cache()

    # Clear ABC registries, restoring previously saved ABC registries.
    abs_classes = [getattr(collections.abc, a) for a in collections.abc.__all__]
    abs_classes = filter(isabstract, abs_classes)
    for abc in abs_classes:
        for obj in abc.__subclasses__() + [abc]:
            for ref in abcs.get(obj, set()):
                if ref() is not None:
                    obj.register(ref())
            obj._abc_caches_clear()

    clear_caches()

[vstinner]

This issue isn't a real memory leak: if I use -R 3:10 instead of -R 3:3, the test doesn't fail anymore.

But the issue is still annoying since it makes Refleaks buildbot workers fail randomly :-/

This issue remembers me the unstable multiprocessing tests:

• bpo-33735: test_multiprocessing_spawn leaked [1, 2, 1] memory blocks on AMD64 Windows8.1 Refleaks 3.7
• bpo-33984: test_multiprocessing_forkserver leaked [1, 2, 1] memory blocks on x86 Gentoo Refleaks 3.x

Patch to always display memory allocations differences:

diff --git a/Lib/test/libregrtest/refleak.py b/Lib/test/libregrtest/refleak.py
index d68ea63b5b..997be819fa 100644
--- a/Lib/test/libregrtest/refleak.py
+++ b/Lib/test/libregrtest/refleak.py
@@ -118,6 +118,8 @@ def dash_R(the_module, test, indirect_test, huntrleaks):
                 print(msg, file=refrep)
                 refrep.flush()
             failed = True
+    if not failed:
+        print(alloc_deltas[nwarmup:])
     return failed
 

Truncated output with the patch:

vstinner@apu$ ./python -m test -F -r -j1 -R 3:10 test_functools
Using random seed 4308771
Run tests in parallel using 1 child processes
0:00:04 load avg: 0.91 [ 1] test_functools passed
[0, 1, 2, 0, 0, 0, 0, 0, 0, 0]
...
0:00:13 load avg: 0.92 [ 3] test_functools passed
[2, 1, 0, 0, 0, 0, 0, 0, 0, 0]
...
0:00:17 load avg: 0.93 [ 4] test_functools passed
[0, 3, 0, 0, 0, 0, 0, 0, 0, 0]
...
0:00:21 load avg: 0.93 [ 5] test_functools passed
[0, 1, 0, 0, 2, 0, 0, 0, 0, 0]
...
0:00:26 load avg: 0.93 [ 6] test_functools passed
[0, 4, 0, 0, 0, 0, 0, 0, 0, 0]
...
0:00:34 load avg: 0.87 [ 8] test_functools passed
[0, 1, 0, 2, 0, 0, 0, 0, 0, 0]
...
0:01:06 load avg: 1.15 [ 15] test_functools passed
[0, 1, 0, 2, 0, -1, 1, 0, 0, 0]
...
0:01:10 load avg: 1.46 [ 16] test_functools passed
[0, 4, 0, 0, 0, 0, 0, 0, -1, 1]
...

The maximum sum() of these list is around 5 on 10 runs: not every run leaks a memory block. It looks more like a internal cache which is "unstable" if you look at the number of allocated memory blocks.

[vstinner]

I wrote PR 12743 to modify _abc: use weakref.WeakSet rather than using directly a set of weak references. With this PR, calling _get_dump() should clear all broken weak references. I'm not sure if it's really useful for this specific issue, since dash_R_cleanup() calls obj._abc_caches_clear() on all abstract base classes (ABC): all caches must be removed before reading the total number of allocated memory blocks (sys.getallocatedblocks()).

[serhiy-storchaka]

_abc was written for optimization. Your PR makes it using slower Python code. Could you please test how much this hits the performance of abc?

[vstinner]

If I modify libregrtest with the following patch:

diff --git a/Lib/test/libregrtest/refleak.py b/Lib/test/libregrtest/refleak.py
index 0bb8a0a2bf..f0225a9768 100644
--- a/Lib/test/libregrtest/refleak.py
+++ b/Lib/test/libregrtest/refleak.py
@@ -128,7 +128,7 @@ def dash_R(ns, the_module, test_name, test_func):
     failed = False
     for deltas, item_name, checker in [
         (rc_deltas, 'references', check_rc_deltas),
-        (alloc_deltas, 'memory blocks', check_rc_deltas),
+        (alloc_deltas, 'memory blocks', check_fd_deltas),
         (fd_deltas, 'file descriptors', check_fd_deltas)
     ]:
         # ignore warmup runs

And I add the following file Lib/test/test_noop.py:

import unittest

class NoopTests(unittest.TestCase):
    def test_noop(self):
        pass

regrtest detects a "leak":

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

== Tests result: FAILURE ==

1 test failed:
test_noop

Total duration: 113 ms
Tests result: FAILURE

The issue comes from this look in Lib/test/libregrtest/refleak.py:

    for i in range(repcount):
        indirect_test()
        alloc_after, rc_after, fd_after = dash_R_cleanup(fs, ps, pic, zdc,
                                                         abcs)
        print('.', end='', file=sys.stderr, flush=True)
        if i >= nwarmup:
            rc_deltas[i] = get_pooled_int(rc_after - rc_before)
            alloc_deltas[i] = get_pooled_int(alloc_after - alloc_before)
            fd_deltas[i] = get_pooled_int(fd_after - fd_before)
        alloc_before = alloc_after
        rc_before = rc_after
        fd_before = fd_after

Because of "if i >= nwarmup:", get_pooled_int() isn't call during "warmup", whereas the purpose of the warmup is to warmup *everything*.

Maybe get_pooled_int() allocates one frame object and keeps it alive in its "zombi frame". Maybe something else is allocated and kept alive.

Anything, removing "if i >= nwarmup:" to always compute deltas fix this specific issue.

Attached PR 12744 fix this bug.

[vstinner]

New changeset 5aaac94 by Victor Stinner in branch 'master':
bpo-36560: Fix reference leak hunting in regrtest (GH-12744)
5aaac94

[vstinner]

New changeset 9c14061 by Victor Stinner in branch '2.7':
bpo-36560: Fix reference leak hunting in regrtest (GH-12744) (GH-12745)
9c14061

[vstinner]

New changeset bb44478 by Victor Stinner in branch 'master':
bpo-36560: regrtest: don't collect the GC twice (GH-12747)
bb44478

[vstinner]

_abc was written for optimization. Your PR makes it using slower Python code. Could you please test how much this hits the performance of abc?

I mostly wrote PR 12743 to debug this issue. Please see the discussion directly on the PR ;-)

[vstinner]

New changeset 86f0354 by Victor Stinner in branch '3.7':
[3.7] bpo-36560: regrtest: don't collect the GC twice (GH-12747) (GH-12749)
86f0354