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.14
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
70       If you launch your program in a cycle (e.g. it's a web app which
71       processes queries) you might want initialize timer once and then take
72       measurements repeatedly. In that case you can use reset() method. After
73       calling this method all accumulated data by timer will be deleted and
74       timer will start countdown again.
75
76         $t->reset();
77         $t->report();
78
79       Sample report:
80
81         Devel::Timer Report -- Total time: 0.3462 secs
82         Interval  Time    Percent
83         ----------------------------------------------
84         01 -> 02  0.3001  86.70%  second db query -> END
85         00 -> 01  0.0461  13.30%  first db query -> second db query
86
87       Pay attention after calling reset() method there will be no mark INIT.
88       This mark is only set once while calling new() method.
89

METHODS

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

SUBCLASSING

186           package MyTimer;
187
188           use strict;
189           use Devel::Timer;
190           use vars qw(@ISA);
191
192           @ISA = ('Devel::Timer');
193
194           sub initialize
195           {
196               my $log = '/tmp/timer.log';
197               open(my $LOG, '>>', $log) or die("Unable to open [$log] for writing.");
198           }
199
200           sub print
201           {
202               my($self, $msg) = @_;
203               print $LOG $msg . "\n";
204           }
205
206           sub shutdown
207           {
208               close $LOG;
209           }
210
211       You would then use the new module MyTimer exactly as you would use
212       "Devel::Timer".
213
214         use MyTimer;
215         my $t = MyTimer->new();
216         $t->mark('about to do x');
217         $t->mark('about to do y');
218         $t->mark('done y');
219         $t->report();
220

TO DO

222       "Devel::Timer" does not currently do any reporting or statistics of any
223       kind based on nested trees of mark() calls. So if your program runs
224       these mark() calls:
225
226         A
227           B, C
228           B, C
229         D
230         E
231
232       "Devel::Timer" never tells you anything about how much time you spent
233       moving from A to D. Depth aware reporting might be an interesting
234       project to tackle.
235

SEE ALSO

237       Time::HiRes
238

REPOSITORY

240       <https://github.com/manwar/Devel-Timer>
241
243       Jason Moore
244
245       This is free software.  It is licensed under the same terms as Perl
246       itself.
247

AUTHOR

249         Author:      Jason Moore - jmoore@sober.com (no longer valid)
250         Maintainer:  Gabor Szabo - gabor@pti.co.il
251         Contributor: Jay Hannah  - jay@jays.net
252
253         Currently maintained by Mohammad S Anwar (MANWAR) - mohammad.anwar@yahoo.com
254
255
256
257perl v5.36.0                      2022-10-08                   Devel::Timer(3)
Impressum