Elapsed Time in Test Output

I’ve been writing tests for a web service in which one of the methods would occasionally take an inordinate amount of time. The amount of time was inconsistent and it would be useful to capture some timing data to provide the vendor. But, I didn’t want to litter my test files with code to calculate the elapsed time. Eventually, the bugs would be worked out and the timing information would just be noise.

So I wanted to somehow hook into the test framework itself to give me the timing data.

First, I explored creating a Test module that overrode the test methods to do what I wanted. Ideally, the interface would look like,

use Test::More;
use Test::Elapsed;

While exploring the source of Test::More and Test::Builder, I decided that I didn’t have time to get something working and a better approach would be to solve this from the formatting side. After all, the timing wasn’t being used in the tests, I only cared about seeing the time taken while running the prove command.

So I hacked together the short TAP::Formatter::Elapsed:

It’s pretty simple to use:

$ prove --formatter TAP::Formatter::Elapsed -v elapsed.t 
[18:04:38] elapsed.t .. 
ok 1 [Mon Jul 30 18:04:39 2012, 1.04, 1.04 elapsed]
ok 2 [Mon Jul 30 18:04:43 2012, 4.00, 5.04 elapsed]
ok 3 [Mon Jul 30 18:04:48 2012, 5.00, 10.04 elapsed]
ok    10017 ms [Mon Jul 30 18:04:48 2012, 0.00, 10.04 elapsed]
[18:04:48]All tests successful.
Files=1, Tests=3, 10 wallclock secs ( 0.02 usr  0.01 sys +  0.01 cusr  0.00 csys =  0.04 CPU)
Result: PASS

I hooked into the _output method, which means the main caveat is that the time elapsed for each test is actually the time elapsed since the output of the previous test. In practice, I doubt this matters, but it’s something to be aware of when interpreting results.

If this works out for me, I’ll see about cleaning it up and releasing it on CPAN. One thing that comes immediately to mind is a way to specify a custom format, like strptime.


It would be great to have this on CPAN. I've recently had some tests occasionally taking way too much time, so something like this would have been quite handy.

For those who want to know how long each individual test program takes, without granualarity to the subtest level, you can just use prove --timer, or set HARNESS_TIMER=1 in your environment. I just set HARNESS_TIMER=1 in my .bashrc on all machines and don't have to think about it.

Interesting. Is there a way to enable this so I can get timing reports on various CPAN Testers machines?

Leave a comment

About Chris Grau

user-pic I use Perl to support an EDA engineering organization. Occasionally I write about the things I do with Perl.