Patchwork [1,of,3,V4] run-tests: '--time' option provide more details to Linux users

login
register
mail settings
Submitter Anurag Goel
Date June 21, 2014, 4:21 p.m.
Message ID <d7a0a8654dbb60ec0121.1403367705@ubuntu.ubuntu-domain>
Download mbox | patch
Permalink /patch/5032/
State Superseded
Commit 4ca4e15720223743bcdff42ce88c47675a94dcb8
Headers show

Comments

Anurag Goel - June 21, 2014, 4:21 p.m.
# HG changeset patch
# User anuraggoel <anurag.dsps@gmail.com>
# Date 1403365016 -19800
#      Sat Jun 21 21:06:56 2014 +0530
# Node ID d7a0a8654dbb60ec0121975f82bb8d06369d8216
# Parent  cd3c79392056a0d965236e4986a7a4b5d580f3e5
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, test cases included with this series does not break on Windows but
instead gives the null value.
Pierre-Yves David - June 23, 2014, 8:46 a.m.
On 06/21/2014 09:21 AM, Anurag Goel wrote:
> # HG changeset patch
> # User anuraggoel <anurag.dsps@gmail.com>
> # Date 1403365016 -19800
> #      Sat Jun 21 21:06:56 2014 +0530
> # Node ID d7a0a8654dbb60ec0121975f82bb8d06369d8216
> # Parent  cd3c79392056a0d965236e4986a7a4b5d580f3e5
> 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

elapsed

> time taken by a process.
>
> There is one limitation of this patch. It can work only for Linux users and not
> for Windows.

This shouldbe reflected in a comment.

>
> "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, test cases included with this series does not break on Windows but
> instead gives the null value.

There is no "null" value in python. Do you mean None?


Also, test should be in the same patches.

> diff -r cd3c79392056 -r d7a0a8654dbb tests/run-tests.py
> --- a/tests/run-tests.py	Wed Jun 18 20:59:36 2014 -0500
> +++ b/tests/run-tests.py	Sat Jun 21 21:06:56 2014 +0530
> @@ -1076,6 +1076,7 @@
>
>           self.times = []
>           self._started = {}
> +        self._stopped = {}
>
>       def addFailure(self, test, reason):
>           self.failures.append((test, reason))
> @@ -1165,17 +1166,26 @@
>       def startTest(self, test):
>           super(TestResult, self).startTest(test)
>
> -        self._started[test.name] = time.time()
> +        self._started[test.name] = os.times()
> +        # os.times module computes the user time and system time spent
> +        # by child's processes along with real ellapsed time taken by
> +        # a process.

Documentation should be before the documented line.


>
>       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()
> +        cuser_time = self._stopped[test.name][2] - self._started[test.name][2]
> +        csys_time = self._stopped[test.name][3] - self._started[test.name][3]
> +        realtime = self._stopped[test.name][4] - self._started[test.name][4]

The highly repetitive part here are: "self._stopped[test.name]" and 
"self._started[test.name]". They are the part that should be factored in 
temporary variables.




> +
> +        self.times.append((test.name, cuser_time, csys_time, realtime))
>           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."""
> @@ -1346,11 +1356,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.
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@selenic.com
> http://selenic.com/mailman/listinfo/mercurial-devel
>

Patch

diff -r cd3c79392056 -r d7a0a8654dbb tests/run-tests.py
--- a/tests/run-tests.py	Wed Jun 18 20:59:36 2014 -0500
+++ b/tests/run-tests.py	Sat Jun 21 21:06:56 2014 +0530
@@ -1076,6 +1076,7 @@ 
 
         self.times = []
         self._started = {}
+        self._stopped = {}
 
     def addFailure(self, test, reason):
         self.failures.append((test, reason))
@@ -1165,17 +1166,26 @@ 
     def startTest(self, test):
         super(TestResult, self).startTest(test)
 
-        self._started[test.name] = time.time()
+        self._started[test.name] = os.times()
+        # os.times module computes the user time and system time spent
+        # by child's processes along with real ellapsed time taken by
+        # a process.
 
     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()
+        cuser_time = self._stopped[test.name][2] - self._started[test.name][2]
+        csys_time = self._stopped[test.name][3] - self._started[test.name][3]
+        realtime = self._stopped[test.name][4] - self._started[test.name][4]
+
+        self.times.append((test.name, cuser_time, csys_time, realtime))
         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."""
@@ -1346,11 +1356,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.