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

There is an adapter, AutotimingTestResultDecorator, that will do that for you.

What timing events are you getting at the moment?

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).

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.

It's -vvv

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

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.

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).

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.