our zope.testing fork needs to emit subunit time immediately before test start and immediately before test completion

Bug #1013921 reported by Gary Poster on 2012-06-16
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Launchpad itself
Low
Unassigned

Bug Description

In order to support testr's more advanced parallel test scheduling algorithm (which might save as much as five or six minutes in a test run), our zope.testing fork needs to emit subunit time immediately before test start and immediately before test completion. Without that, we are essentially getting round robin.

Jonathan Lange (jml) wrote :

What timing events are you getting at the moment?

Gary Poster (gary) wrote :

Looks like they are at layer events, though I have a vague belief that the UnitTests layer tests might have even less times than others.

$ ./bin/test --subunit --layer=UnitTest
time: 2012-06-18 13:56:20.612836Z
test: zope.testing.testrunner.layer.UnitTests:setUp
tags: zope:layer
time: 2012-06-18 13:56:20.612841Z
successful: zope.testing.testrunner.layer.UnitTests:setUp
tags: zope:layer:zope.testing.testrunner.layer.UnitTests
test: lp.answers.tests.test_question_notifications.QuestionAddedNotificationTestCase.test_recipient_set
successful: lp.answers.tests.test_question_notifications.QuestionAddedNotificationTestCase.test_recipient_set
...

testr adds timing data itself (using the same decorator). I've just
checked and it looks like it may be adding it at repository
serialisation time (post-muxing of parallel workers) which will lead
to entirely noddy times. So... we may need to move that to the front
of the pipeline within testr (but emitting timestamps at source is a
definitely good idea *anyhow*, so please do do that, these are
separate though related issues).

Gary Poster (gary) wrote :

We've been waiting on this because of some other work, but while reviewing an MP I saw that apparently using -v or -vv with --subunit will do exactly what we want. I'll experiment later, and report back. I'll move the bug to our lpbuildbot config if so.

Gary Poster (gary) wrote :

It's -vvv

Robert Collins (lifeless) wrote :

Huh!. I'd saying timing data if its being generated should always be
included. It is a machine protocol after all.

Gary Poster (gary) wrote :

Unfortunately, it doesn't appear to reduce the (post-LXC-workaround) typical seven or eight minutes of difference between the shortest- and longest-running worker. Moreover, the test counts for each worker are within 3 or 4 of each other.

I don't know if this is because the layer distribution somehow skews something, or because of something I forget that Robert mentioned about how testr merges times incorrectly right now (right?), or Something Else.

Gary Poster (gary) wrote :

I'm moving this to low, to reflect Robert's request that timing data always be included. We don't need this, and I'd rather spend the time elsewhere (like figuring out why the worker times are still so different).

Changed in launchpad:
importance: High → Low
Robert Collins (lifeless) wrote :

On Fri, Jun 22, 2012 at 11:46 AM, Gary Poster <email address hidden> wrote:
> I'm moving this to low, to reflect Robert's request that timing data
> always be included.  We don't need this, and I'd rather spend the time
> elsewhere (like figuring out why the worker times are still so
> different).

Could you run a whole test run of LP, with timing data, without testr
- just write the output somewhere, gz it and attach to the bug. I'll
pull it into testr and check that its not getting mangled by the
import process etc, single threaded or concurrent.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers