'testr run' gives incorrect time deltas

[Jonathan Lange]

jml@grace:~/src/testrepository$ testr run
running=${PYTHON:-python} -m subunit.run testrepository.tests.test_suite
Ran 264 tests in 1.520s (-0.219s)
PASSED (id=14)
jml@grace:~/src/testrepository$ testr run
running=${PYTHON:-python} -m subunit.run testrepository.tests.test_suite
Ran 264 tests in 1.547s (-0.087s)
PASSED (id=15)
jml@grace:~/src/testrepository$ testr run
running=${PYTHON:-python} -m subunit.run testrepository.tests.test_suite
Ran 264 tests in 1.622s (-0.039s)
PASSED (id=16)

Times are: 1.520s, 1.547s, 1.622s
Deltas should be: +0.027s, +0.075s
Deltas instead are: -0.087s, -0.039s

[Robert Collins (lifeless)]

This is an interesting one; looks like near constant overhead inflating the baseline. I wonder if its inter-test processing time or something.

[Jonathan Lange (jml)]

I haven't drilled down into the root cause, but if we don't wrap the inserter in AutoTimingTestResultDecorator then we get correct times.

$ bzr di
=== modified file 'testrepository/repository/__init__.py'
--- testrepository/repository/__init__.py 2011-11-17 15:45:10 +0000
+++ testrepository/repository/__init__.py 2012-04-30 11:44:57 +0000
@@ -81,8 +81,7 @@ class AbstractRepository(object):
             that testtools 0.9.2 and above offer. The startTestRun and
             stopTestRun methods in particular must be called.
         """
- return subunit.test_results.AutoTimingTestResultDecorator(
- self._get_inserter(partial))
+ return self._get_inserter(partial)

     def _get_inserter(self):
         """Get an inserter for get_inserter.

=== modified file 'testrepository/tests/commands/test_last.py'
--- testrepository/tests/commands/test_last.py 2011-11-03 20:41:47 +0000
+++ testrepository/tests/commands/test_last.py 2012-04-30 11:44:57 +0000
@@ -48,7 +48,7 @@ class TestCommand(ResourcedTestCase):
         # We should have seen test outputs (of the failure) and summary data.
         self.assertEqual([
             ('results', Wildcard),
- ('summary', False, 2, 0, Wildcard, 0.0,
+ ('summary', False, 2, 0, Wildcard, None,
              [('id', id, None), ('failures', 1, 0)])],
             ui.outputs)
         suite = ui.outputs[0][1]

=== modified file 'testrepository/tests/test_repository.py'
--- testrepository/tests/test_repository.py 2011-11-17 15:45:10 +0000
+++ testrepository/tests/test_repository.py 2012-04-30 11:44:57 +0000
@@ -333,8 +333,7 @@ class TestRepositoryContract(ResourcedTe
         run.get_test().run(result)
         self.assertEqual(
             result._events,
- [('time', Wildcard), # XXX: Auto-timer inserts clock time
- ('time', now),
+ [('time', now),
              ('startTest', Wildcard),
              ('time', now + 1 * second),
              ('addSuccess', Wildcard),

$ ./testr run
running=${PYTHON:-python} -m subunit.run testrepository.tests.test_suite
Ran 270 tests in 1.433s (-0.060s)
PASSED (id=157)

$ ./testr run
running=${PYTHON:-python} -m subunit.run testrepository.tests.test_suite
Ran 270 tests in 1.483s (+0.050s)
PASSED (id=158)

$ ./testr run
running=${PYTHON:-python} -m subunit.run testrepository.tests.test_suite
Ran 270 tests in 1.491s (+0.008s)
PASSED (id=159)

Note that 1.491s = 1.483s + 0.008s and 1.483s = 1.433s + 0.050s. i.e. that the time delta is correct.

[Robert Collins (lifeless)]

So that suggests something is broken in the auto timing result decorator.

Separately, we're doing our auto timing *after* the concurrenttestsuite step, which means we're batching any auto-timing data we add.

=== modified file 'testrepository/commands/load.py'
--- testrepository/commands/load.py 2012-05-01 11:27:07 +0000
+++ testrepository/commands/load.py 2012-09-09 06:20:17 +0000
@@ -16,7 +16,7 @@

 import optparse

-import subunit
+import subunit.test_results
 from testtools import ConcurrentTestSuite, MultiTestResult, Tagger

 from testrepository.commands import Command
@@ -28,7 +28,8 @@
     worker_id = 'worker-%s' % thread_number
     tags_to_add = set([worker_id])
     tags_to_remove = set()
- return Tagger(result, tags_to_add, tags_to_remove)
+ return subunit.test_results.AutoTimingTestResultDecorator(
+ Tagger(result, tags_to_add, tags_to_remove))

 class load(Command):

fixes that, I think. I haven't written a test, because timing tests are hard, and timing tests of concurrent streams are even harder. Perhaps I should. For now, I'm going to file a separate bug about the batching issue.

[Robert Collins (lifeless)]

Here is an interesting experiment:
./testr run --subunit > sample-log
cat sample-log | ./testr load
running=${PYTHON:-python} -m subunit.run testrepository.tests.test_suite
Ran 274 tests in 1.416s (-0.121s)
PASSED (id=34)

cat sample-log | ./testr load
running=${PYTHON:-python} -m subunit.run testrepository.tests.test_suite
Ran 274 tests in 1.416s (+9.882s)
PASSED (id=35)

cat sample-log | ./testr load
running=${PYTHON:-python} -m subunit.run testrepository.tests.test_suite
Ran 274 tests in 1.416s (+11.651s)
PASSED (id=36)

cat sample-log | ./testr load
running=${PYTHON:-python} -m subunit.run testrepository.tests.test_suite
Ran 274 tests in 1.416s (+12.920s)
PASSED (id=37)

cat sample-log | ./testr load --subunit > sample-log2

diff sample-log sample-log2
472c472
< time: 2012-09-09 06:22:37.126431Z
---
> time: 2012-09-09 06:22:37.126430Z

Thats explainable by floating point error.

One possibility is a UI glitch - rather than taking the first timestamp from the run, its taking now(), which is clearly a source of error, and would explain the constant offset issue as well.

We have a similar issue when we look at last, the timing data there seems to be sum of durations, not max time - min time.

[Robert Collins (lifeless)]

The cause of the skew is this: the AutoTiming decorator was outputing a now() time at the first event (startTestRun), which happened $timetostartrealrun ahead, but the timing data was being gathered from the stream, which led to the skew.