[PATCH V3] run-tests: '--time' option provide more details to Linux users

[Anurag Goel]

# HG changeset patch
# User anuraggoel <anurag.dsps at gmail.com>
# Date 1403079999 -19800
#      Wed Jun 18 13:56:39 2014 +0530
# Node ID faa6469d11ddb4842169be76fb8f83312e5e0359
# Parent  4951b897118e18d3081f07b98a96c0a917d71a24
run-tests: '--time' option provide more details to Linux users

As our tests execute in child processes, this patch uses os.times()
module in replace of time.time() module to provide additional info like
user time and system time spent by child's processes along with real ellapased
time taken by a process.

There is one limitation of this patch. It can work only for Linux users and not
for Windows.

"os.times" module returns a 5-tuple of a floaing point numbers.
1) User time
2) System time
3) Child's user time
4) Child's system time
5) Ellapsed real time

On Windows, only the first two items are filled, the others are zero.
Therefore, below test case does not break on Windows but instead gives the
null value.

diff -r 4951b897118e -r faa6469d11dd tests/run-tests.py
--- a/tests/run-tests.py	Wed Jun 18 02:29:14 2014 +0530
+++ b/tests/run-tests.py	Wed Jun 18 13:56:39 2014 +0530
@@ -1070,6 +1070,7 @@
 
         self.times = []
         self._started = {}
+        self._stopped = {}
 
     def addFailure(self, test, reason):
         self.failures.append((test, reason))
@@ -1159,17 +1160,23 @@
     def startTest(self, test):
         super(TestResult, self).startTest(test)
 
-        self._started[test.name] = time.time()
+        self._started[test.name] = os.times()
 
     def stopTest(self, test, interrupted=False):
         super(TestResult, self).stopTest(test)
 
-        self.times.append((test.name, time.time() - self._started[test.name]))
+        self._stopped[test.name] = os.times()
+        self.times.append((test.name, self._stopped[test.name][2] -
+                    self._started[test.name][2], self._stopped[test.name][3] -
+                    self._started[test.name][3], self._stopped[test.name][4] -
+                    self._started[test.name][4]))
+
         del self._started[test.name]
+        del self._stopped[test.name]
 
         if interrupted:
             self.stream.writeln('INTERRUPTED: %s (after %d seconds)' % (
-                test.name, self.times[-1][1]))
+                test.name, self.times[-1][3]))
 
 class TestSuite(unittest.TestSuite):
     """Custom unitest TestSuite that knows how to execute Mercurial tests."""
@@ -1338,11 +1345,12 @@
 
     def printtimes(self, times):
         self.stream.writeln('# Producing time report')
-        times.sort(key=lambda t: (t[1], t[0]), reverse=True)
-        cols = '%7.3f   %s'
-        self.stream.writeln('%-7s   %s' % ('Time', 'Test'))
-        for test, timetaken in times:
-            self.stream.writeln(cols % (timetaken, test))
+        times.sort(key=lambda t: (t[3]))
+        cols = '%0.3f %7.3f %7.3f   %s'
+        self.stream.writeln('%-7s %-7s %-7s   %s' % ('cuser', 'csys', 'real',
+                    'Test'))
+        for test, cuser, csys, real in times:
+            self.stream.writeln(cols % (cuser, csys, real, test))
 
 class TestRunner(object):
     """Holds context for executing tests.
diff -r 4951b897118e -r faa6469d11dd tests/test-run-tests.t
--- a/tests/test-run-tests.t	Wed Jun 18 02:29:14 2014 +0530
+++ b/tests/test-run-tests.t	Wed Jun 18 13:56:39 2014 +0530
@@ -19,6 +19,16 @@
   .
   # Ran 1 tests, 0 skipped, 0 warned, 0 failed.
 
+test for --time
+==================
+
+  $ $TESTDIR/run-tests.py --with-hg=`which hg` --time
+  .
+  # Ran 1 tests, 0 skipped, 0 warned, 0 failed.
+  # Producing time report
+  cuser   csys    real      Test
+  * (glob)
+
 failing test
 ==================