[Zope-dev] Re: Test runner: layers, subprocesses, and tear down

[Marius Gedminas]

On Fri, Jul 04, 2008 at 05:44:12PM -0400, Benji York wrote:
> On Fri, Jul 4, 2008 at 4:49 PM, Marius Gedminas <marius at gedmin.as> wrote:
> > I tried this in a Zope 3.4 checkout I had handy on a Core 2 Duo machine
> > (1.8 GHz, running 64-bit Ubuntu Hardy).  One test module could not be
> > loaded, which explains the slightly lower number of tests reported:
> 
> > Here are the results:
> >
> >                        time                                # tests
> >                        real        user        system      reported
> > old test runner         3m16.033s   2m44.670s   0m2.832s    6895
> > zope.testing trunk      2m27.816s   1m58.971s   0m2.196s    6890
> > new test runner -j0     2m37.322s   2m5.808s    0m2.944s    6890
> > new test runner -j1     2m32.249s   1m58.847s   0m2.652s    6890
> > new test runner -j2     2m22.287s   3m51.214s   0m13.457s   584
> > new test runner -j3     2m20.560s   3m46.990s   0m12.613s   584
> > new test runner -j4     2m30.026s   3m43.198s   0m13.241s   584
> 
> I'm really curious why you didn't see more improvement.

I wish one of the system-wide profilers (oprofile, sysprof) had support
for extracting Python tracebacks out of C-level stack frames...

> > Zope 3 appears to be composed of a multitude of small tests.  If my
> > numbers are correct, the advantage of using both CPU cores is almost
> > completely negated by the extra bookkeeping that the test runner has to
> > do.
> 
> There's no appreciable bookkeeping for the parallelization, so I don't
> know where the CPU time is going.

Every layer is spawned in a separate subprocess, right?  That means 36
new Python processes with the associated startup cost, plus the module
import cost, plus some test result marshalling through plain-text Unix
pipes.  Two seconds of startup cost per subprocess would nicely account
for the one extra minute of user time if there are over 30 subprocesses.

My crude measurements (time ./test.py --list-tests > /dev/null) indicate
the time needed to import everything is closer to 4 seconds, but that's
importing everything -- importing just the things needed for a single
layer may reduce that to two seconds on average.

> > "Test-module import failures" is printed several times.  test -j4
> > printed that message 37 times!  test -j1 only did it once.  -j2 and -j3
> > also did that a bit often (once per layer?)
> 
> Interesting.  I'll investigate.

It corroborates my theory that each subprocess imports all the test
modules.

Marius Gedminas
-- 
H.323 has much in common with other ITU-T standards - it features a complex
binary wire protocol, a nightmarish implementation, and a bulk that can be used
to fell medium-to-large predatory animals.
        -- Anthony Baxter
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 191 bytes
Desc: Digital signature
Url : http://mail.zope.org/pipermail/zope-dev/attachments/20080705/6d8847ec/attachment.bin