f4a81495a0eee6451d056b012c575cb0eb09397c
[p5sagit/p5-mst-13.2.git] / lib / Benchmark.pm
1 package Benchmark;
2
3 =head1 NAME
4
5 Benchmark - benchmark running times of code
6
7 timethis - run a chunk of code several times
8
9 timethese - run several chunks of code several times
10
11 timeit - run a chunk of code and see how long it goes
12
13 =head1 SYNOPSIS
14
15     timethis ($count, "code");
16
17     # Use Perl code in strings...
18     timethese($count, {
19         'Name1' => '...code1...',
20         'Name2' => '...code2...',
21     });
22
23     # ... or use subroutine references.
24     timethese($count, {
25         'Name1' => sub { ...code1... },
26         'Name2' => sub { ...code2... },
27     });
28
29     $t = timeit($count, '...other code...')
30     print "$count loops of other code took:",timestr($t),"\n";
31
32 =head1 DESCRIPTION
33
34 The Benchmark module encapsulates a number of routines to help you
35 figure out how long it takes to execute some code.
36
37 =head2 Methods
38
39 =over 10
40
41 =item new
42
43 Returns the current time.   Example:
44
45     use Benchmark;
46     $t0 = new Benchmark;
47     # ... your code here ...
48     $t1 = new Benchmark;
49     $td = timediff($t1, $t0);
50     print "the code took:",timestr($td),"\n";
51
52 =item debug
53
54 Enables or disable debugging by setting the C<$Benchmark::Debug> flag:
55
56     debug Benchmark 1;
57     $t = timeit(10, ' 5 ** $Global ');
58     debug Benchmark 0;
59
60 =back
61
62 =head2 Standard Exports
63
64 The following routines will be exported into your namespace
65 if you use the Benchmark module:
66
67 =over 10
68
69 =item timeit(COUNT, CODE)
70
71 Arguments: COUNT is the number of times to run the loop, and CODE is
72 the code to run.  CODE may be either a code reference or a string to
73 be eval'd; either way it will be run in the caller's package.
74
75 Returns: a Benchmark object.
76
77 =item timethis ( COUNT, CODE, [ TITLE, [ STYLE ]] )
78
79 Time COUNT iterations of CODE. CODE may be a string to eval or a
80 code reference; either way the CODE will run in the caller's package.
81 Results will be printed to STDOUT as TITLE followed by the times.
82 TITLE defaults to "timethis COUNT" if none is provided. STYLE
83 determines the format of the output, as described for timestr() below.
84
85 The COUNT can be zero or negative: this means the I<minimum number of
86 CPU seconds> to run.  A zero signifies the default of 3 seconds.  For
87 example to run at least for 10 seconds:
88
89         timethis(-10, $code)
90
91 or to run two pieces of code tests for at least 3 seconds:
92
93         timethese(0, { test1 => '...', test2 => '...'})
94
95 CPU seconds is, in UNIX terms, the user time plus the system time of
96 the process itself, as opposed to the real (wallclock) time and the
97 time spent by the child processes.  Less than 0.1 seconds is not
98 accepted (-0.01 as the count, for example, will cause a fatal runtime
99 exception).
100
101 Note that the CPU seconds is the B<minimum> time: CPU scheduling and
102 other operating system factors may complicate the attempt so that a
103 little bit more time is spent.  The benchmark output will, however,
104 also tell the number of C<$code> runs/second, which should be a more
105 interesting number than the actually spent seconds.
106
107 Returns a Benchmark object.
108
109 =item timethese ( COUNT, CODEHASHREF, [ STYLE ] )
110
111 The CODEHASHREF is a reference to a hash containing names as keys
112 and either a string to eval or a code reference for each value.
113 For each (KEY, VALUE) pair in the CODEHASHREF, this routine will
114 call
115
116         timethis(COUNT, VALUE, KEY, STYLE)
117
118 The routines are called in string comparison order of KEY.
119
120 The COUNT can be zero or negative, see timethis().
121
122 Returns a hash of Benchmark objects, keyed by name.
123
124 =item timediff ( T1, T2 )
125
126 Returns the difference between two Benchmark times as a Benchmark
127 object suitable for passing to timestr().
128
129 =item timesum ( T1, T2 )
130
131 Returns the sum of two Benchmark times as a Benchmark object suitable
132 for passing to timestr().
133
134 =item timestr ( TIMEDIFF, [ STYLE, [ FORMAT ] ] )
135
136 Returns a string that formats the times in the TIMEDIFF object in
137 the requested STYLE. TIMEDIFF is expected to be a Benchmark object
138 similar to that returned by timediff().
139
140 STYLE can be any of 'all', 'none', 'noc', 'nop' or 'auto'. 'all' shows
141 each of the 5 times available ('wallclock' time, user time, system time,
142 user time of children, and system time of children). 'noc' shows all
143 except the two children times. 'nop' shows only wallclock and the
144 two children times. 'auto' (the default) will act as 'all' unless
145 the children times are both zero, in which case it acts as 'noc'.
146 'none' prevents output.
147
148 FORMAT is the L<printf(3)>-style format specifier (without the
149 leading '%') to use to print the times. It defaults to '5.2f'.
150
151 =back
152
153 =head2 Optional Exports
154
155 The following routines will be exported into your namespace
156 if you specifically ask that they be imported:
157
158 =over 10
159
160 =item clearcache ( COUNT )
161
162 Clear the cached time for COUNT rounds of the null loop.
163
164 =item clearallcache ( )
165
166 Clear all cached times.
167
168 =item cmpthese ( COUT, CODEHASHREF, [ STYLE ] )
169
170 =item cmpthese ( RESULTSHASHREF )
171
172 Optionally calls timethese(), then outputs comparison chart.  This 
173 chart is sorted from slowest to highest, and shows the percent 
174 speed difference between each pair of tests.  Can also be passed 
175 the data structure that timethese() returns:
176
177     $results = timethese( .... );
178     cmpthese( $results );
179
180 Returns the data structure returned by timethese().
181
182 =item disablecache ( )
183
184 Disable caching of timings for the null loop. This will force Benchmark
185 to recalculate these timings for each new piece of code timed.
186
187 =item enablecache ( )
188
189 Enable caching of timings for the null loop. The time taken for COUNT
190 rounds of the null loop will be calculated only once for each
191 different COUNT used.
192
193 =back
194
195 =head1 NOTES
196
197 The data is stored as a list of values from the time and times
198 functions:
199
200       ($real, $user, $system, $children_user, $children_system)
201
202 in seconds for the whole loop (not divided by the number of rounds).
203
204 The timing is done using time(3) and times(3).
205
206 Code is executed in the caller's package.
207
208 The time of the null loop (a loop with the same
209 number of rounds but empty loop body) is subtracted
210 from the time of the real loop.
211
212 The null loop times can be cached, the key being the
213 number of rounds. The caching can be controlled using
214 calls like these:
215
216     clearcache($key);
217     clearallcache();
218
219     disablecache();
220     enablecache();
221
222 Caching is off by default, as it can (usually slightly) decrease
223 accuracy and does not usually noticably affect runtimes.
224
225 =head1 INHERITANCE
226
227 Benchmark inherits from no other class, except of course
228 for Exporter.
229
230 =head1 CAVEATS
231
232 Comparing eval'd strings with code references will give you
233 inaccurate results: a code reference will show a slower
234 execution time than the equivalent eval'd string.
235
236 The real time timing is done using time(2) and
237 the granularity is therefore only one second.
238
239 Short tests may produce negative figures because perl
240 can appear to take longer to execute the empty loop
241 than a short test; try:
242
243     timethis(100,'1');
244
245 The system time of the null loop might be slightly
246 more than the system time of the loop with the actual
247 code and therefore the difference might end up being E<lt> 0.
248
249 =head1 AUTHORS
250
251 Jarkko Hietaniemi <F<jhi@iki.fi>>, Tim Bunce <F<Tim.Bunce@ig.co.uk>>
252
253 =head1 MODIFICATION HISTORY
254
255 September 8th, 1994; by Tim Bunce.
256
257 March 28th, 1997; by Hugo van der Sanden: added support for code
258 references and the already documented 'debug' method; revamped
259 documentation.
260
261 April 04-07th, 1997: by Jarkko Hietaniemi, added the run-for-some-time
262 functionality.
263
264 September, 1999; by Barrie Slaymaker: math fixes and accuracy and 
265 efficiency tweaks.  Added cmpthese().  A result is now returned from 
266 timethese().
267
268 =cut
269
270 # evaluate something in a clean lexical environment
271 sub _doeval { eval shift }
272
273 #
274 # put any lexicals at file scope AFTER here
275 #
276
277 use Carp;
278 use Exporter;
279 @ISA=(Exporter);
280 @EXPORT=qw(timeit timethis timethese timediff timesum timestr);
281 @EXPORT_OK=qw(clearcache clearallcache cmpthese disablecache enablecache);
282
283 &init;
284
285 sub init {
286     $debug = 0;
287     $min_count = 4;
288     $min_cpu   = 0.4;
289     $defaultfmt = '5.2f';
290     $defaultstyle = 'auto';
291     # The cache can cause a slight loss of sys time accuracy. If a
292     # user does many tests (>10) with *very* large counts (>10000)
293     # or works on a very slow machine the cache may be useful.
294     &disablecache;
295     &clearallcache;
296 }
297
298 sub debug { $debug = ($_[1] != 0); }
299
300 # The cache needs two branches: 's' for strings and 'c' for code.  The
301 # emtpy loop is different in these two cases.
302 sub clearcache    { delete $cache{"$_[0]c"}; delete $cache{"$_[0]s"}; }
303 sub clearallcache { %cache = (); }
304 sub enablecache   { $cache = 1; }
305 sub disablecache  { $cache = 0; }
306
307 # --- Functions to process the 'time' data type
308
309 sub new { my @t = (time, times, @_ == 2 ? $_[1] : 0);
310           print "new=@t\n" if $debug;
311           bless \@t; }
312
313 sub cpu_p { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps         ; }
314 sub cpu_c { my($r,$pu,$ps,$cu,$cs) = @{$_[0]};         $cu+$cs ; }
315 sub cpu_a { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps+$cu+$cs ; }
316 sub real  { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $r              ; }
317
318 sub timediff {
319     my($a, $b) = @_;
320     my @r;
321     for (my $i=0; $i < @$a; ++$i) {
322         push(@r, $a->[$i] - $b->[$i]);
323     }
324     bless \@r;
325 }
326
327 sub timesum {
328      my($a, $b) = @_;
329      my @r;
330      for (my $i=0; $i < @$a; ++$i) {
331         push(@r, $a->[$i] + $b->[$i]);
332      }
333      bless \@r;
334 }
335
336 sub timestr {
337     my($tr, $style, $f) = @_;
338     my @t = @$tr;
339     warn "bad time value (@t)" unless @t==6;
340     my($r, $pu, $ps, $cu, $cs, $n) = @t;
341     my($pt, $ct, $t) = ($tr->cpu_p, $tr->cpu_c, $tr->cpu_a);
342     $f = $defaultfmt unless defined $f;
343     # format a time in the required style, other formats may be added here
344     $style ||= $defaultstyle;
345     $style = ($ct>0) ? 'all' : 'noc' if $style eq 'auto';
346     my $s = "@t $style"; # default for unknown style
347     $s=sprintf("%2d wallclock secs (%$f usr %$f sys + %$f cusr %$f csys = %$f CPU)",
348                             @t,$t) if $style eq 'all';
349     $s=sprintf("%2d wallclock secs (%$f usr + %$f sys = %$f CPU)",
350                             $r,$pu,$ps,$pt) if $style eq 'noc';
351     $s=sprintf("%2d wallclock secs (%$f cusr + %$f csys = %$f CPU)",
352                             $r,$cu,$cs,$ct) if $style eq 'nop';
353     $s .= sprintf(" @ %$f/s (n=$n)", $n / ( $pu + $ps )) if $n;
354     $s;
355 }
356
357 sub timedebug {
358     my($msg, $t) = @_;
359     print STDERR "$msg",timestr($t),"\n" if $debug;
360 }
361
362 # --- Functions implementing low-level support for timing loops
363
364 sub runloop {
365     my($n, $c) = @_;
366
367     $n+=0; # force numeric now, so garbage won't creep into the eval
368     croak "negative loopcount $n" if $n<0;
369     confess "Usage: runloop(number, [string | coderef])" unless defined $c;
370     my($t0, $t1, $td); # before, after, difference
371
372     # find package of caller so we can execute code there
373     my($curpack) = caller(0);
374     my($i, $pack)= 0;
375     while (($pack) = caller(++$i)) {
376         last if $pack ne $curpack;
377     }
378
379     my ($subcode, $subref);
380     if (ref $c eq 'CODE') {
381         $subcode = "sub { for (1 .. $n) { local \$_; package $pack; &\$c; } }";
382         $subref  = eval $subcode;
383     }
384     else {
385         $subcode = "sub { for (1 .. $n) { local \$_; package $pack; $c;} }";
386         $subref  = _doeval($subcode);
387     }
388     croak "runloop unable to compile '$c': $@\ncode: $subcode\n" if $@;
389     print STDERR "runloop $n '$subcode'\n" if $debug;
390
391     # Wait for the user timer to tick.  This makes the error range more like 
392     # -0.01, +0.  If we don't wait, then it's more like -0.01, +0.01.  This
393     # may not seem important, but it significantly reduces the chances of
394     # getting a too low initial $n in the initial, 'find the minimum' loop
395     # in &runfor.  This, in turn, can reduce the number of calls to
396     # &runloop a lot, and thus reduce additive errors.
397     my $tbase = Benchmark->new(0)->[1];
398     do {
399        $t0 = Benchmark->new(0);
400     } while ( $t0->[1] == $tbase );
401     &$subref;
402     $t1 = Benchmark->new($n);
403     $td = &timediff($t1, $t0);
404     timedebug("runloop:",$td);
405     $td;
406 }
407
408
409 sub timeit {
410     my($n, $code) = @_;
411     my($wn, $wc, $wd);
412
413     printf STDERR "timeit $n $code\n" if $debug;
414     my $cache_key = $n . ( ref( $code ) ? 'c' : 's' );
415     if ($cache && exists $cache{$cache_key} ) {
416         $wn = $cache{$cache_key};
417     } else {
418         $wn = &runloop($n, ref( $code ) ? sub { undef } : '' );
419         # Can't let our baseline have any iterations, or they get subtracted
420         # out of the result.
421         $wn->[5] = 0;
422         $cache{$cache_key} = $wn;
423     }
424
425     $wc = &runloop($n, $code);
426
427     $wd = timediff($wc, $wn);
428     timedebug("timeit: ",$wc);
429     timedebug("      - ",$wn);
430     timedebug("      = ",$wd);
431
432     $wd;
433 }
434
435
436 my $default_for = 3;
437 my $min_for     = 0.1;
438
439
440 sub runfor {
441     my ($code, $tmax) = @_;
442
443     if ( not defined $tmax or $tmax == 0 ) {
444         $tmax = $default_for;
445     } elsif ( $tmax < 0 ) {
446         $tmax = -$tmax;
447     }
448
449     die "runfor(..., $tmax): timelimit cannot be less than $min_for.\n"
450         if $tmax < $min_for;
451
452     my ($n, $tc);
453
454     # First find the minimum $n that gives a significant timing.
455     for ($n = 1; ; $n *= 2 ) {
456         my $td = timeit($n, $code);
457         $tc = $td->[1] + $td->[2];
458         last if $tc > 0.1;
459     }
460
461     my $nmin = $n;
462
463     # Get $n high enough that we can guess the final $n with some accuracy.
464     my $tpra = 0.1 * $tmax; # Target/time practice.
465     while ( $tc < $tpra ) {
466         # The 5% fudge is to keep us from iterating again all
467         # that often (this speeds overall responsiveness when $tmax is big
468         # and we guess a little low).  This does not noticably affect 
469         # accuracy since we're not couting these times.
470         $n = int( $tpra * 1.05 * $n / $tc ); # Linear approximation.
471         my $td = timeit($n, $code);
472         $tc = $td->[1] + $td->[2];
473     }
474
475     # Now, do the 'for real' timing(s), repeating until we exceed
476     # the max.
477     my $ntot  = 0;
478     my $rtot  = 0;
479     my $utot  = 0.0;
480     my $stot  = 0.0;
481     my $cutot = 0.0;
482     my $cstot = 0.0;
483     my $ttot  = 0.0;
484
485     # The 5% fudge is because $n is often a few % low even for routines
486     # with stable times and avoiding extra timeit()s is nice for
487     # accuracy's sake.
488     $n = int( $n * ( 1.05 * $tmax / $tc ) );
489
490     while () {
491         my $td = timeit($n, $code);
492         $ntot  += $n;
493         $rtot  += $td->[0];
494         $utot  += $td->[1];
495         $stot  += $td->[2];
496         $cutot += $td->[3];
497         $cstot += $td->[4];
498         $ttot = $utot + $stot;
499         last if $ttot >= $tmax;
500
501         my $r = $tmax / $ttot - 1; # Linear approximation.
502         $n = int( $r * $ntot );
503         $n = $nmin if $n < $nmin;
504     }
505
506     return bless [ $rtot, $utot, $stot, $cutot, $cstot, $ntot ];
507 }
508
509 # --- Functions implementing high-level time-then-print utilities
510
511 sub n_to_for {
512     my $n = shift;
513     return $n == 0 ? $default_for : $n < 0 ? -$n : undef;
514 }
515
516 sub timethis{
517     my($n, $code, $title, $style) = @_;
518     my($t, $for, $forn);
519
520     if ( $n > 0 ) {
521         croak "non-integer loopcount $n, stopped" if int($n)<$n;
522         $t = timeit($n, $code);
523         $title = "timethis $n" unless defined $title;
524     } else {
525         $fort  = n_to_for( $n );
526         $t     = runfor($code, $fort);
527         $title = "timethis for $fort" unless defined $title;
528         $forn  = $t->[-1];
529     }
530     local $| = 1;
531     $style = "" unless defined $style;
532     printf("%10s: ", $title) unless $style eq 'none';
533     print timestr($t, $style, $defaultfmt),"\n" unless $style eq 'none';
534
535     $n = $forn if defined $forn;
536
537     # A conservative warning to spot very silly tests.
538     # Don't assume that your benchmark is ok simply because
539     # you don't get this warning!
540     print "            (warning: too few iterations for a reliable count)\n"
541         if     $n < $min_count
542             || ($t->real < 1 && $n < 1000)
543             || $t->cpu_a < $min_cpu;
544     $t;
545 }
546
547 sub timethese{
548     my($n, $alt, $style) = @_;
549     die "usage: timethese(count, { 'Name1'=>'code1', ... }\n"
550                 unless ref $alt eq HASH;
551     my @names = sort keys %$alt;
552     $style = "" unless defined $style;
553     print "Benchmark: " unless $style eq 'none';
554     if ( $n > 0 ) {
555         croak "non-integer loopcount $n, stopped" if int($n)<$n;
556         print "timing $n iterations of" unless $style eq 'none';
557     } else {
558         print "running" unless $style eq 'none';
559     }
560     print " ", join(', ',@names) unless $style eq 'none';
561     unless ( $n > 0 ) {
562         my $for = n_to_for( $n );
563         print ", each for at least $for CPU seconds" unless $style eq 'none';
564     }
565     print "...\n" unless $style eq 'none';
566
567     # we could save the results in an array and produce a summary here
568     # sum, min, max, avg etc etc
569     my %results;
570     foreach my $name (@names) {
571         $results{$name} = timethis ($n, $alt -> {$name}, $name, $style);
572     }
573
574     return \%results;
575 }
576
577 sub cmpthese{
578     my $results = ref $_[0] ? $_[0] : timethese( @_ );
579
580     return $results
581        if defined $_[2] && $_[2] eq 'none';
582
583     # Flatten in to an array of arrays with the name as the first field
584     my @vals = map{ [ $_, @{$results->{$_}} ] } keys %$results;
585
586     for (@vals) {
587         # The epsilon fudge here is to prevent div by 0.  Since clock
588         # resolutions are much larger, it's below the noise floor.
589         my $rate = $_->[6] / ( $_->[2] + $_->[3] + 0.000000000000001 );
590         $_->[7] = $rate;
591     }
592
593     # Sort by rate
594     @vals = sort { $a->[7] <=> $b->[7] } @vals;
595
596     # If more than half of the rates are greater than one...
597     my $display_as_rate = $vals[$#vals>>1]->[7] > 1;
598
599     my @rows;
600     my @col_widths;
601
602     my @top_row = ( 
603         '', 
604         $display_as_rate ? 'Rate' : 's/iter', 
605         map { $_->[0] } @vals 
606     );
607
608     push @rows, \@top_row;
609     @col_widths = map { length( $_ ) } @top_row;
610
611     # Build the data rows
612     # We leave the last column in even though it never has any data.  Perhaps
613     # it should go away.  Also, perhaps a style for a single column of
614     # percentages might be nice.
615     for my $row_val ( @vals ) {
616         my @row;
617
618         # Column 0 = test name
619         push @row, $row_val->[0];
620         $col_widths[0] = length( $row_val->[0] )
621             if length( $row_val->[0] ) > $col_widths[0];
622
623         # Column 1 = performance
624         my $row_rate = $row_val->[7];
625
626         # We assume that we'll never get a 0 rate.
627         my $a = $display_as_rate ? $row_rate : 1 / $row_rate;
628
629         # Only give a few decimal places before switching to sci. notation,
630         # since the results aren't usually that accurate anyway.
631         my $format = 
632            $a >= 100 ? 
633                "%0.0f" : 
634            $a >= 10 ?
635                "%0.1f" :
636            $a >= 1 ?
637                "%0.2f" :
638            $a >= 0.1 ?
639                "%0.3f" :
640                "%0.2e";
641
642         $format .= "/s"
643             if $display_as_rate;
644         # Using $b here due to optimizing bug in _58 through _61
645         my $b = sprintf( $format, $a );
646         push @row, $b;
647         $col_widths[1] = length( $b )
648             if length( $b ) > $col_widths[1];
649
650         # Columns 2..N = performance ratios
651         my $skip_rest = 0;
652         for ( my $col_num = 0 ; $col_num < @vals ; ++$col_num ) {
653             my $col_val = $vals[$col_num];
654             my $out;
655             if ( $skip_rest ) {
656                 $out = '';
657             }
658             elsif ( $col_val->[0] eq $row_val->[0] ) {
659                 $out = "--";
660                 # $skip_rest = 1;
661             }
662             else {
663                 my $col_rate = $col_val->[7];
664                 $out = sprintf( "%.0f%%", 100*$row_rate/$col_rate - 100 );
665             }
666             push @row, $out;
667             $col_widths[$col_num+2] = length( $out )
668                 if length( $out ) > $col_widths[$col_num+2];
669
670             # A little wierdness to set the first column width properly
671             $col_widths[$col_num+2] = length( $col_val->[0] )
672                 if length( $col_val->[0] ) > $col_widths[$col_num+2];
673         }
674         push @rows, \@row;
675     }
676
677     # Equalize column widths in the chart as much as possible without
678     # exceeding 80 characters.  This does not use or affect cols 0 or 1.
679     my @sorted_width_refs = 
680        sort { $$a <=> $$b } map { \$_ } @col_widths[2..$#col_widths];
681     my $max_width = ${$sorted_width_refs[-1]};
682
683     my $total = 0;
684     for ( @col_widths ) { $total += $_ }
685
686     STRETCHER:
687     while ( $total < 80 ) {
688         my $min_width = ${$sorted_width_refs[0]};
689         last
690            if $min_width == $max_width;
691         for ( @sorted_width_refs ) {
692             last 
693                 if $$_ > $min_width;
694             ++$$_;
695             ++$total;
696             last STRETCHER
697                 if $total >= 80;
698         }
699     }
700
701     # Dump the output
702     my $format = join( ' ', map { "%${_}s" } @col_widths ) . "\n";
703     substr( $format, 1, 0 ) = '-';
704     for ( @rows ) {
705         printf $format, @$_;
706     }
707
708     return $results;
709 }
710
711
712 1;