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]
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 strptime.
I use Perl to support an EDA engineering organization. Occasionally I write about the things I do with Perl.
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.
Hi Chris
See also https://metacpan.org/release/Time-Elapsed
Interesting. Is there a way to enable this so I can get timing reports on various CPAN Testers machines?
Thanks for pointing out the use of the --timer flag. I had meant to say something about it, but forgot. It's one of the options I have set in my ~/.proverc file and, as you mentioned, is quite useful for timing an entire test script.
Thanks, Ron. I rather liked the Time::Elapsed module when I found it and, in fact, had started using it when I was still adding timing code to my test files. I may try to use it if I develop a Test:: module to be included in test files.
Steven,
That's a good question. I don't know how an alternative formatter can be activated from within a test file, which would probably be required for CPAN Testers to use a custom formatter. This may be the use case I need to develop a Test:: module to enable something similar within a test file.