Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

new option gc-after-test #133

Merged
merged 13 commits into from
Jun 3, 2022
Merged

new option gc-after-test #133

merged 13 commits into from
Jun 3, 2022

Conversation

d-maurer
Copy link
Contributor

to analyze ResourceWarnings and the creation of cyclic garbage.

Fixes #131.

The PR introduces the option gc-after-test. Its setting causes gc.collect to be called after each test and its return value to be recorded. If the return value rv is nonzero, ! is output on verbosity level 1 and [rv] on verbosity levels above 1. This makes it easy to detect whether a test has created cyclic garbage.

gc-after-test can also help in the analysis of the ResourceWarnings not raised locally but only as a side effect of garbage collection. Having gc.collect called after each test allows to associate a ResourceWarning which the test responsible for the warning; otherwise, it may not be reported at all or reported in the context of a different test (when garbage collection happens to be activated).

@d-maurer
Copy link
Contributor Author

The option does not work with Jython (apparently, its gc is only a dummy).

On PyPy, gc.collect returns None (rather than the number of collected objects). Therefore, the option cannot by used to analyze the creation of cyclic garbage.

@jugmac00
Copy link
Member

I am pretty packed this week, but still I had quick look yesterday night.

Back then when I ran tox on all zopefoundation projects, I found quite some with resource warnings.

So I picked this one to zopefoundation/zc.recipe.deployment#8 to test drive your changes.

But I was a bit surprised when I ran the current version of zope.testrunner and finding this output:

❯ tox -e py39 
py39 create: /home/jugmac00/Projects/zc.recipe.deployment/.tox/py39
py39 develop-inst: /home/jugmac00/Projects/zc.recipe.deployment
py39 installed: six==1.16.0,zc.buildout==2.13.7,-e git+ssh://git@github.com/zopefoundation/zc.recipe.deployment.git@3740c47405eff4fa646ec9e90c2d53809b47d2b9#egg=zc.recipe.deployment,zope.exceptions==4.5,zope.interface==5.4.0,zope.testing==4.10,zope.testrunner==5.4.0
py39 run-test-pre: PYTHONHASHSEED='1743485114'
py39 run-test: commands[0] | zope-testrunner --test-path=src -vc
Running tests at level 1
Running zope.testrunner.layer.UnitTests tests:
  Set up zope.testrunner.layer.UnitTests in 0.000 seconds.
  Running:
..<doctest README.txt[94]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='/tmp/tmp0vbma65bbuildoutSetUp/_TEST_/sample-buildout/etc/cron.d/foo-cron' mode='r' encoding='UTF-8'>
  open(os.path.join(sample_buildout, 'etc/cron.d/foo-cron')).read()
ResourceWarning: Enable tracemalloc to get the object allocation traceback
<doctest README.txt[97]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='/tmp/tmp0vbma65bbuildoutSetUp/_TEST_/sample-buildout/etc/cron.d/bar-cron' mode='r' encoding='UTF-8'>
  open(os.path.join(sample_buildout, 'etc/cron.d/bar-cron')).read()
ResourceWarning: Enable tracemalloc to get the object allocation traceback
<doctest README.txt[100]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='etc/cron.d/bar-cron' mode='r' encoding='UTF-8'>
  open('etc/cron.d/bar-cron').read()
