Merge lp:~gz/bzr/use_testtools_timings_625594 into lp:bzr

Proposed by Martin Packman on 2010-09-27
Status: Merged
Approved by: Vincent Ladeuil on 2010-10-07
Approved revision: 5446
Merged at revision: 5467
Proposed branch: lp:~gz/bzr/use_testtools_timings_625594
Merge into: lp:bzr
Diff against target: 48 lines (+18/-2)
2 files modified
bzrlib/tests/ (+3/-2)
bzrlib/tests/ (+15/-0)
To merge this branch: bzr merge lp:~gz/bzr/use_testtools_timings_625594
Reviewer Review Type Date Requested Status
Vincent Ladeuil 2010-09-27 Approve on 2010-09-29
Review via email:

Commit message

Use testtools timing mechanisms.

Description of the change

The bzr half of the fix for bug 625594, see <lp:~gz/testtools/result_timings_forwarding_625594> for the testtools part.

Simply switches the test timing mechanism to use the api testtools provides, which enables the adaptation of subunit timestamp streams to work for bzr selftest as well without further changes.

There are some downsides here, we switch from tracking nice simple unix timestamps to datetime instances, which are harder to work with and also prevents switching to time.clock on windows for higher than 60Hz tick rate.

To post a comment you must log in.
Martin Packman (gz) wrote :

There's a run that vila launched on babune with this change and the testtools change with a subset of the tests:

Has some interesting things you can drill down to from the grouped timings, for instance, of the 10 seconds it takes to run bt.test_workingtree_4 on gentoo:
There are 4 seconds each in test_commit_updates_hash_cache and test_observed_sha1_cachable (they sleep).

Also useful for comparing the different platforms on the same suite or test.

Vincent Ladeuil (vila) wrote :

Sounds good to me.

I'm curious to see if it pqm will accept it giving the relationship with testtools but if it lands, let's do that. (We are still waiting for testtools-0.9.6 to be deployed there anyway).

review: Approve
Vincent Ladeuil (vila) wrote :


babune is currently using your testtools change and now display times for tests...

So is *this* patch really needed after all ?

Martin Packman (gz) wrote :

> So is *this* patch really needed after all ?

It's needed for normal use with `bzr selftest -v` on the terminal, I'd forgotten that babune says subunit all the way through to the output formatting so (apart from the test added here failing) isn't affected by this change.

I'm pretty confident this will pass PQM, the blame on the testtools code this is depending on is from the end of 2009 so predates 0.9.2 which is our current min version.

Martin Packman (gz) wrote :

...that was unclear, I'll try again. The code change here has no effect on babune beyond making the test added pass, whereas it would fail without it.

Vincent Ladeuil (vila) wrote :

sent to pqm by email

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'bzrlib/tests/'
2--- bzrlib/tests/ 2010-09-27 19:31:45 +0000
3+++ bzrlib/tests/ 2010-09-27 20:29:40 +0000
4@@ -260,7 +260,8 @@
6 def _elapsedTestTimeString(self):
7 """Return a time string for the overall time the current test has taken."""
8- return self._formatTime(time.time() - self._start_time)
9+ return self._formatTime(self._delta_to_float(
10+ self._now() - self._start_datetime))
12 def _testTimeString(self, testCase):
13 benchmark_time = self._extractBenchmarkTime(testCase)
14@@ -315,7 +316,7 @@
16 def _recordTestStartTime(self):
17 """Record that a test has started."""
18- self._start_time = time.time()
19+ self._start_datetime = self._now()
21 def addError(self, test, err):
22 """Tell result that test finished with an error.
24=== modified file 'bzrlib/tests/'
25--- bzrlib/tests/ 2010-09-27 19:31:45 +0000
26+++ bzrlib/tests/ 2010-09-27 20:29:40 +0000
27@@ -849,6 +849,21 @@
28 self.assertContainsRe(output,
29 r"LSProf output for <type 'unicode'>\(\('world',\), {'errors': 'replace'}\)\n")
31+ def test_uses_time_from_testtools(self):
32+ """Test case timings in verbose results should use testtools times"""
33+ import datetime
34+ class TimeAddedVerboseTestResult(tests.VerboseTestResult):
35+ def startTest(self, test):
36+ self.time(datetime.datetime.utcfromtimestamp(1.145))
37+ super(TimeAddedVerboseTestResult, self).startTest(test)
38+ def addSuccess(self, test):
39+ self.time(datetime.datetime.utcfromtimestamp(51.147))
40+ super(TimeAddedVerboseTestResult, self).addSuccess(test)
41+ def report_tests_starting(self): pass
42+ sio = StringIO()
43+ self.get_passing_test().run(TimeAddedVerboseTestResult(sio, 0, 2))
44+ self.assertEndsWith(sio.getvalue(), "OK 50002ms\n")
46 def test_known_failure(self):
47 """A KnownFailure being raised should trigger several result actions."""
48 class InstrumentedTestResult(tests.ExtendedTestResult):