Comment 2 for bug 625594

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 8/27/2010 6:40 PM, Martin [gz] wrote:
> Public bug reported:
>
> Individual test timings appear to be completely off when selftest is run
> across multiple processes.
>
> Running two reasonably slow tests:
>
> blackbox.test_log.TestLogTags.test_log_with_tags OK 483ms
> blackbox.test_log.TestLogTags.test_merged_log_with_tags OK 468ms
> ----------------------------------------------------------------------
> Ran 2 tests in 1.000s
>
> But with --parallel=subprocess (and BZR_CONCURRENCY=2):
>
> blackbox.test_log.TestLogTags.test_log_with_tags OK 0ms
> blackbox.test_log.TestLogTags.test_merged_log_with_tags OK 0ms
> ----------------------------------------------------------------------
> Ran 2 tests in 3.531s
>
> The timer is doing *something* as occasionally it thinks a test takes
> 15ms rather than 0ms, but clearly this is not actually timing how long
> the test is taking.

On many Windows platforms the 'time.time()' resolution is 15ms. Which is
why you could see it fluctuate from 0 to 15ms, but not something small
like 1-2ms.

That said, there certainly seems to be something odd going on for it to
be succeeding that quickly.

Offhand... subunit seems to take the last 'time' statement as the start
of this test. Maybe when it is joining up the child streams, it
intermingles the 'time' commands?

For example, imagine in a regular run:

time 1
test a
time 2

time 3
test b
time 4

however, when running with forking or parallel you end up with:
time 1a
time 1b
test a
time 2a
test b
time 2b

And 2b - 2a is very fast.

Note also that --subunit only streams clock times. It doesn't send out
delta times, etc.
John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkx7298ACgkQJdeBCYSNAANNLwCgxKoggqz6sjIsqtMKC+wjQnSY
2NYAnRZXYAumzbIUIoHsGjUGoX4QRpAx
=DnRI
-----END PGP SIGNATURE-----