Clear caches after every test

[serhiy-storchaka]

BPO	23839
Nosy	@rhettinger, @pitrou, @vstinner, @rbtcollins, @ezio-melotti, @voidspace, @vadmium, @serhiy-storchaka
PRs	[Do Not Merge] Convert Misc/NEWS so that it is managed by towncrier #552
Files	regrtest_clear_caches.patch regrtest_clear_caches_2.patch regrtest_clear_caches_3.patch

^{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 = 'https://github.com/serhiy-storchaka'
closed_at = <Date 2016-11-11.12:51:26.462>
created_at = <Date 2015-04-01.11:30:41.807>
labels = ['3.7', 'tests', 'performance']
title = 'Clear caches after every test'
updated_at = <Date 2017-03-31.16:36:37.509>
user = 'https://github.com/serhiy-storchaka'

bugs.python.org fields:

activity = <Date 2017-03-31.16:36:37.509>
actor = 'dstufft'
assignee = 'serhiy.storchaka'
closed = True
closed_date = <Date 2016-11-11.12:51:26.462>
closer = 'serhiy.storchaka'
components = ['Tests']
creation = <Date 2015-04-01.11:30:41.807>
creator = 'serhiy.storchaka'
dependencies = []
files = ['38804', '45413', '45419']
hgrepos = []
issue_num = 23839
keywords = ['patch']
message_count = 17.0
messages = ['239782', '239791', '239794', '239796', '239799', '239844', '239845', '239898', '249038', '249287', '249288', '280433', '280562', '280571', '280579', '280725', '280768']
nosy_count = 9.0
nosy_names = ['rhettinger', 'pitrou', 'vstinner', 'rbcollins', 'ezio.melotti', 'michael.foord', 'python-dev', 'martin.panter', 'serhiy.storchaka']
pr_nums = ['552']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'resource usage'
url = 'https://bugs.python.org/issue23839'
versions = ['Python 2.7', 'Python 3.5', 'Python 3.6', 'Python 3.7']

[serhiy-storchaka]

Some caches can grow unlimitedly during running the testsuite (in particular linecache). On some machines with limited resources this can cause multiple MemoryErrors. Many of these MemoryErrors can be avoided if clear caches between tests. Lib/test/regrtest.py already contains a code for cleaning caches, but it is used only with the -R option.

[vstinner]

Maybe tests known to fill caches should clear theirself caches at cleanup? Always clearing all caches may have an impact on performances and so makes tests longer. Caches are designed to speedup Python :-)

We may add some helper functions in test.support for the most common caches, but not to clear *all* caches.

By the way, forcing calls to gc.collect() may make tests more reliable. It would avoid to get warnings 4 lines after the test leaking a resource finished.

But it's not easy to make this reliable, because unittest stores a lot of things. unittest.TestCase.run() stores exceptions which store a traceback which stores frames which store references to local variables. Instead of storing a whole sys.exc_info(), we can maybe use the new light traceback.TracebackException which only stores info required to format a traceback as text, without storing all these heavily objects creating reference cycles.

(Hum, it becomes a little off-topic, sorry, we may open a new separated issue.)

[serhiy-storchaka]

We should try to know how it impacts a performance. I suppose not too much, but may be my intuition lies me.

[vstinner]

By the way, a workaround is also to run each test (file) in a new fresh process. It's a common way to work around memory fragmentation ;-)

On some machines with limited resources this can cause multiple MemoryErrors.

Do you have an idea of the memory usage of the Python test suite? You may run it with tracemalloc to get the memory peak from tracemalloc.get_traced_memory()[1].

I mean, memory is cheap nowadays. If you get MemoryError, it's probably more a bug than tests leaking more and more memory, no?

[serhiy-storchaka]

max_rss is a little larger 500 MB after ran all testsuite (except bigmem tests) on 32-bit Linux. Only few tests needs more than 200 MB. But may be some 64-bit only tests consume more memory. If a test consume more than 1GiB of memory and is not decorated with bigmemtest, it should be considered as a bug.

[rbtcollins]

I'd like to see a definite profile of a bloated stdlib test process before we assume we know the issue - the usual leak I see in test code is used test objects, and I'm not sure we've ported the usual fix for that into unittest yet (we should).

