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

# HG changeset patch
# User anuraggoel <anurag.dsps@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.

On Wed, Jun 18, 2014 at 2:07 PM, Anurag Goel <anurag.dsps@gmail.com> wrote:

> # HG changeset patch
> # User anuraggoel <anurag.dsps@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)
>

* (glob) could be replace with the following line

[\d.\s]{23} test-success.t (re)

This one looks more precise.

+
>  failing test
>  ==================
>
>
I will wait to get more review on this patch before sending the next
version of this patch.

On 06/18/2014 01:37 AM, Anurag Goel wrote:
> # HG changeset patch
> # User anuraggoel <anurag.dsps@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()

You should document the new content type here (in a comment)

>
>       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]))
> +

1. the indentation is wrong should be align with parents opening.

2. unreadale blob. Put stuff in intermediate variable.

>           del self._started[test.name]
> +        del self._stopped[test.name]

suspicious indentation.

>
>           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)

The glob is far too wide. Please produce a more precise regular expression.


You should also provides a test that check --time with --jobs