NAME
Devel::Timer - Track and report execution time for parts of code
VERSION
version 0.11
SYNOPSIS
use Devel::Timer;
my $t = Devel::Timer->new();
$t->mark('first db query');
## do some work
$t->mark('second db query');
## do some more work
$t->mark('end of second db query');
$t->report();
DESCRIPTION
Devel::Timer allows developers to accurately time how long a specific piece of code takes to execute. This can be helpful in locating the slowest parts of an existing application.
First, the Devel::Timer module is used and instantiated.
use Devel::Timer;
my $t = Devel::Timer->new();
Second, markers are placed before and after pieces of code that need to be timed. For this example, we are profiling the methods get_user_score() and get_average_user_score().
$t->mark('first db query');
&get_user_score($user);
$t->mark('second db query');
&get_average_user_score();
Finally, at the end of the code that you want to profile, and end marker is place, and a report is generated on stderr.
$t->mark('END');
$t->report();
Sample report:
Devel::Timer Report -- Total time: 0.3464 secs
Interval Time Percent
----------------------------------------------
02 -> 03 0.3001 86.63% second db query -> END
01 -> 02 0.0461 13.30% first db query -> second db query
00 -> 01 0.0002 0.07% INIT -> first db query
The report is output using the method Devel::Timer::print() which currently just prints to stderr. If you want to send the output to a custom location you can override the print() method. The initialize() and shutdown() methods can also overridden if you want to open and close log files or database connections.
METHODS
new()
Create a new instance. No parameters are processed.
initialize()
Empty method. Can be implemented in the subclass.
mark($name)
Set a timestamp with a $name
.
print()
Prints to STDERR. Can be overridden in the subclass.
report(%args)
Prints the report to STDOUT. The %args can have the following keys:
+----------+--------------------------+
| Keys | Description |
+----------+--------------------------+
| collapse | can be 0 or 1 |
| | |
| sort_by | can be 'time' or 'count' |
+----------+--------------------------+
By default report() looks like this:
$t->report;
Devel::Timer Report -- Total time: 7.0028 secs
Interval Time Percent
----------------------------------------------
05 -> 06 3.0006 42.85% something begin -> something end
03 -> 04 2.0007 28.57% something begin -> something end
06 -> 07 1.0009 14.29% something end -> END
01 -> 02 1.0004 14.29% something begin -> something end
00 -> 01 0.0000 0.00% INIT -> something begin
04 -> 05 0.0000 0.00% something end -> something begin
02 -> 03 0.0000 0.00% something end -> something begin
Which is great for small or non-iterative programs, but if there's hundreds of loops of 'something begin -> something end' the report gets very painful very quickly. :)
In that scenario you might find collapse useful:
$t->report(collapse => 1);
Devel::Timer Report -- Total time: 7.0028 secs
Count Time Percent
----------------------------------------------
3 6.0018 85.71% something begin -> something end
1 1.0009 14.29% something end -> END
2 0.0001 0.00% something end -> something begin
1 0.0000 0.00% INIT -> something begin
The stats for all combinations of labels are added together.
We also accept a sort_by parameter. By default the report is sorted by total time spent descending (like the default report()), but you can sort by count descending instead if you want:
$t->report(collapse => 1, sort_by => 'count');
Devel::Timer Report -- Total time: 7.0028 secs
Count Time Percent
----------------------------------------------
3 6.0018 85.71% something begin -> something end
2 0.0001 0.00% something end -> something begin
1 0.0000 0.00% INIT -> something begin
1 1.0009 14.29% something end -> END
get_stats($start, $end)
Returns the accumulated statistics for a specific a combination of mark()'s that have occurred while your program ran. These values are the exact same statistics that report() prints. get_stats() simply returns them to you so you can do something creative with them.
For example, to get the cumulative stats for every time your program has specifically moved from mark('X') to mark('Y'), you can run this:
my ($time, $percent, $count) = $t->get_stats('X', 'Y');
$time is the total number of seconds elapsed between 'X' and 'Y'.
$percent is the percentage of total program run time that you have spent between 'X' and 'Y'.
$count is the number of times your program has moved from 'X' to 'Y'.
shutdown
Empty method. Can be implemented in subclass.
SUBCLASSING
package MyTimer;
use strict;
use Devel::Timer;
use vars qw(@ISA);
@ISA = ('Devel::Timer');
sub initialize
{
my $log = '/tmp/timer.log';
open(my $LOG, '>>', $log) or die("Unable to open [$log] for writing.");
}
sub print
{
my($self, $msg) = @_;
print $LOG $msg . "\n";
}
sub shutdown
{
close $LOG;
}
You would then use the new module MyTimer exactly as you would use Devel::Timer
.
use MyTimer;
my $t = MyTimer->new();
$t->mark('about to do x');
$t->mark('about to do y');
$t->mark('done y');
$t->report();
TO DO
Devel::Timer
does not currently do any reporting or statistics of any kind based on nested trees of mark() calls. So if your program runs these mark() calls:
A
B, C
B, C
D
E
Devel::Timer
never tells you anything about how much time you spent moving from A to D. Depth aware reporting might be an interesting project to tackle.
SEE ALSO
REPOSITORY
https://github.com/manwar/Devel-Timer
LICENSE AND COPYRIGHT
Jason Moore
This is free software. It is licensed under the same terms as Perl itself.
AUTHOR
Author: Jason Moore - jmoore@sober.com (no longer valid)
Maintainer: Gabor Szabo - gabor@pti.co.il
Contributor: Jay Hannah - jay@jays.net
Currently maintained by Mohammad S Anwar (MANWAR) - mohammad.anwar@yahoo.com