1Devel::Timer(3) User Contributed Perl Documentation Devel::Timer(3)
2
6 Devel::Timer - Track and report execution time for parts of code
7
9 version 0.14
10
12 use Devel::Timer;
13 my $t = Devel::Timer->new();
15 $t->mark('first db query');
17 ## do some work
19 $t->mark('second db query');
21 ## do some more work
23 $t->mark('end of second db query');
25 $t->report();
27
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 First, the Devel::Timer module is used and instantiated.
34 use Devel::Timer;
36 my $t = Devel::Timer->new();
38 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 $t->mark('first db query');
44 &get_user_score($user);
45 $t->mark('second db query');
47 &get_average_user_score();
48 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 $t->mark('END');
53 $t->report();
54 Sample report:
56 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 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 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 $t->reset();
77 $t->report();
78 Sample report:
80 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 Pay attention after calling reset() method there will be no mark INIT.
88 This mark is only set once while calling new() method.
89
91 new()
92 Create a new instance. No parameters are processed.
93 initialize()
95 Empty method. Can be implemented in the subclass.
96 mark($name)
98 Set a timestamp with a $name.
99 reset()
101 Delete all data accumulated by timer.
102 print()
104 Prints to STDERR. Can be overridden in the subclass.
105 report(%args)
107 Prints the report to STDOUT. The %args can have the following keys:
108 +----------+--------------------------+
110 | Keys | Description |
111 +----------+--------------------------+
112 | collapse | can be 0 or 1 |
113 | | |
114 | sort_by | can be 'time' or 'count' |
115 +----------+--------------------------+
116 By default report() looks like this:
118 $t->report;
120 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 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 In that scenario you might find collapse useful:
137 $t->report(collapse => 1);
139 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 The stats for all combinations of labels are added together.
149 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 $t->report(collapse => 1, sort_by => 'count');
155 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 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 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 my ($time, $percent, $count) = $t->get_stats('X', 'Y');
174 $time is the total number of seconds elapsed between 'X' and 'Y'.
176 $percent is the percentage of total program run time that you have
178 spent between 'X' and 'Y'.
179 $count is the number of times your program has moved from 'X' to 'Y'.
181 shutdown
183 Empty method. Can be implemented in subclass.
184
186 package MyTimer;
187 use strict;
189 use Devel::Timer;
190 use vars qw(@ISA);
191 @ISA = ('Devel::Timer');
193 sub initialize
195 {
196 my $log = '/tmp/timer.log';
197 open(my $LOG, '>>', $log) or die("Unable to open [$log] for writing.");
198 }
199 sub print
201 {
202 my($self, $msg) = @_;
203 print $LOG $msg . "\n";
204 }
205 sub shutdown
207 {
208 close $LOG;
209 }
210 You would then use the new module MyTimer exactly as you would use
212 "Devel::Timer".
213 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
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 A
227 B, C
228 B, C
229 D
230 E
231 "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
237 Time::HiRes
238
240 <https://github.com/manwar/Devel-Timer>
241
243 Jason Moore
244 This is free software. It is licensed under the same terms as Perl
246 itself.
247
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 Currently maintained by Mohammad S Anwar (MANWAR) - mohammad.anwar@yahoo.com
254perl v5.38.0 2023-07-20 Devel::Timer(3)