[Zope-dev] transience and gc.set_threshold(1)

[Tim Peters]

[Michael Dunstan]
> I'm seeing test failures in transience when running the tests for
> Zope-2_7-branch (python 2.3.3) with garbage collection threshold0 set
> to 1.
> 
> Seems to break in slightly different places from run to run. Here is
> one example:
> 
> % python test.py -vv --dir lib/python/Products/Transience/tests -g 1 "" "testPathological"
> gc threshold: (1, 10, 10)
> Running unit tests at level 1
> Running unit tests from /Zope/lib/python/Products/Transience/tests
> testPathologicalLeftBranching
> (Products.Transience.tests.testTransientObjectContainer.TestTransientObj
> ectContainer) ... ERROR
> testPathologicalRightBranching
> (Products.Transience.tests.testTransientObjectContainer.TestTransientObj
> ectContainer) ... ERROR
> 
> ======================================================================
> ERROR: testPathologicalLeftBranching
> (Products.Transience.tests.testTransientObjectContainer.TestTransientObjectContainer)
> ----------------------------------------------------------------------
> Traceback (most recent call last):
>   File
> "/Zope/lib/python/Products/Transience/tests/
> testTransientObjectContainer.py", line 193, in
> testPathologicalLeftBranching
>     map(self.t.__delitem__, revr)
>   File "/Zope/lib/python/Products/Transience/Transience.py", line 470,
> in __delitem__
>     del bucket[k]
> KeyError: 946
>
> ======================================================================
> ERROR: testPathologicalRightBranching
> (Products.Transience.tests.testTransientObjectContainer.TestTransientObj
> ectContainer)
> ----------------------------------------------------------------------
> Traceback (most recent call last):
>   File
> "/Zope/lib/python/Products/Transience/tests/
> testTransientObjectContainer.py", line 183, in
> testPathologicalRightBranching
>     map(self.t.__delitem__, r)
>   File "/Zope/lib/python/Products/Transience/Transience.py", line 470,
> in __delitem__
>     del bucket[k]
> KeyError: 69
> 
> ----------------------------------------------------------------------
> Ran 2 tests in 4.659s
> 
> FAILED (errors=2)

Whenever I see a test module import fauxtime, I run screaming in
terror.  This seems to be like running the multiprocess ZEO tests
(from which I run screaming daily <wink>):  "depending on" a gazillion
timing accidents you can't control, sometimes they just fail.

I ran the tests above in a loop a few hundred times on my box just
now, with no failures, Python 2.3.4 and command line:

test.py -vvLd -g1 --dir lib/python/Products/Transience/tests . testPathological

There's a big difference between my runs and yours, though:  running
the two tests took about 4.6 seconds on your box, but takes about 1.8
seconds on mine.  Now, for example, if I add

        oldtime.sleep(3)  # approximately 4.6 - 1.8, on the high side

right before

        map(self.t.__delitem__, r)

in testPathologicalRightBranching, then testPathologicalRightBranching
fails every time in a way similar to your reported failure -- and even
without -g1 on the command line.

If I change the sleep to 1.5, then (with -g1 again) sometimes it
passes, sometimes not, depending on how busy the box is doing other
stuff at the same time.

So that's A Problem.  Any test that adds a bunch of stuff to a
TransientObjectContainer and expects to *find* it all there later is
implicitly assuming that the test runs fast enough so that containees
don't vanish before their containedness is checked.  I suspect you're
seeing problems with -g1 here just because -g1 grossly slows the
tests.