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

[Pierre-Yves David]

# HG changeset patch
# User Pierre-Yves David <pierre-yves.david at fb.com>
# Date 1431067229 25200
#      Thu May 07 23:40:29 2015 -0700
# Node ID ccf10d4a7c9051adfad90847d989ed99aadd5e06
# Parent  7bb8c7d943cdb4889ea643e5e3474b5c7d470613
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'.

diff --git a/tests/run-tests.py b/tests/run-tests.py
--- a/tests/run-tests.py
+++ b/tests/run-tests.py
@@ -1601,17 +1601,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
@@ -396,22 +396,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