Patchwork [2,of,2] run-tests: include 'start' and 'end' in --time output

login
register
mail settings
Submitter Pierre-Yves David
Date May 9, 2015, 8:18 p.m.
Message ID <3e17246263ed1c5e1984.1431202725@marginatus.alto.octopoid.net>
Download mbox | patch
Permalink /patch/8996/
State Superseded
Commit bf84ab53c2fd73654ea2546eb609f75cbf8c2901
Headers show

Comments

Pierre-Yves David - May 9, 2015, 8:18 p.m.
# HG changeset patch
# User Pierre-Yves David <pierre-yves.david@fb.com>
# Date 1431067229 25200
#      Thu May 07 23:40:29 2015 -0700
# Node ID 3e17246263ed1c5e1984721fd724b6f5c9852c9a
# Parent  8e0564ce5766e039845ba5e8b4a8e94aa085b33c
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'.

Patch

diff --git a/tests/run-tests.py b/tests/run-tests.py
--- a/tests/run-tests.py
+++ b/tests/run-tests.py
@@ -1579,17 +1579,17 @@  class TextTestRunner(unittest.TextTestRu
 
     def printtimes(self, times):
         # 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.
 
     Tests rely on a lot of state. This object holds it for them.
diff --git a/tests/test-run-tests.t b/tests/test-run-tests.t
--- a/tests/test-run-tests.t
+++ b/tests/test-run-tests.t
@@ -389,22 +389,22 @@  test for --time
 
   $ $TESTDIR/run-tests.py --with-hg=`which hg` test-success.t --time
   .
   # 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
 ====================================
 
   $ $TESTDIR/run-tests.py --with-hg=`which hg` test-success.t --time --jobs 2
   .
   # 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
 ================
   $ cat > test-skip.t <<EOF
   >   $ echo xyzzy