File Coverage

blib/lib/Benchmark/Timer.pm
Criterion Covered Total %
statement 165 203 81.2
branch 47 82 57.3
condition 16 51 31.3
subroutine 25 27 92.5
pod 10 12 83.3
total 263 375 70.1


line stmt bran cond sub pod time code
1             package Benchmark::Timer;
2             require 5.005;
3 5     5   84397 use strict;
  5         9  
  5         201  
4              
5 5     5   24 use Carp;
  5         6  
  5         400  
6 5     5   2020 use Time::HiRes qw( gettimeofday tv_interval );
  5         5142  
  5         23  
7              
8 5     5   871 use vars qw($VERSION);
  5         7  
  5         373  
9             $VERSION = sprintf "%d.%02d%02d", q/0.71.7/ =~ /(\d+)/g;
10              
11 5     5   25 use constant BEFORE => 0;
  5         7  
  5         360  
12 5     5   22 use constant ELAPSED => 1;
  5         5  
  5         202  
13 5     5   20 use constant LASTTAG => 2;
  5         5  
  5         201  
14 5     5   26 use constant TAGS => 3;
  5         13  
  5         207  
15 5     5   19 use constant SKIP => 4;
  5         9  
  5         187  
16 5     5   50 use constant MINIMUM => 5;
  5         9  
  5         191  
17 5     5   21 use constant SKIPCOUNT => 6;
  5         15  
  5         213  
18 5     5   19 use constant CONFIDENCE => 7;
  5         7  
  5         184  
19 5     5   16 use constant ERROR => 8;
  5         7  
  5         260  
20 5     5   26 use constant STAT => 9;
  5         5  
  5         11019  
