run-tests: include 'start' and 'end' in --time output
authorPierre-Yves David <pierre-yves.david@fb.com>
Thu, 07 May 2015 23:40:29 -0700
changeset 25098 bf84ab53c2fd
parent 25097 a4fce7905721
child 25099 5e111215e38b
run-tests: include 'start' and 'end' in --time output This is useful information to understand what is taking time in tests. Both are included because I can see myself sorting this output using shell script. Having both data makes it much easier than extracting 'start'+'real'.
tests/run-tests.py
tests/test-run-tests.t
--- a/tests/run-tests.py	Thu May 07 23:34:58 2015 -0700
+++ b/tests/run-tests.py	Thu May 07 23:40:29 2015 -0700
@@ -1603,13 +1603,13 @@
         # iolock held by run
         self.stream.writeln('# Producing time report')
         times.sort(key=lambda t: (t[3]))
-        cols = '%7.3f %7.3f %7.3f   %s'
-        self.stream.writeln('%-7s %-7s %-7s   %s' % ('cuser', 'csys', 'real',
-                    'Test'))
+        cols = '%7.3f %7.3f %7.3f %7.3f %7.3f   %s'
+        self.stream.writeln('%-7s %-7s %-7s %-7s %-7s   %s' %
+                            ('start', 'end', 'cuser', 'csys', 'real', 'Test'))
         for tdata in times:
             test = tdata[0]
-            cuser, csys, real = tdata[1:4]
-            self.stream.writeln(cols % (cuser, csys, real, test))
+            cuser, csys, real, start, end = tdata[1:6]
+            self.stream.writeln(cols % (start, end, cuser, csys, real, test))
 
 class TestRunner(object):
     """Holds context for executing tests.
--- a/tests/test-run-tests.t	Thu May 07 23:34:58 2015 -0700
+++ b/tests/test-run-tests.t	Thu May 07 23:40:29 2015 -0700
@@ -398,8 +398,8 @@
   .
   # Ran 1 tests, 0 skipped, 0 warned, 0 failed.
   # Producing time report
-  cuser   csys    real      Test
-  \s*[\d\.]{5}   \s*[\d\.]{5}   \s*[\d\.]{5}   test-success.t (re)
+  start   end     cuser   csys    real      Test
+  \s*[\d\.]{5}   \s*[\d\.]{5}   \s*[\d\.]{5}   \s*[\d\.]{5}   \s*[\d\.]{5}   test-success.t (re)
 
 test for --time with --job enabled
 ====================================
@@ -408,8 +408,8 @@
   .
   # Ran 1 tests, 0 skipped, 0 warned, 0 failed.
   # Producing time report
-  cuser   csys    real      Test
-  \s*[\d\.]{5}   \s*[\d\.]{5}   \s*[\d\.]{5}   test-success.t (re)
+  start   end     cuser   csys    real      Test
+  \s*[\d\.]{5}   \s*[\d\.]{5}   \s*[\d\.]{5}   \s*[\d\.]{5}   \s*[\d\.]{5}   test-success.t (re)
 
 Skips
 ================