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::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
So I hacked together the short
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] 1..3 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