Patchwork run-test: '--time' option provide more details to user

login
register
mail settings
Submitter Anurag Goel
Date May 24, 2014, 7:10 p.m.
Message ID <0c6ee6403d787f8eb08f.1400958641@ubuntu.ubuntu-domain>
Download mbox | patch
Permalink /patch/4859/
State Changes Requested
Headers show

Comments

Anurag Goel - May 24, 2014, 7:10 p.m.
# HG changeset patch
# User anuraggoel <anurag.dsps@gmail.com>
# Date 1400958116 -19800
#      Sun May 25 00:31:56 2014 +0530
# Node ID 0c6ee6403d787f8eb08fe01550f2e9e0aa637c26
# Parent  883e268cb860c0ea2eb0faa94114e11c3a4a3893
run-test: '--time' option provide more details to user

'time.time()' module can only be used to calculate 'real' time taken by a
process. Therefore, I switched it to 'os.times()' module which helps in
getting additional info like "Total number of CPU-seconds that the process
spent in kernel mode" and "Total number of CPU-seconds that the process spent
in user mode".
Pierre-Yves David - May 26, 2014, 6:42 p.m.
On 05/24/2014 12:10 PM, Anurag Goel wrote:
> # HG changeset patch
> # User anuraggoel <anurag.dsps@gmail.com>
> # Date 1400958116 -19800
> #      Sun May 25 00:31:56 2014 +0530
> # Node ID 0c6ee6403d787f8eb08fe01550f2e9e0aa637c26
> # Parent  883e268cb860c0ea2eb0faa94114e11c3a4a3893
> run-test: '--time' option provide more details to user
>
> 'time.time()' module can only be used to calculate 'real' time taken by a
> process. Therefore, I switched it to 'os.times()' module which helps in
> getting additional info like "Total number of CPU-seconds that the process
> spent in kernel mode" and "Total number of CPU-seconds that the process spent
> in user mode".


What does the new output looks like?

did you tested it? are you sure it works? Did you tested it with -j

What would be for example the output of it for test-largefiles.t?
Anurag Goel - May 26, 2014, 7:02 p.m.
On Tue, May 27, 2014 at 12:12 AM, Pierre-Yves David <
pierre-yves.david@ens-lyon.org> wrote:

>
>
> On 05/24/2014 12:10 PM, Anurag Goel wrote:
>
>> # HG changeset patch
>> # User anuraggoel <anurag.dsps@gmail.com>
>> # Date 1400958116 -19800
>> #      Sun May 25 00:31:56 2014 +0530
>> # Node ID 0c6ee6403d787f8eb08fe01550f2e9e0aa637c26
>> # Parent  883e268cb860c0ea2eb0faa94114e11c3a4a3893
>> run-test: '--time' option provide more details to user
>>
>> 'time.time()' module can only be used to calculate 'real' time taken by a
>> process. Therefore, I switched it to 'os.times()' module which helps in
>> getting additional info like "Total number of CPU-seconds that the process
>> spent in kernel mode" and "Total number of CPU-seconds that the process
>> spent
>> in user mode".
>>
>
>
> What does the new output looks like?
>
 user-time    sys-time     real-time     Testname

did you tested it? are you sure it works? Did you tested it with -j
>
Yes i tested it  and it seems to work perfectly fine even with -j option.

>
> What would be for example the output of it for test-largefiles.t?
>
.
# Ran 1 tests, 0 skipped, 0 warned, 0 failed.

user    sys     real     Test
0.090   0.030  35.680  test-largefiles.t


>
>
> --
> Pierre-Yves David
>
Gregory Szorc - May 26, 2014, 7:03 p.m.
On 5/24/2014 12:10 PM, Anurag Goel wrote:
> # HG changeset patch
> # User anuraggoel <anurag.dsps@gmail.com>
> # Date 1400958116 -19800
> #      Sun May 25 00:31:56 2014 +0530
> # Node ID 0c6ee6403d787f8eb08fe01550f2e9e0aa637c26
> # Parent  883e268cb860c0ea2eb0faa94114e11c3a4a3893
> run-test: '--time' option provide more details to user
> 
> 'time.time()' module can only be used to calculate 'real' time taken by a
> process. Therefore, I switched it to 'os.times()' module which helps in
> getting additional info like "Total number of CPU-seconds that the process
> spent in kernel mode" and "Total number of CPU-seconds that the process spent
> in user mode".
> 
> diff -r 883e268cb860 -r 0c6ee6403d78 tests/run-tests.py
> --- a/tests/run-tests.py	Wed Apr 30 18:40:20 2014 -0700
> +++ b/tests/run-tests.py	Sun May 25 00:31:56 2014 +0530
> @@ -551,11 +551,11 @@
>  
>  def outputtimes(options):
>      vlog('# Producing time report')
> -    times.sort(key=lambda t: (t[1], t[0]), reverse=True)
> -    cols = '%7.3f   %s'
> -    print '\n%-7s   %s' % ('Time', 'Test')
> -    for test, timetaken in times:
> -        print cols % (timetaken, test)
> +    times.sort(key=lambda t: (t[2]))
> +    cols = '%0.3f %7.3f %7.3f  %s'
> +    print '\n%-7s %-7s %-7s  %s' % ('user', 'sys', 'real', 'Test')
> +    for user, sys, real, test in times:
> +        print cols % (user, sys, real, test)
>  
>  def outputcoverage(options):
>  
> @@ -990,15 +990,16 @@
>      env = createenv(options, testtmp, threadtmp, port)
>      createhgrc(env['HGRCPATH'], options)
>  
> -    starttime = time.time()
> +    starttime = os.times()
>      try:
>          ret, out = runner(testpath, testtmp, options, replacements, env)
>      except KeyboardInterrupt:
>          endtime = time.time()
>          log('INTERRUPTED: %s (after %d seconds)' % (test, endtime - starttime))
>          raise
> -    endtime = time.time()
> -    times.append((test, endtime - starttime))
> +    endtime = os.times()
> +    times.append((endtime[0] - starttime[0], endtime[1] - starttime[1],
> +                endtime[4] - starttime[4], test))
>      vlog("# Ret was:", ret)
>  
>      killdaemons(env['DAEMON_PIDS'])

