1Devel::Timer(3)       User Contributed Perl Documentation      Devel::Timer(3)
2
3
4

NAME

6       Devel::Timer - Track and report execution time for parts of code
7

VERSION

9       version 0.12
10

SYNOPSIS

12         use Devel::Timer;
13
14         my $t = Devel::Timer->new();
15
16         $t->mark('first db query');
17
18         ## do some work
19
20         $t->mark('second db query');
21
22         ## do some more work
23
24         $t->mark('end of second db query');
25
26         $t->report();
27

DESCRIPTION

29       Devel::Timer allows developers to accurately time how long a specific
30       piece of code takes to execute.  This can be helpful in locating the
31       slowest parts of an existing application.
32
33       First, the Devel::Timer module is used and instantiated.
34
35         use Devel::Timer;
36
37         my $t = Devel::Timer->new();
38
39       Second, markers are placed before and after pieces of code that need to
40       be timed.  For this example, we are profiling the methods
41       get_user_score() and get_average_user_score().
42
43         $t->mark('first db query');
44         &get_user_score($user);
45
46         $t->mark('second db query');
47         &get_average_user_score();
48
49       Finally, at the end of the code that you want to profile, and end
50       marker is place, and a report is generated on stderr.
51
52         $t->mark('END');
53         $t->report();
54
55       Sample report:
56
57         Devel::Timer Report -- Total time: 0.3464 secs
58         Interval  Time    Percent
59         ----------------------------------------------
60         02 -> 03  0.3001  86.63%  second db query -> END
61         01 -> 02  0.0461  13.30%  first db query -> second db query
62         00 -> 01  0.0002   0.07%  INIT -> first db query
63
64       The report is output using the method Devel::Timer::print() which
65       currently just prints to stderr.  If you want to send the output to a
66       custom location you can override the print() method.  The initialize()
67       and shutdown() methods can also overridden if you want to open and
68       close log files or database connections.
69

METHODS

71   new()
72       Create a new instance. No parameters are processed.
73
74   initialize()
75       Empty method. Can be implemented in the subclass.
76
77   mark($name)
78       Set a timestamp with a $name.
79
80   print()
81       Prints to STDERR. Can be overridden in the subclass.
82
83   report(%args)
84       Prints the report to STDOUT. The %args can have the following keys:
85
86           +----------+--------------------------+
87           | Keys     | Description              |
88           +----------+--------------------------+
89           | collapse | can be 0 or 1            |
90           |          |                          |
91           | sort_by  | can be 'time' or 'count' |
92           +----------+--------------------------+
93
94       By default report() looks like this:
95
96         $t->report;
97
98         Devel::Timer Report -- Total time: 7.0028 secs
99         Interval  Time    Percent
100         ----------------------------------------------
101         05 -> 06  3.0006  42.85%  something begin -> something end
102         03 -> 04  2.0007  28.57%  something begin -> something end
103         06 -> 07  1.0009  14.29%  something end -> END
104         01 -> 02  1.0004  14.29%  something begin -> something end
105         00 -> 01  0.0000   0.00%  INIT -> something begin
106         04 -> 05  0.0000   0.00%  something end -> something begin
107         02 -> 03  0.0000   0.00%  something end -> something begin
108
109       Which is great for small or non-iterative programs, but if there's
110       hundreds of loops of 'something begin -> something end' the report gets
111       very painful very quickly. :)
112
113       In that scenario you might find collapse useful:
114
115         $t->report(collapse => 1);
116
117         Devel::Timer Report -- Total time: 7.0028 secs
118         Count     Time    Percent
119         ----------------------------------------------
120                3  6.0018  85.71%  something begin -> something end
121                1  1.0009  14.29%  something end -> END
122                2  0.0001   0.00%  something end -> something begin
123                1  0.0000   0.00%  INIT -> something begin
124
125       The stats for all combinations of labels are added together.
126
127       We also accept a sort_by parameter. By default the report is sorted by
128       total time spent descending (like the default report()), but you can
129       sort by count descending instead if you want:
130
131         $t->report(collapse => 1, sort_by => 'count');
132
133         Devel::Timer Report -- Total time: 7.0028 secs
134         Count     Time    Percent
135         ----------------------------------------------
136                3  6.0018  85.71%  something begin -> something end
137                2  0.0001   0.00%  something end -> something begin
138                1  0.0000   0.00%  INIT -> something begin
139                1  1.0009  14.29%  something end -> END
140
141   get_stats($start, $end)
142       Returns the accumulated statistics for a specific a combination of
143       mark()'s that have occurred while your program ran.  These values are
144       the exact same statistics that report() prints. get_stats() simply
145       returns them to you so you can do something creative with them.
146
147       For example, to get the cumulative stats for every time your program
148       has specifically moved from mark('X') to mark('Y'), you can run this:
149
150         my ($time, $percent, $count) = $t->get_stats('X', 'Y');
151
152       $time is the total number of seconds elapsed between 'X' and 'Y'.
153
154       $percent is the percentage of total program run time that you have
155       spent between 'X' and 'Y'.
156
157       $count is the number of times your program has moved from 'X' to 'Y'.
158
159   shutdown
160       Empty method. Can be implemented in subclass.
161

SUBCLASSING

163           package MyTimer;
164
165           use strict;
166           use Devel::Timer;
167           use vars qw(@ISA);
168
169           @ISA = ('Devel::Timer');
170
171           sub initialize
172           {
173               my $log = '/tmp/timer.log';
174               open(my $LOG, '>>', $log) or die("Unable to open [$log] for writing.");
175           }
176
177           sub print
178           {
179               my($self, $msg) = @_;
180               print $LOG $msg . "\n";
181           }
182
183           sub shutdown
184           {
185               close $LOG;
186           }
187
188       You would then use the new module MyTimer exactly as you would use
189       "Devel::Timer".
190
191         use MyTimer;
192         my $t = MyTimer->new();
193         $t->mark('about to do x');
194         $t->mark('about to do y');
195         $t->mark('done y');
196         $t->report();
197

TO DO

199       "Devel::Timer" does not currently do any reporting or statistics of any
200       kind based on nested trees of mark() calls. So if your program runs
201       these mark() calls:
202
203         A
204           B, C
205           B, C
206         D
207         E
208
209       "Devel::Timer" never tells you anything about how much time you spent
210       moving from A to D. Depth aware reporting might be an interesting
211       project to tackle.
212

SEE ALSO

214       Time::HiRes
215

REPOSITORY

217       <https://github.com/manwar/Devel-Timer>
218

220       Jason Moore
221
222       This is free software.  It is licensed under the same terms as Perl
223       itself.
224

AUTHOR

226         Author:      Jason Moore - jmoore@sober.com (no longer valid)
227         Maintainer:  Gabor Szabo - gabor@pti.co.il
228         Contributor: Jay Hannah  - jay@jays.net
229
230         Currently maintained by Mohammad S Anwar (MANWAR) - mohammad.anwar@yahoo.com
231
232
233
234perl v5.28.1                      2017-02-10                   Devel::Timer(3)
Impressum