21              
22             # ------------------------------------------------------------------------
23             # Constructor
24              
25             sub new {
26 14     14 1 7190 my $class = shift;
27 14         34 my $self = [];
28 14         33 bless $self, $class;
29 14         40 return $self->reset(@_);
30             }
31              
32              
33             # ------------------------------------------------------------------------
34             # Public methods
35              
36             sub reset {
37 17     17 1 458 my $self = shift;
38 17         39 my %args = @_;
39              
40 17         50 $self->[BEFORE] = {}; # [ gettimeofday ] storage
41 17         30 $self->[ELAPSED] = {}; # elapsed fractional seconds
42 17         22 $self->[LASTTAG] = undef; # what the last tag was
43 17         23 $self->[TAGS] = []; # keep list of tags in order seen
44 17         24 $self->[SKIP] = 0; # how many samples to skip
45 17         26 $self->[MINIMUM] = 1; # the minimum number of trails to run
46 17         26 $self->[SKIPCOUNT] = {}; # trial skip storage
47 17         74 delete $self->[CONFIDENCE]; # confidence factor
48 17         18 delete $self->[ERROR]; # allowable error
49 17         21 delete $self->[STAT]; # stat objects for each tag
50              
51 17 100       45 if(exists $args{skip}) {
52 8 100 100     371 croak 'argument skip must be a non-negative integer'
      66        
53             unless defined $args{skip}
54             and $args{skip} !~ /\D/
55             and int $args{skip} == $args{skip};
56 5         8 $self->[SKIP] = $args{skip};
57 5         10 delete $args{skip};
58             }
59              
60 14 50       32 if(exists $args{minimum}) {
61 0 0 0     0 croak 'argument minimum must be a non-negative integer'
      0        
62             unless defined $args{minimum}
63             and $args{minimum} !~ /\D/
64             and int $args{minimum} == $args{minimum};
65 0 0 0     0 croak 'argument minimum must greater than or equal to skip'
66             unless defined $args{minimum}
67             and $args{minimum} >= $self->[SKIP];
68 0         0 $self->[MINIMUM] = $args{minimum};
69 0         0 delete $args{minimum};
70             }
71              
72 14   0     54 my $confidence_is_valid =
73             (defined $args{confidence}
74             and $args{confidence} =~ /^\d*\.?\d*$/
75             and $args{confidence} > 0
76             and $args{confidence} < 100);
77              
78 14   0     53 my $error_is_valid =
79             (defined $args{error}
80             and $args{error} =~ /^\d*\.?\d*$/
81             and $args{error} > 0
82             and $args{error} < 100);
83              
84 14 50 33     125 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 0 0       0 croak 'Could not load the Statistics::PointEstimation module'
100             unless eval "require Statistics::PointEstimation";
101             }
102              
103 14 100       29 if(%args) {
104 1         85 carp 'skipping unknown arguments';
105             }
106              
107 14         43 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 1212 my $self = shift;
116 65   50     126 my $tag = shift || $self->[LASTTAG] || '_default';
117 65         93 $self->[LASTTAG] = $tag;
118 65 100       106 if(exists $self->[SKIPCOUNT]->{$tag}) {
119 55 100       85 if($self->[SKIPCOUNT]->{$tag} > 1) {
120 26         50 $self->[SKIPCOUNT]->{$tag}--;
121             } else {
122 29         33 $self->[SKIPCOUNT]->{$tag} = 0;
123 29         23 push @{$self->[BEFORE]->{$tag}}, [ gettimeofday ];
  29         114  
124             }
125             } else {
126 10         13 push @{$self->[TAGS]}, $tag;
  10         18  
127 10         35 $self->[SKIPCOUNT]->{$tag} = $self->[SKIP] + 1;
128 10 100       26 if($self->[SKIPCOUNT]->{$tag} > 1) {
129 4         12 $self->[SKIPCOUNT]->{$tag}--;
130             } else {
131 6         12 $self->[SKIPCOUNT]->{$tag} = 0;
132 6         56 $self->[BEFORE]->{$tag} = [ [ gettimeofday ] ]
133             }
134             }
135             }
136              
137              
138             sub stop {
139 67     67 1 265 my $after = [ gettimeofday ]; # minimize overhead
140 67         66 my $self = shift;
141 67   100     239 my $tag = shift || $self->[LASTTAG] || '_default';
142              
143 67 100       327 croak 'must call $t->start($tag) before $t->stop($tag)'
144             unless exists $self->[SKIPCOUNT]->{$tag};
145              
146 66 100       152 return if $self->[SKIPCOUNT]->{$tag} > 0;
147              
148 28         41 my $i = exists $self->[ELAPSED]->{$tag} ?
149 36 100       68 scalar @{$self->[ELAPSED]->{$tag}} : 0;
150 36         50 my $before = $self->[BEFORE]->{$tag}->[$i];
151 36 100       143 croak 'timer out of sync' unless defined $before;
152              
153             # Create a stats object if we need to
154 35 50 33     67 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         82 my $elapsed = tv_interval($before, $after);
161              
162 35 100       315 if($i > 0) {
163 27         25 push @{$self->[ELAPSED]->{$tag}}, $elapsed;
  27         55  
164             } else {
165 8         21 $self->[ELAPSED]->{$tag} = [ $elapsed ];
166             }
167              
168 35 50       76 $self->[STAT]->{$tag}->add_data($elapsed)
169             if defined $self->[STAT]->{$tag};
170              
171 35         64 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 0 0 0     0 return 1
184             if !defined $self->[STAT]->{$tag} ||
185             $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 678 my $self = shift;
202 9   50     22 my $tag = shift || $self->[LASTTAG] || '_default';
203              
204 9 50       16 unless(exists $self->[ELAPSED]->{$tag}) {
205 0         0 carp join ' ', 'tag', $tag, 'still running';
206 0         0 return;
207             }
208              
209 9         16 return $self->_report($tag);
210             }
211              
212              
213              
214             sub reports {
215 4     4 1 1447 my $self = shift;
216              
217 4 100       7 if (wantarray)
218             {
219 2         3 my @reports;
220              
221 2         3 foreach my $tag (@{$self->[TAGS]}) {
  2         3  
222 3         4 push @reports, $tag;
223 3         5 push @reports, $self->report($tag);
224             }
225              
226 2         8 return @reports;
227             }
228             else
229             {
230 2         2 my $report = '';
231              
232 2         2 foreach my $tag (@{$self->[TAGS]}) {
  2         4  
233 3         4 $report .= $self->report($tag);
234             }
235              
236 2         5 return $report;
237             }
238             }
239              
240              
241             sub _report {
242 9     9   6 my $self = shift;
243 9         7 my $tag = shift;
244              
245 9 50       14 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         7 my $report = '';
250              
251 9         7 my @times = @{$self->[ELAPSED]->{$tag}};
  9         18  
252 9         6 my $n = scalar @times;
253 9         6 my $total = 0; $total += $_ foreach @times;
  9         24  
254              
255 9 100       14 if ($n == 1)
256             {
257 4         6 $report .= sprintf "\%d trial of \%s (\%s total)\n",
258             $n, $tag, timestr($total);
259             }
260             else
261             {
262 5         8 $report .= sprintf "\%d trials of \%s (\%s total), \%s/trial\n",
263             $n, $tag, timestr($total), timestr($total / $n);
264             }
265              
266 9 50       18 if (defined $self->[STAT]->{$tag})
267             {
268 0         0 my $delta = 0;
269 0 0       0 $delta = $self->[STAT]->{$tag}->delta()
270             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         21 return $report;
277             }
278              
279              
280              
281             sub result {
282 3     3 1 301 my $self = shift;
283 3   50     12 my $tag = shift || $self->[LASTTAG] || '_default';
284 3 50       10 unless(exists $self->[ELAPSED]->{$tag}) {
285 0         0 carp join ' ', 'tag', $tag, 'still running';
286 0         0 return;
287             }
288 3         4 my @times = @{$self->[ELAPSED]->{$tag}};
  3         8  
289 3         4 my $total = 0; $total += $_ foreach @times;
  3         12  
290 3         11 return $total / @times;
291             }
292              
293              
294             sub results {
295 2     2 1 850 my $self = shift;
296 2         3 my @results;
297 2         2 foreach my $tag (@{$self->[TAGS]}) {
  2         6  
298 2         3 push @results, $tag;
299 2         5 push @results, $self->result($tag);
300             }
301 2 100       9 return wantarray ? @results : \@results;
302             }
303              
304              
305              
306             sub data {
307 10     10 1 1487 my $self = shift;
308 10         13 my $tag = shift;
309 10         8 my @results;
310 10 100       22 if($tag) {
311 8 100       16 if(exists $self->[ELAPSED]->{$tag}) {
312 6         9 @results = @{$self->[ELAPSED]->{$tag}};
  6         19  
313             } else {
314 2         4 @results = ();
315             }
316             } else {
317 2   50     12 @results = map { ( $_ => $self->[ELAPSED]->{$_} || [] ) }
  2         6  
318 2         3 @{$self->[TAGS]};
319             }
320 10 100       41 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 0 14 my $sec = shift;
335 14         7 my $retstr;
336 14 50       34 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         36 $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         32 $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 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