As far as linecache is concerned, we shouldn't be triggering linecache population except when a traceback is actually rendered, and so on a passing test run there should be little hitting it at all outside of tests that actually test rendering of tracebacks.

[rbtcollins]

+1 on moving to the summary classes rather than actual tracebacks in unittest. (Or perhaps even just serialised tracebacks like we do in testtools).

[serhiy-storchaka]

I ran all tests with and without clearing all caches.

Unpatched (without clearing):

real 31m23.694s
user 16m10.340s
sys 2m25.084s

Patched (with clearing):

real 29m28.859s
user 16m19.048s
sys 1m42.184s

There is no significant difference (may be with the patch tests are even faster).

[rbtcollins]

Ok, so this is still in the noise space - it might be useful, it might not. Do we have reports of machines failing to run the test suite (that are also usefully big enough to compile Python and use it)?

[serhiy-storchaka]

http://buildbot.python.org/all/builders/AMD64%20OpenIndiana%203.x/builds/9963/steps/test/logs/stdio

Passed 395 tests of 398 and failed on test_decimal:

...
[396/398] test_decimal
Traceback (most recent call last):
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/regrtest.py", line 1276, in runtest_inner
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/test_decimal.py", line 5598, in test_main
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/support/__init__.py", line 1809, in run_unittest
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/support/__init__.py", line 1775, in _run_suite
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/unittest/runner.py", line 176, in run
    test(result)
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/unittest/suite.py", line 122, in run
    test(result)
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/unittest/suite.py", line 122, in run
    test(result)
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/unittest/case.py", line 645, in __call__
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/unittest/case.py", line 605, in run
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/unittest/case.py", line 538, in _feedErrorsToResult
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/unittest/runner.py", line 69, in addError
    self.stream.writeln("ERROR")
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/unittest/runner.py", line 25, in writeln
    self.write(arg)
MemoryError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/regrtest.py", line 1279, in runtest_inner
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/regrtest.py", line 1232, in __exit__
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/regrtest.py", line 1172, in get_sysconfig__CONFIG_VARS
MemoryError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/regrtest.py", line 532, in main
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/regrtest.py", line 963, in runtest
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/regrtest.py", line 1300, in runtest_inner
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/traceback.py", line 163, in format_exc
    return "".join(format_exception(*sys.exc_info(), limit=limit, chain=chain))
MemoryError
Traceback (most recent call last):
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/runpy.py", line 170, in _run_module_as_main
    "__main__", mod_spec)
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/__main__.py", line 3, in <module>
    regrtest.main_in_temp_cwd()
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/regrtest.py", line 1560, in main_in_temp_cwd
    main()
  File "/export/home/buildbot/64bits/3.x.cea-indiana-amd64/build/Lib/test/regrtest.py", line 738, in main
    raise Exception("Child error on {}: {}".format(test, result[1]))
Exception: Child error on test_decimal:

[serhiy-storchaka]

May be related: http://buildbot.python.org/all/builders/x86%20OpenIndiana%203.x/builds/10375/steps/test/logs/stdio

======================================================================
ERROR: testCount (test.test_socket.SendfileUsingSendfileTest)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_socket.py", line 5160, in testCount
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_socket.py", line 5063, in recv_data
MemoryError

======================================================================
ERROR: testCount (test.test_socket.SendfileUsingSendfileTest)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_socket.py", line 266, in _tearDown
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_socket.py", line 278, in clientRun
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_socket.py", line 5153, in _testCount
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/socket.py", line 282, in _sendfile_use_sendfile
    raise _socket.timeout('timed out')
socket.timeout: timed out

======================================================================
ERROR: testWithTimeout (test.test_socket.SendfileUsingSendfileTest)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_socket.py", line 5230, in testWithTimeout
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_socket.py", line 5063, in recv_data
MemoryError

======================================================================
ERROR: testWithTimeout (test.test_socket.SendfileUsingSendfileTest)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_socket.py", line 266, in _tearDown
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_socket.py", line 278, in clientRun
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_socket.py", line 5225, in _testWithTimeout
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/socket.py", line 282, in _sendfile_use_sendfile
    raise _socket.timeout('timed out')
socket.timeout: timed out

---

[serhiy-storchaka]

Synchronized with current code and added clearing typing caches.

[rhettinger]

LGTM.