File Coverage

blib/lib/Benchmark/Timer.pm
Criterion Covered Total %
statement 165 204 80.8
branch 47 82 57.3
condition 14 51 27.4
subroutine 25 27 92.5
pod 10 10 100.0
total 261 374 69.7


line stmt bran cond sub pod time code
1             package Benchmark::Timer;
2             require 5.005;
3 6     6   405167 use strict;
  6         66  
  6         205  
4              
5 6     6   38 use Carp;
  6         16  
  6         567  
6 6     6   2416 use Time::HiRes qw( gettimeofday tv_interval );
  6         6728  
  6         29  
7              
8 6     6   1407 use vars qw($VERSION);
  6         25  
  6         542  
9             $VERSION = sprintf "%d.%02d%02d", q/0.71.12/ =~ /(\d+)/g;
10              
11 6     6   47 use constant BEFORE => 0;
  6         15  
  6         705  
12 6     6   42 use constant ELAPSED => 1;
  6         13  
  6         349  
13 6     6   56 use constant LASTTAG => 2;
  6         20  
  6         304  
14 6     6   39 use constant TAGS => 3;
  6         11  
  6         357  
15 6     6   44 use constant SKIP => 4;
  6         14  
  6         305  
16 6     6   87 use constant MINIMUM => 5;
  6         38  
  6         328  
17 6     6   36 use constant SKIPCOUNT => 6;
  6         12  
  6         311  
18 6     6   34 use constant CONFIDENCE => 7;
  6         14  
  6         313  
19 6     6   35 use constant ERROR => 8;
  6         12  
  6         320  
20 6     6   36 use constant STAT => 9;
  6         9  
  6         12668  