Only the first 2 elements of os.times() are available on Windows.
Therefore this patch does not properly report wall time (os.times()[4])
on Windows and thus regresses behavior. Also, this patch has been bit
rotted by run-tests.py refactoring. Finally, test time recording occurs
in the parent process/thread whereas tests execute in child processes.
This patch doesn't measure what you think it is measuring.

I like the intention, but this patch isn't acceptable.
Anurag Goel - May 26, 2014, 10:01 p.m.
On Tue, May 27, 2014 at 12:33 AM, Gregory Szorc <gregory.szorc@gmail.com>wrote:

> On 5/24/2014 12:10 PM, Anurag Goel wrote:
> > # HG changeset patch
> > # User anuraggoel <anurag.dsps@gmail.com>
> > # Date 1400958116 -19800
> > #      Sun May 25 00:31:56 2014 +0530
> > # Node ID 0c6ee6403d787f8eb08fe01550f2e9e0aa637c26
> > # Parent  883e268cb860c0ea2eb0faa94114e11c3a4a3893
> > run-test: '--time' option provide more details to user
> >
> > 'time.time()' module can only be used to calculate 'real' time taken by a
> > process. Therefore, I switched it to 'os.times()' module which helps in
> > getting additional info like "Total number of CPU-seconds that the
> process
> > spent in kernel mode" and "Total number of CPU-seconds that the process
> spent
> > in user mode".
>

 Could you suggest me some alternate way to add  above mentioned features?
Gregory Szorc - May 27, 2014, 5:11 p.m.
On 5/26/14, 3:01 PM, Anurag Goel wrote:
> On Tue, May 27, 2014 at 12:33 AM, Gregory Szorc <gregory.szorc@gmail.com
> <mailto:gregory.szorc@gmail.com>> wrote:
>
>     On 5/24/2014 12:10 PM, Anurag Goel wrote:
>      > # HG changeset patch
>      > # User anuraggoel <anurag.dsps@gmail.com
>     <mailto:anurag.dsps@gmail.com>>
>      > # Date 1400958116 -19800
>      > #      Sun May 25 00:31:56 2014 +0530
>      > # Node ID 0c6ee6403d787f8eb08fe01550f2e9e0aa637c26
>      > # Parent  883e268cb860c0ea2eb0faa94114e11c3a4a3893
>      > run-test: '--time' option provide more details to user
>      >
>      > 'time.time()' module can only be used to calculate 'real' time
>     taken by a
>      > process. Therefore, I switched it to 'os.times()' module which
>     helps in
>      > getting additional info like "Total number of CPU-seconds that
>     the process
>      > spent in kernel mode" and "Total number of CPU-seconds that the
>     process spent
>      > in user mode".
>
>
>   Could you suggest me some alternate way to add  above mentioned features?

For Windows, I /think/ you are out of luck. AFAIK Windows doesn't have 
an API that counts subprocess times (like getrusage()). It does have 
GetProcessTimes(), but that's only for a single process. There are also 
performance counters for CPU usage, but those are system wide.

I think some information is better than no information. I think 
supplementing the wall time output with os.times() on platforms where 
those values are recorded would be beneficial.

Patch

diff -r 883e268cb860 -r 0c6ee6403d78 tests/run-tests.py
--- a/tests/run-tests.py	Wed Apr 30 18:40:20 2014 -0700
+++ b/tests/run-tests.py	Sun May 25 00:31:56 2014 +0530
@@ -551,11 +551,11 @@ 
 
 def outputtimes(options):
     vlog('# Producing time report')
-    times.sort(key=lambda t: (t[1], t[0]), reverse=True)
-    cols = '%7.3f   %s'
-    print '\n%-7s   %s' % ('Time', 'Test')
-    for test, timetaken in times:
-        print cols % (timetaken, test)
+    times.sort(key=lambda t: (t[2]))
+    cols = '%0.3f %7.3f %7.3f  %s'
+    print '\n%-7s %-7s %-7s  %s' % ('user', 'sys', 'real', 'Test')
+    for user, sys, real, test in times:
+        print cols % (user, sys, real, test)
 
 def outputcoverage(options):
 
@@ -990,15 +990,16 @@ 
     env = createenv(options, testtmp, threadtmp, port)
     createhgrc(env['HGRCPATH'], options)
 
-    starttime = time.time()
+    starttime = os.times()
     try:
         ret, out = runner(testpath, testtmp, options, replacements, env)
     except KeyboardInterrupt:
         endtime = time.time()
         log('INTERRUPTED: %s (after %d seconds)' % (test, endtime - starttime))
         raise
-    endtime = time.time()
-    times.append((test, endtime - starttime))
+    endtime = os.times()
+    times.append((endtime[0] - starttime[0], endtime[1] - starttime[1],
+                endtime[4] - starttime[4], test))
     vlog("# Ret was:", ret)
 
     killdaemons(env['DAEMON_PIDS'])