| 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
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?
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 >
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.
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?
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'])