21              
22             # ------------------------------------------------------------------------
23             # Constructor
24              
25             sub new {
26 14     14 1 7148 my $class = shift;
27 14         38 my $self = [];
28 14         36 bless $self, $class;
29 14         49 return $self->reset(@_);
30             }
31              
32              
33             # ------------------------------------------------------------------------
34             # Public methods
35              
36             sub reset {
37 17     17 1 625 my $self = shift;
38 17         54 my %args = @_;
39              
40 17         64 $self->[BEFORE] = {}; # [ gettimeofday ] storage
41 17         43 $self->[ELAPSED] = {}; # elapsed fractional seconds
42 17         42 $self->[LASTTAG] = undef; # what the last tag was
43 17         36 $self->[TAGS] = []; # keep list of tags in order seen
44 17         41 $self->[SKIP] = 0; # how many samples to skip
45 17         39 $self->[MINIMUM] = 1; # the minimum number of trails to run
46 17         41 $self->[SKIPCOUNT] = {}; # trial skip storage
47 17         36 delete $self->[CONFIDENCE]; # confidence factor
48 17         26 delete $self->[ERROR]; # allowable error
49 17         27 delete $self->[STAT]; # stat objects for each tag
50              
51 17 100       57 if(exists $args{skip}) {
52             croak 'argument skip must be a non-negative integer'
53             unless defined $args{skip}
54             and $args{skip} !~ /\D/
55 8 100 100     430 and int $args{skip} == $args{skip};
      66        
56 5         17 $self->[SKIP] = $args{skip};
57 5         14 delete $args{skip};
58             }
59              
60 14 50       41 if(exists $args{minimum}) {
61             croak 'argument minimum must be a non-negative integer'
62             unless defined $args{minimum}
63             and $args{minimum} !~ /\D/
64 0 0 0     0 and int $args{minimum} == $args{minimum};
      0        
65             croak 'argument minimum must greater than or equal to skip'
66             unless defined $args{minimum}
67 0 0 0     0 and $args{minimum} >= $self->[SKIP];
68 0         0 $self->[MINIMUM] = $args{minimum};
69 0         0 delete $args{minimum};
70             }
71              
72             my $confidence_is_valid =
73             (defined $args{confidence}
74             and $args{confidence} =~ /^\d*\.?\d*$/
75             and $args{confidence} > 0
76 14   0     53 and $args{confidence} < 100);
77              
78             my $error_is_valid =
79             (defined $args{error}
80             and $args{error} =~ /^\d*\.?\d*$/
81             and $args{error} > 0
82 14   0     50 and $args{error} < 100);
83              
84 14 50 33     138 if ($confidence_is_valid && !$error_is_valid ||
    50 33        
      33        
      33        
85             !$confidence_is_valid && $error_is_valid)
86             {
87 0         0 carp 'you must specify both confidence and error'
88             }
89             elsif ($confidence_is_valid && $error_is_valid)
90             {
91 0         0 $self->[CONFIDENCE] = $args{confidence};
92 0         0 delete $args{confidence};
93              
94 0         0 $self->[ERROR] = $args{error};
95 0         0 delete $args{error};
96              
97             # Demand load the module we need. We could just
98             # require people to install it...
99             croak 'Could not load the Statistics::PointEstimation module'
100 0 0       0 unless eval {require Statistics::PointEstimation};
  0         0  
101             }
102              
103 14 100       42 if(%args) {
104 1         124 carp 'skipping unknown arguments';
105             }
106              
107 14         60 return $self;
108             }
109              
110              
111             # In this routine we try hard to make the [ gettimeofday ] take place
112             # as late as possible to minimize Heisenberg problems. :)
113              
114             sub start {
115 65     65 1 2109 my $self = shift;
116 65   0     168 my $tag = shift || $self->[LASTTAG] || '_default';
117 65         130 $self->[LASTTAG] = $tag;
118 65 100       149 if(exists $self->[SKIPCOUNT]->{$tag}) {
119 55 100       119 if($self->[SKIPCOUNT]->{$tag} > 1) {
120 26         57 $self->[SKIPCOUNT]->{$tag}--;
121             } else {
122 29         54 $self->[SKIPCOUNT]->{$tag} = 0;
123 29         57 push @{$self->[BEFORE]->{$tag}}, [ gettimeofday ];
  29         141  
124             }
125             } else {
126 10         19 push @{$self->[TAGS]}, $tag;
  10         34  
127 10         38 $self->[SKIPCOUNT]->{$tag} = $self->[SKIP] + 1;
128 10 100       34 if($self->[SKIPCOUNT]->{$tag} > 1) {
129 4         10 $self->[SKIPCOUNT]->{$tag}--;
130             } else {
131 6         16 $self->[SKIPCOUNT]->{$tag} = 0;
132 6         43 $self->[BEFORE]->{$tag} = [ [ gettimeofday ] ]
133             }
134             }
135             }
136              
137              
138             sub stop {
139 67     67 1 377 my $after = [ gettimeofday ]; # minimize overhead
140 67         138 my $self = shift;
141 67   100     286 my $tag = shift || $self->[LASTTAG] || '_default';
142              
143             croak 'must call $t->start($tag) before $t->stop($tag)'
144 67 100       387 unless exists $self->[SKIPCOUNT]->{$tag};
145              
146 66 100       198 return if $self->[SKIPCOUNT]->{$tag} > 0;
147              
148             my $i = exists $self->[ELAPSED]->{$tag} ?
149 36 100       85 scalar @{$self->[ELAPSED]->{$tag}} : 0;
  28         61  
150 36         73 my $before = $self->[BEFORE]->{$tag}->[$i];
151 36 100       161 croak 'timer out of sync' unless defined $before;
152              
153             # Create a stats object if we need to
154 35 50 33     102 if (defined $self->[CONFIDENCE] && !defined $self->[STAT]->{$tag})
155             {
156 0         0 $self->[STAT]->{$tag} = Statistics::PointEstimation->new;
157 0         0 $self->[STAT]->{$tag}->set_significance($self->[CONFIDENCE]);
158             }
159              
160 35         114 my $elapsed = tv_interval($before, $after);
161              
162 35 100       520 if($i > 0) {
163 27         46 push @{$self->[ELAPSED]->{$tag}}, $elapsed;
  27         98  
164             } else {
165 8         61 $self->[ELAPSED]->{$tag} = [ $elapsed ];
166             }
167              
168             $self->[STAT]->{$tag}->add_data($elapsed)
169 35 50       120 if defined $self->[STAT]->{$tag};
170              
171 35         115 return $elapsed;
172             }
173              
174              
175             sub need_more_samples {
176 0     0 1 0 my $self = shift;
177 0   0     0 my $tag = shift || $self->[LASTTAG] || '_default';
178              
179 0 0       0 carp 'You must set the confidence and error in order to use need_more_samples'
180             unless defined $self->[CONFIDENCE];
181              
182             # In case this function is called before any trials are run
183             return 1
184             if !defined $self->[STAT]->{$tag} ||
185 0 0 0     0 $self->[STAT]->{$tag}->count < $self->[MINIMUM];
186              
187             # For debugging
188             # printf STDERR "Average: %.5f +/- %.5f, Samples: %d\n",
189             # $self->[STAT]->{$tag}->mean(), $self->[STAT]->{$tag}->delta(),
190             # $self->[STAT]->{$tag}->count;
191             # printf STDERR "Percent Error: %.5f > %.5f\n",
192             # $self->[STAT]->{$tag}->delta() / $self->[STAT]->{$tag}->mean() * 100,
193             # $self->[ERROR];
194              
195 0         0 return (($self->[STAT]->{$tag}->delta() / $self->[STAT]->{$tag}->mean() * 100) >
196             $self->[ERROR]);
197             }
198              
199              
200             sub report {
201 9     9 1 613 my $self = shift;
202 9   50     34 my $tag = shift || $self->[LASTTAG] || '_default';
203              
204 9 50       25 unless(exists $self->[ELAPSED]->{$tag}) {
205 0         0 carp join ' ', 'tag', $tag, 'still running';
206 0         0 return;
207             }
208              
209 9         29 return $self->_report($tag);
210             }
211              
212              
213              
214             sub reports {
215 4     4 1 2669 my $self = shift;
216              
217 4 100       14 if (wantarray)
218             {
219 2         5 my @reports;
220              
221 2         4 foreach my $tag (@{$self->[TAGS]}) {
  2         7  
222 3         9 push @reports, $tag;
223 3         9 push @reports, $self->report($tag);
224             }
225              
226 2         15 return @reports;
227             }
228             else
229             {
230 2         5 my $report = '';
231              
232 2         12 foreach my $tag (@{$self->[TAGS]}) {
  2         8  
233 3         9 $report .= $self->report($tag);
234             }
235              
236 2         10 return $report;
237             }
238             }
239              
240              
241             sub _report {
242 9     9   12 my $self = shift;
243 9         18 my $tag = shift;
244              
245 9 50       20 unless(exists $self->[ELAPSED]->{$tag}) {
246 0         0 return "Tag $tag is still running or has not completed its skipped runs, skipping\n";
247             }
248              
249 9         16 my $report = '';
250              
251 9         17 my @times = @{$self->[ELAPSED]->{$tag}};
  9         23  
252 9         20 my $n = scalar @times;
253 9         27 my $total = 0; $total += $_ foreach @times;
  9         33  
254              
255 9 100       23 if ($n == 1)
256             {
257 4         12 $report .= sprintf "\%d trial of \%s (\%s total)\n",
258             $n, $tag, _timestr($total);
259             }
260             else
261             {
262 5         13 $report .= sprintf "\%d trials of \%s (\%s total), \%s/trial\n",
263             $n, $tag, _timestr($total), _timestr($total / $n);
264             }
265              
266 9 50       52 if (defined $self->[STAT]->{$tag})
267             {
268 0         0 my $delta = 0;
269             $delta = $self->[STAT]->{$tag}->delta()
270 0 0       0 if defined $self->[STAT]->{$tag}->delta();
271            
272 0         0 $report .= sprintf "Error: +/- \%.5f with \%s confidence\n",
273             $delta, $self->[CONFIDENCE];
274             }
275              
276 9         37 return $report;
277             }
278              
279              
280              
281             sub result {
282 3     3 1 364 my $self = shift;
283 3   0     11 my $tag = shift || $self->[LASTTAG] || '_default';
284 3 50       13 unless(exists $self->[ELAPSED]->{$tag}) {
285 0         0 carp join ' ', 'tag', $tag, 'still running';
286 0         0 return;
287             }
288 3         6 my @times = @{$self->[ELAPSED]->{$tag}};
  3         9  
289 3         6 my $total = 0; $total += $_ foreach @times;
  3         12  
290 3         14 return $total / @times;
291             }
292              
293              
294             sub results {
295 2     2 1 1170 my $self = shift;
296 2         5 my @results;
297 2         4 foreach my $tag (@{$self->[TAGS]}) {
  2         6  
298 2         6 push @results, $tag;
299 2         7 push @results, $self->result($tag);
300             }
301 2 100       10 return wantarray ? @results : \@results;
302             }
303              
304              
305              
306             sub data {
307 10     10 1 2056 my $self = shift;
308 10         23 my $tag = shift;
309 10         20 my @results;
310 10 100       26 if($tag) {
311 8 100       39 if(exists $self->[ELAPSED]->{$tag}) {
312 6         12 @results = @{$self->[ELAPSED]->{$tag}};
  6         20  
313             } else {
314 2         6 @results = ();
315             }
316             } else {
317 2   50     13 @results = map { ( $_ => $self->[ELAPSED]->{$_} || [] ) }
318 2         5 @{$self->[TAGS]};
  2         5  
319             }
320 10 100       52 return wantarray ? @results : \@results;
321             }
322              
323              
324             # ------------------------------------------------------------------------
325             # Internal utility subroutines
326              
327             # _timestr($sec) takes a floating-point number of seconds and formats
328             # it in a sensible way, commifying large numbers of seconds, and
329             # converting to milliseconds if it makes sense. Since Time::HiRes has
330             # at most microsecond resolution, no attempt is made to convert into
331             # anything below that. A unit string is appended to the number.
332              
333             sub _timestr {
334 14     14   31 my $sec = shift;
335 14         20 my $retstr;
336 14 50       62 if($sec >= 1_000) {
    50          
    50          
    50          
337 0         0 $retstr = _commify(int $sec) . 's';
338             } elsif($sec >= 1) {
339 0 0       0 $retstr = sprintf $sec == int $sec ? '%ds' : '%0.3fs', $sec;
340             } elsif($sec >= 0.001) {
341 0         0 my $ms = $sec * 1_000;
342 0 0       0 $retstr = sprintf $ms == int $ms ? '%dms' : '%0.3fms', $ms;
343             } elsif($sec >= 0.000001) {
344 14         54 $retstr = sprintf '%dus', $sec * 1_000_000;
345             } else {
346             # I'll have whatever real-time OS she's having
347 0         0 $retstr = $sec . 's';
348             }
349 14         61 $retstr;
350             }
351              
352              
353             # _commify($num) inserts a grouping comma according to en-US standards
354             # for numbers larger than 1000. For example, the integer 123456 would
355             # be written 123,456. Any fractional part is left untouched.
356              
357             sub _commify {
358 0     0     my $num = shift;
359 0 0         return unless $num =~ /\d/;
360 0 0         return $num if $num < 1_000;
361              
362 0           my $ip = int $num;
363 0           my($fp) = ($num =~ /\.(\d+)/);
364              
365 0           $ip =~ s/(\d\d\d)$/,$1/;
366 0           1 while $ip =~ s/(\d)(\d\d\d),/$1,$2,/;
367              
368 0 0         return $fp ? join '.', $ip, $fp : $ip;
369             }
370              
371             # ------------------------------------------------------------------------
372             # Return true for a valid Perl include
373              
374             1;
375              
376             # ---------------------------------------------------------------------------
377              
378             =head1 NAME
379              
380             Benchmark::Timer - Benchmarking with statistical confidence
381              
382              
383             =head1 SYNOPSIS
384              
385             # Non-statistical usage
386             use Benchmark::Timer;
387             $t = Benchmark::Timer->new(skip => 1);
388              
389             for(1 .. 1000) {
390             $t->start('tag');
391             &long_running_operation();
392             $t->stop('tag');
393             }
394             print $t->report;
395              
396             # --------------------------------------------------------------------
397              
398             # Statistical usage
399             use Benchmark::Timer;
400             $t = Benchmark::Timer->new(skip => 1, confidence => 97.5, error => 2);
401              
402             while($t->need_more_samples('tag')) {
403             $t->start('tag');
404             &long_running_operation();
405             $t->stop('tag');
406             }
407             print $t->report;
408              
409             =head1 DESCRIPTION
410              
411             The Benchmark::Timer class allows you to time portions of code
412             conveniently, as well as benchmark code by allowing timings of repeated
413             trials. It is perfect for when you need more precise information about the
414             running time of portions of your code than the Benchmark module will give
415             you, but don't want to go all out and profile your code.
416              
417             The methodology is simple; create a Benchmark::Timer object, and wrap portions
418             of code that you want to benchmark with C and C method calls.
419             You can supply a tag to those methods if you plan to time multiple portions of
420             code. If you provide error and confidence values, you can also use
421             C to determine, statistically, whether you need to
422             collect more data.
423              
424             After you have run your code, you can obtain information about the running
425             time by calling the C method, or get a descriptive benchmark report
426             by calling C. If you run your code over multiple trials, the
427             average time is reported. This is wonderful for benchmarking time-critical
428             portions of code in a rigorous way. You can also optionally choose to skip any
429             number of initial trials to cut down on initial case irregularities.
430              
431             =head1 METHODS
432              
433             In all of the following methods, C<$tag> refers to the user-supplied name of
434             the code being timed. Unless otherwise specified, $tag defaults to the tag of
435             the last call to C, or "_default" if C was not previously
436             called with a tag.
437              
438             =over 4
439              
440             =item $t = Benchmark::Timer->new( [options] );
441              
442             Constructor for the Benchmark::Timer object; returns a reference to a
443             timer object. Takes the following named arguments:
444              
445             =over 4
446              
447             =item skip
448              
449             The number of trials (if any) to skip before recording timing information.
450              
451             =item minimum
452              
453             The minimum number of trials to run.
454              
455             =item error
456              
457             A percentage between 0 and 100 which indicates how much error you are willing
458             to tolerate in the average time measured by the benchmark. For example, a
459             value of 1 means that you want the reported average time to be within 1% of
460             the real average time. C will use this value to determine
461             when it is okay to stop collecting data.
462              
463             If you specify an error you must also specify a confidence.
464              
465             =item confidence
466              
467             A percentage between 0 and 100 which indicates how confident you want to be in
468             the error measured by the benchmark. For example, a value of 97.5 means that
469             you want to be 97.5% confident that the real average time is within the error
470             margin you have specified. C will use this value to
471             compute the estimated error for the collected data, so that it can determine
472             when it is okay to stop.
473              
474             If you specify a confidence you must also specify an error.
475              
476             =back
477              
478             =item $t->reset;
479              
480             Reset the timer object to the pristine state it started in.
481             Erase all memory of tags and any previously accumulated timings.
482             Returns a reference to the timer object. It takes the same arguments
483             the constructor takes.
484              
485             =item $t->start($tag);
486              
487             Record the current time so that when C is called, we can calculate an
488             elapsed time.
489              
490             =item $t->stop($tag);
491              
492             Record timing information. If $tag is supplied, it must correspond to one
493             given to a previously called C call. It returns the elapsed time in
494             milliseconds. C croaks if the timer gets out of sync (e.g. the number
495             of Cs does not match the number of Cs.)
496              
497             =item $t->need_more_samples($tag);
498              
499             Compute the estimated error in the average of the data collected thus far, and
500             return true if that error exceeds the user-specified error. If a $tag is
501             supplied, it must correspond to one given to a previously called C
502             call.
503              
504             This routine assumes that the data are normally distributed.
505              
506             =item $t->report($tag);
507              
508             Returns a string containing a simple report on the collected timings for $tag.
509             This report contains the number of trials run, the total time taken, and, if
510             more than one trial was run, the average time needed to run one trial and
511             error information. C will complain (via a warning) if a tag is
512             still active.
513              
514             =item $t->reports;
515              
516             In a scalar context, returns a string containing a simple report on the
517             collected timings for all tags. The report is a concatenation of the
518             individual tag reports, in the original tag order. In an list context, returns
519             a hash keyed by tag and containing reports for each tag. The return value is
520             actually an array, so that the original tag order is preserved if you assign
521             to an array instead of a hash. C will complain (via a warning) if a
522             tag is still active.
523              
524             =item $t->result($tag);
525              
526             Return the time it took for $tag to elapse, or the mean time it took for $tag
527             to elapse once, if $tag was used to time code more than once. C will
528             complain (via a warning) if a tag is still active.
529              
530             =item $t->results;
531              
532             Returns the timing data as a hash keyed on tags where each value is
533             the time it took to run that code, or the average time it took,
534             if that code ran more than once. In scalar context it returns a reference
535             to that hash. The return value is actually an array, so that the original
536             tag order is preserved if you assign to an array instead of a hash.
537              
538             =item $t->data($tag), $t->data;
539              
540             These methods are useful if you want to recover the full internal timing
541             data to roll your own reports.
542              
543             If called with a $tag, returns the raw timing data for that $tag as
544             an array (or a reference to an array if called in scalar context). This is
545             useful for feeding to something like the Statistics::Descriptive package.
546              
547             If called with no arguments, returns the raw timing data as a hash keyed
548             on tags, where the values of the hash are lists of timings for that
549             code. In scalar context, it returns a reference to that hash. As with
550             C, the data is internally represented as an array so you can
551             recover the original tag order by assigning to an array instead of a hash.
552              
553             =back
554              
555             =head1 BUGS
556              
557             Benchmarking is an inherently futile activity, fraught with uncertainty
558             not dissimilar to that experienced in quantum mechanics. But things are a
559             little better if you apply statistics.
560              
561             =head1 LICENSE
562              
563             This code is distributed under the GNU General Public License (GPL) Version 2.
564             See the file LICENSE in the distribution for details.
565              
566             =head1 AUTHOR
567              
568             The original code (written before April 20, 2001) was written by Andrew Ho
569             Eandrew@zeuscat.comE, and is copyright (c) 2000-2001 Andrew Ho.
570             Versions up to 0.5 are distributed under the same terms as Perl.
571              
572             Maintenance of this module is now being done by David Coppit
573             Edavid@coppit.orgE.
574              
575             =head1 SEE ALSO
576              
577             L, L, L, L
578              
579             =cut