ResourceWarning: Enable tracemalloc to get the object allocation traceback
<doctest README.txt[101]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='.installed.cfg' mode='r' encoding='UTF-8'>
  installed = [l for l in open('.installed.cfg')
ResourceWarning: Enable tracemalloc to get the object allocation traceback
<doctest README.txt[102]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='.installed.cfg' mode='w' encoding='UTF-8'>
  _ = open('.installed.cfg', 'w').write(''.join(installed))
ResourceWarning: Enable tracemalloc to get the object allocation traceback
<doctest README.txt[109]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='y.cfg' mode='w' encoding='UTF-8'>
  _ = open('y.cfg', 'w').write(
ResourceWarning: Enable tracemalloc to get the object allocation traceback
<doctest README.txt[112]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='y.cfg' mode='r' encoding='UTF-8'>
  print_(open('y.cfg', 'r').read())
ResourceWarning: Enable tracemalloc to get the object allocation traceback
<doctest README.txt[115]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='y.cfg' mode='a' encoding='UTF-8'>
  _ = open('y.cfg', 'a').write(
ResourceWarning: Enable tracemalloc to get the object allocation traceback
<doctest README.txt[124]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='/tmp/tmp0vbma65bbuildoutSetUp/_TEST_/sample-buildout/etc/z.cfg' mode='r' encoding='UTF-8'>
  print_(open(join(sample_buildout, 'etc', 'z.cfg'), 'r').read())
ResourceWarning: Enable tracemalloc to get the object allocation traceback
<doctest README.txt[130]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='anotherconfig.cfg' mode='w' encoding='UTF-8'>
  _ = open('anotherconfig.cfg', 'w').write('one')
ResourceWarning: Enable tracemalloc to get the object allocation traceback
<doctest README.txt[133]>:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='anotherconfig.cfg' mode='r' encoding='UTF-8'>
  print_(open('anotherconfig.cfg').read())
ResourceWarning: Enable tracemalloc to get the object allocation traceback

  Ran 2 tests with 0 failures, 0 errors, 0 skipped in 13.501 seconds.
Tearing down left over layers:
  Tear down zope.testrunner.layer.UnitTests in 0.000 seconds.
________________________________________________________________________ summary _________________________________________________________________________
  py39: commands succeeded
  congratulations :)

So it looks like that resource warnings are already decently shown even before applying your PR.

I then installed your changes:

❯ .tox/py39/bin/pip install git+https://github.com/zopefoundation/zope.testrunner@132c98abff1be3f569e561527851b12c19da084e

and ran

❯ tox -e py39 -- --gc-after-test

and there was no difference in output (except for paths for the tmp files).

Screenshot from 2022-04-26 08-04-27

So this was a "black box test" - without reading the implementation.

I'll have a look at the implementation on the weekend.

@icemac
Copy link
Member

icemac commented May 25, 2022

@jugmac00 Did you find the time to look into this PR?

@d-maurer
Copy link
Contributor Author

d-maurer commented May 25, 2022 via email

@jugmac00
Copy link
Member

@jugmac00 Did you find the time to look into this PR?

I am afraid no. Both private and work life are currently super busy.

@d-maurer Could you give us a clearer scope of this PR?

In your first comment you mention that the new option helps to analyze resource warnings, but as seen in my comment, resource warnings are already very well visible with the current state.

@d-maurer
Copy link
Contributor Author

d-maurer commented May 25, 2022 via email

@d-maurer
Copy link
Contributor Author

@jugmac00 To visualize the effect of --gc-after-test (regarding ResourceWarnings), I have created 2 log file wo.log and wi.log with:

zope-testrunner --path src/zope/testrunner/tests/testrunner-ex --tests-pattern gc-after-test -vv >~/tmp/wo.log 2>&1
zope-testrunner --path src/zope/testrunner/tests/testrunner-ex --tests-pattern gc-after-test -vv --gc-after-test >~/tmp/wi.log 2>&1

i.e. wo.log contains the output without --gc-after-test, wi.log that with this option.
The difference:

--- /home/dieter/tmp/wo.log	2022-05-31 08:17:19.263474317 +0200
+++ /home/dieter/tmp/wi.log	2022-05-31 08:20:13.237727483 +0200
@@ -2,8 +2,10 @@
 Running zope.testrunner.layer.UnitTests tests:
   Set up zope.testrunner.layer.UnitTests in 0.000 seconds.
   Running:
- test_cycle_with_resource (gc-after-test.GcAfterTestTests)
- test_cycle_without_resource (gc-after-test.GcAfterTestTests)
+ test_cycle_with_resource (gc-after-test.GcAfterTestTests)zope/testrunner/tests/testrunner-ex/gc-after-test.py:60: ResourceWarning: not closed
+  warn(ResourceWarning("not closed"))
+ [3]
+ test_cycle_without_resource (gc-after-test.GcAfterTestTests) [2]
  test_exception (gc-after-test.GcAfterTestTests)
 
 Error in test test_exception (gc-after-test.GcAfterTestTests)
@@ -35,11 +37,9 @@
 
 
  test_okay (gc-after-test.GcAfterTestTests)
- test_test_holds_cycle (gc-after-test.GcAfterTestTests)
- test_traceback_cycle (gc-after-test.GcAfterTestTests)
-zope/testrunner/tests/testrunner-ex/gc-after-test.py:60: ResourceWarning: not closed
-  warn(ResourceWarning("not closed"))
-  Ran 7 tests with 1 failures, 1 errors and 0 skipped in 0.001 seconds.
+ test_test_holds_cycle (gc-after-test.GcAfterTestTests) [3]
+ test_traceback_cycle (gc-after-test.GcAfterTestTests) [7]
+  Ran 7 tests with 1 failures, 1 errors and 0 skipped in 0.100 seconds.
 Tearing down left over layers:
   Tear down zope.testrunner.layer.UnitTests in 0.000 seconds.

This shows: with gc-after-test, we see that the test test_cycle_with_resource was responsible for the ResourceWaning. Without the option, the warning is reported at the end of the test run -- without indication which test has been responsible.

@d-maurer
Copy link
Contributor Author

Example for the new feature to analyze cyclic garbage: -vvvv --gc-after-test

(py39) zope-testrunner --test-path ../ZEO/src -vvvv --gc-after-test -t vote
Running tests at level 1
Running zope.testrunner.layer.UnitTests tests:
  Set up zope.testrunner.layer.UnitTests in 0.000 seconds.
  Running:
 errors_in_vote_should_clear_lock (ZEO.tests.testZEO2) (0.008 s) [208]
The following test left cyclic garbage behind:
errors_in_vote_should_clear_lock (ZEO.tests.testZEO2)
Cycle 1
 *  (<class 'ZEO.tests.testZEO2.MappingStorage'>, <class 'type'>)
 *  {'__name__': 'ZEO.tests.testZEO2.MappingStorage',
    'inherit': <class 'ZEO.tests.testZEO2.MappingStorage'>}
 *  {<InterfaceClass ZODB.interfaces.IStorage>: (),
    <InterfaceClass ZODB.interfaces.IStorageIteration>: (),
    <InterfaceClass zope.interface.Interface>: (),
    classImplements(MappingStorage): (),
    classImplements(MappingStorage, IStorage, IStorageIteration): (),
   ...
 *  (classImplements(MappingStorage),
    classImplements(MappingStorage, IStorage, IStorageIteration),
    <InterfaceClass ZODB.interfaces.IStorage>,
    <InterfaceClass ZODB.interfaces.IStorageIteration>,
    classImplements(object),
   ...
 *  classImplements(MappingStorage)
 *  {directlyProvides(MappingStorage): (),
    <InterfaceClass zope.interface.Interface>: (),
    classImplements(object): (),
    classImplements(type): ()}
 *  (directlyProvides(MappingStorage),
    classImplements(type),
    classImplements(object),
    <InterfaceClass zope.interface.Interface>)
 *  directlyProvides(MappingStorage)
 *  {'__doc__': None,
    '__implemented__': classImplements(MappingStorage),
    '__module__': 'ZEO.tests.testZEO2',
    '__provides__': directlyProvides(MappingStorage),
    'tpc_vote': <function MappingStorage.tpc_vote at 0x7f644b9dd9d0>}
 *  (<class 'ZEO.tests.testZEO2.MappingStorage'>,
    <class 'ZODB.MappingStorage.MappingStorage'>,
    <class 'object'>)
 *  <class 'ZEO.tests.testZEO2.MappingStorage'>
Cycle 2
 *  <bound method ServerProtocol.async_ of ZEO.asyncio.server.ServerProtocol...
 *  <bound method ServerProtocol.call_soon_threadsafe of ZEO.asyncio.server....
 *  <Future finished result=True created at /home/dieter/tmp/ZEO/src/ZEO/asy...
 *  {'addrs': (),
    'connecting': {},
    'exceptions': [],
    'get_debug': <function Loop.__init__.<locals>.<lambda> at 0x7f6449d64d30>,
    'later': [],
   ...
 *  <ZEO.asyncio.testing.Loop object at 0x7f64495ce940>
 *  <class 'dict'> instance at 0x7f6449619740
 *  ZEO.asyncio.server.ServerProtocol('test-addr-1')
 *  <bound method ServerProtocol.async_threadsafe of ZEO.asyncio.server.Serv...
 *  {'1': <ZEO.monitor.StorageStats object at 0x7f64495cee20>}
 *  {'1': <ZEO.StorageServer.LockManager object at 0x7f64495ceaf0>}
 *  <class 'dict'> instance at 0x7f644b9ea600
 *  <bound method Acceptor.factory of <ZEO.asyncio.server.Acceptor object at...
 *  {'_active_count': 0,
    '_backlog': 100,
    '_loop': <_UnixSelectorEventLoop running=False closed=True debug=False>,
    '_protocol_factory': <bound method Acceptor.factory of <ZEO.asyncio.ser...
    '_serving': False,
   ...
 *  <Server sockets=()>
 *  {'addr': 'x',
    'closed': True,
    'event_loop': <_UnixSelectorEventLoop running=False closed=True debug=F...
    'msgpack': False,
    'server': <Server sockets=()>,
   ...
 *  <ZEO.asyncio.server.Acceptor object at 0x7f64495ceac0>
 *  <bound method Acceptor.loop of <ZEO.asyncio.server.Acceptor object at 0x...
 *  <class 'dict'> instance at 0x7f644b9ee900
 *  <ZEO.tests.servertesting.StorageServer object at 0x7f64495c64f0>
 *  <class 'list'> instance at 0x7f644a1d5a40
 *  <class 'dict'> instance at 0x7f644b9eac40
 *  <ZEO.monitor.StorageStats object at 0x7f64495cee20>
 *  {'_lock': <unlocked _thread.RLock object owner=0 count=0 at 0x7f64495cea...
    'locked': None,
    'stats': <ZEO.monitor.StorageStats object at 0x7f64495cee20>,
    'storage_id': '1',
    'timeout': <ZEO.StorageServer.StubTimeoutThread object at 0x7f64495ceee0>,
   ...
 *  <ZEO.StorageServer.LockManager object at 0x7f64495ceaf0>
 *  {'_iterator_ids': count(0),
    '_iterators': {},
    '_txn_iterators_last': {},
    'async_': <bound method ServerProtocol.async_ of ZEO.asyncio.server.Ser...
    'async_threadsafe': <bound method ServerProtocol.async_threadsafe of ZE...
   ...
 *  <class 'ZEO.StorageServer.ZEOStorage'> instance at 0x7f64495c6d00
Cycle 3
 *  <frame at 0x7f6449069520, file '<doctest ZEO.tests.testZEO2.errors_in_vo...
 *  <traceback object at 0x7f64526490c0>
 *  <frame at 0x555f467e66d0, file '/home/dieter/tmp/ZEO/src/ZEO/StorageServ...
 *  <traceback object at 0x7f644953bf40>
 *  <traceback object at 0x7f644953bf80>
 *  <traceback object at 0x7f644953b5c0>
 *  <traceback object at 0x7f644953b700>
 *  ValueError()
 *  (<class 'ValueError'>, ValueError(), <traceback object at 0x7f644953b700>)
 *  {'BOOM': 2,
    'FAILURE': 1,
    'SUCCESS': 0,
    'check': <bound method OutputChecker.check_output of <zope.testing.reno...
    'compileflags': 1048576,
   ...
 *  <frame at 0x555f46b51100, file '/usr/local/lib/python3.9/doctest.py', li...
 *  <frame at 0x7f6449069040, file '<doctest ZEO.tests.testZEO2.errors_in_vo...
 *  <frame at 0x7f6449063c10, file '/home/dieter/tmp/ZEO/src/ZEO/StorageServ...
 *  <frame at 0x7f6449600800, file '/home/dieter/tmp/ZEO/src/ZEO/StorageServ...
 *  <traceback object at 0x7f6449598600>
  Ran 1 tests with 0 failures, 0 errors and 0 skipped in 0.050 seconds.
Tearing down left over layers:
  Tear down zope.testrunner.layer.UnitTests in 0.000 seconds.

The test left 208 garbage objects in 3 cycles.
Cycle 1 is caused by zope.interface.alsoProvides, cycle 2 by the ZEO implementation and cycle 3 by the test.

@d-maurer d-maurer merged commit 88d1685 into master Jun 3, 2022
@d-maurer d-maurer deleted the gc-after-test#131 branch June 3, 2022 06:17
navytux pushed a commit to zopefoundation/ZEO that referenced this pull request Aug 2, 2022
The commit target and cyclic garbage created during tests. For the analysis, a `zope.testrunner` enhancement ("zopefoundation/zope.testrunner#133") has been important.

...

I believe that the ZEO implementation no longer creates cyclic garbage of its own. However, most tests still produce cyclic garbage. The analysis found 3 causes:
1. Python 3 (at least) creates a reference cycle for each class definition (between the class and its `mro'). This means that (most) local class definitions result in cyclic garbage. `unittest.mock` (prominently used by some tests) makes extensive use of local class definitions.
2. `asyncio` (at least in Python 3.9) can create cyclic garbage
3. `zope.interface` can create cyclic garbage in its implementation of `alsoProvides`

The cyclic garbage collector can free the cyclic structures; thus, there is no serious problem.

Extracted from #195
More details at: #195 (comment)
navytux pushed a commit to zopefoundation/ZEO that referenced this pull request Aug 2, 2022
The commit target and cyclic garbage created during tests. For the analysis, a `zope.testrunner` enhancement ("zopefoundation/zope.testrunner#133") has been important.

...

I believe that the ZEO implementation no longer creates cyclic garbage of its own. However, most tests still produce cyclic garbage. The analysis found 3 causes:
1. Python 3 (at least) creates a reference cycle for each class definition (between the class and its `mro'). This means that (most) local class definitions result in cyclic garbage. `unittest.mock` (prominently used by some tests) makes extensive use of local class definitions.
2. `asyncio` (at least in Python 3.9) can create cyclic garbage
3. `zope.interface` can create cyclic garbage in its implementation of `alsoProvides`

The cyclic garbage collector can free the cyclic structures; thus, there is no serious problem.

Extracted from #195
More details at: #195 (comment)
@d-maurer
Copy link
Contributor Author

d-maurer commented Oct 11, 2022 via email

navytux pushed a commit to zopefoundation/ZEO that referenced this pull request Dec 22, 2022
The commit target and cyclic garbage created during tests. For the analysis, a `zope.testrunner` enhancement ("zopefoundation/zope.testrunner#133") has been important.

...

I believe that the ZEO implementation no longer creates cyclic garbage of its own. However, most tests still produce cyclic garbage. The analysis found 3 causes:
1. Python 3 (at least) creates a reference cycle for each class definition (between the class and its `mro'). This means that (most) local class definitions result in cyclic garbage. `unittest.mock` (prominently used by some tests) makes extensive use of local class definitions.
2. `asyncio` (at least in Python 3.9) can create cyclic garbage
3. `zope.interface` can create cyclic garbage in its implementation of `alsoProvides`

The cyclic garbage collector can free the cyclic structures; thus, there is no serious problem.

Extracted from #195
More details at: #195 (comment)
navytux pushed a commit to zopefoundation/ZEO that referenced this pull request Dec 30, 2022
The commit target and cyclic garbage created during tests. For the analysis, a `zope.testrunner` enhancement ("zopefoundation/zope.testrunner#133") has been important.

...

I believe that the ZEO implementation no longer creates cyclic garbage of its own. However, most tests still produce cyclic garbage. The analysis found 3 causes:
1. Python 3 (at least) creates a reference cycle for each class definition (between the class and its `mro'). This means that (most) local class definitions result in cyclic garbage. `unittest.mock` (prominently used by some tests) makes extensive use of local class definitions.
2. `asyncio` (at least in Python 3.9) can create cyclic garbage
3. `zope.interface` can create cyclic garbage in its implementation of `alsoProvides`

The cyclic garbage collector can free the cyclic structures; thus, there is no serious problem.

Extracted from #195
More details at: #195 (comment)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Improve localizing ResourceWarnings
3 participants