Getting timing details from a test

mcdave has asked for the wisdom of the Perl Monks concerning the following question:

I have a test plan that does a sequence of steps, building on each other. I call the file with Test::Harness. I wrap each step in an "ok" statement, and I can get a nice statement at the end about the total time used in the process. That's very nice. I don't see a way to get it to tell me how many milliseconds each individual test took, though.

Technically, I don't really care about the absolute numbers. I actually want to know whether speeding up step N in various ways will slow down step N+1. I'm sure other clever things would come to mind if I could get it working, but I had in mind something that would process the output from my Test::Harness run and come up with some sort of statement about where my bottlenecks are, etc. So I'd like the output to be something like

ok 1 - 100 ms - the first test
ok 2 - 85 ms - test #2
ok 3 - 25 ms - done now
1..3
ok 210 ms
Result: PASS
[download]

and I'd look at that and do something with it.

As it stands now, I get most of this information but can't get the intermediate "ok" statements to tell me their timing. I wonder if there's a different tool I should look at or if I can just teach Test::Harness to do its output differently. I understand it would work fine if I used separate test files for each little piece, but then I don't see how to pass the results from one to the next.

Thanks for your help,

dave

Comment on Getting timing details from a test Download Code

Replies are listed 'Best First'.
Re: Getting timing details from a test by moritz (Cardinal) on Jan 07, 2011 at 21:52 UTC
As far as I can tell, all calls to the standard testing functions eventually go through `sub ok` in cpan/Test-Simple/lib/Test/Builder.pm in perl.git. If you override this sub, you could get a timestamp per individual sub test. If you just want one number, you could modify the test harness to do the timing on the caller side. Or you could write your own harness with TAP::Harness -- don't worry, it's not much work at all, TAP::Harness does all the hard parts for you. Perl 6 - second systems done right	[reply] [d/l]
Re^2: Getting timing details from a test by mcdave (Beadle) on May 29, 2012 at 16:49 UTC
I'm revisiting this year-old question because I had occasion last week to try to do this benchmark-plus-test thing in an extensible way and came up against some funny roadblocks. The most amusing/irritating was that overriding `sub ok` turned out to be a total bust! So I'll comment for posterity (which will include my future self) about why. Quite simply, `ok` just reads the result of the test. So in `ok(&test1, 'the first test') ;` the `ok` method doesn't get invoked at all until `test1` has finished. Hence, all my tests were showing up as instantaneous (because I was really just measuring time it took to call the `ok` method itself). What I need, somehow, is a version of "`ok`" that takes a subroutine as its first argument rather than a string then times the execution. As part of the process, though, I came across Test::More::Diagnostic which seems like the right kind of idea for augmenting my outputs so that future executions can be compared to baseline. This seems like a version of "write your own harness," and I'm hoping it won't be all that difficult.	[reply] [d/l] [select]
Re: Getting timing details from a test by kennethk (Abbot) on Jan 07, 2011 at 20:42 UTC
If your goal is benchmarking or profiling, you should probably use software developed for that purpose. The usual go-tos there are Benchmark and Devel::NYTProf, respectively. If you really want to including timing in your test result statements, you could use Time::HiRes to add appropriate output to your test descriptions.	[reply]
Re^2: Getting timing details from a test by mcdave (Beadle) on Jan 13, 2011 at 18:11 UTC
Thanks for mentioning "Benchmark". It turned out to be really easy to splice in. Just put some "new Benchmark" statements between my existing tests, and I'm good: `... use Benchmark qw(:hireswallclock); use Test::More ; ... $t0 = Benchmark->new ; ok(&test1, 'the first test') ; $t1 = Benchmark->new ; ok(&test2, 'test #2' ) ; $t2 = Benchmark->new ; ok(&test3, 'done now' ) ; $t3 = Benchmark->new ; note( 'the first test: ' . timestr(timediff($t1, $t0) ) ) ; note( 'test #2: ' . timestr(timediff($t2, $t1) ) ) ; note( 'done now: ' . timestr(timediff($t3, $t2) ) ) ;` [download] That's giving output I can work with.	[reply] [d/l]