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

[Marius Gedminas]

On Fri, Jul 04, 2008 at 11:50:34AM -0400, Benji York wrote:
> On Thu, Jul 3, 2008 at 5:22 PM, Benji York <benji at zope.com> wrote:
> > I'm working on making the zope.testing test runner run tests in
> > parallelized subprocesses.  The option will likely be spelled -j N,
> > where N is the maximum number of processes.
> 
> The branch (svn+ssh://svn.zope.org/repos/main/zope.testing/branches/benji-parallelize-subprocesses)
> is feature complete.  I basically did a very simple transformation that
> resulted in the runner spawning subprocesses in threads, several at a
> time, instead of spawning them serially.  The patch is less than 250
> lines.  Any critiques of the changes would be appreciated.

I'll try to take a look.

> I found that to eliminate nearly all CPU idle time, I had to use -j4 on
> my two core laptop.
> 
> For a particular test corpus on a 4 core machine -j1 (the default) takes
> about 7 minutes -j6 takes about 2 minutes 20 seconds.

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:

    Test-module import failures:

    Module: zope.app.twisted.ftp.tests.test_zopetrial

    Traceback (most recent call last):
      File "/home/mg/src/ivija-zope-3.4/Zope3.4/src/zope/app/twisted/ftp/tests/test_zopetrial.py", line 37, in ?
        orig_configure_logging = zope.testing.testrunner.configure_logging
    AttributeError: 'module' object has no attribute 'configure_logging'

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

At the end of the experiment I discovered that I have CPU frequency
scaling enabled.  It only scales down to 1.6 GHz and quickly jumps back
up to 1.87 GHz.

I find the speedup by switching to a modern test runner somewhat
unexpected.  Can those 5 missing tests really account for 45 seconds?

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.

Visual ogling of my CPU usage applet shows that -j0/1 use only one
CPU, while -j2 and above use only one CPU for the first test layer
(zope.app.apidoc.testing.APIDocLayer) and then use both CPUs for the
rest.  Bug?

The total number of tests is misreported when you have -jN with N > 1.

"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?)

As far as I can understand, the granularity of the test distribution to
CPUs is a test layer?  If so, that's rather unfortunate for my
application, which has only two layers (unit and functional).
Especially given the quirk that the first test layer is run on one CPU
while the other idles.

Marius Gedminas

P.S. Zope 3 is such a sweet little thing!  All the tests finish in 3
minutes!  Heaven.
-- 
The planning fallacy is that people think they can plan, ha ha.
            -- Eliezer Yudkowsky,
               http://www.overcomingbias.com/2007/09/planning-fallac.html
-------------- 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/20080704/b91f4c4c/attachment.bin