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

[Martin Packman]

Use testtools timing mechanisms.

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.

[Martin Packman (gz)]

There's a run that vila launched on babune with this change and the testtools change with a subset of the tests:
<http://babune.ladeuil.net:24842/view/debug/job/selftest-subset-all/93/aggregatedTestReport/>

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:
<http://babune.ladeuil.net:24842/job/selftest-subset-gentoo/75/testReport/bzrlib.tests.test_workingtree_4/TestWorkingTreeFormat4/>
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)]

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

waitaminute

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

So is *this* patch really needed after all ?

[Martin Packman (gz)]

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

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

sent to pqm by email

=== modified file 'bzrlib/tests/__init__.py'
--- bzrlib/tests/__init__.py	2010-09-27 19:31:45 +0000
+++ bzrlib/tests/__init__.py	2010-09-27 20:29:40 +0000
@@ -260,7 +260,8 @@
 
     def _elapsedTestTimeString(self):
         """Return a time string for the overall time the current test has taken."""
-        return self._formatTime(time.time() - self._start_time)
+        return self._formatTime(self._delta_to_float(
+            self._now() - self._start_datetime))
 
     def _testTimeString(self, testCase):
         benchmark_time = self._extractBenchmarkTime(testCase)
@@ -315,7 +316,7 @@
 
     def _recordTestStartTime(self):
         """Record that a test has started."""
-        self._start_time = time.time()
+        self._start_datetime = self._now()
 
     def addError(self, test, err):
         """Tell result that test finished with an error.
 
=== modified file 'bzrlib/tests/test_selftest.py'
--- bzrlib/tests/test_selftest.py	2010-09-27 19:31:45 +0000
+++ bzrlib/tests/test_selftest.py	2010-09-27 20:29:40 +0000
@@ -849,6 +849,21 @@
         self.assertContainsRe(output,
             r"LSProf output for <type 'unicode'>\(\('world',\), {'errors': 'replace'}\)\n")
 
+    def test_uses_time_from_testtools(self):
+        """Test case timings in verbose results should use testtools times"""
+        import datetime
+        class TimeAddedVerboseTestResult(tests.VerboseTestResult):
+            def startTest(self, test):
+                self.time(datetime.datetime.utcfromtimestamp(1.145))
+                super(TimeAddedVerboseTestResult, self).startTest(test)
+            def addSuccess(self, test):
+                self.time(datetime.datetime.utcfromtimestamp(51.147))
+                super(TimeAddedVerboseTestResult, self).addSuccess(test)
+            def report_tests_starting(self): pass
+        sio = StringIO()
+        self.get_passing_test().run(TimeAddedVerboseTestResult(sio, 0, 2))
+        self.assertEndsWith(sio.getvalue(), "OK    50002ms\n")
+
     def test_known_failure(self):
         """A KnownFailure being raised should trigger several result actions."""
         class InstrumentedTestResult(tests.ExtendedTestResult):