MPE/iX Perl 5.005_02 oops
[p5sagit/p5-mst-13.2.git] / lib / Benchmark.pm
CommitLineData
a0d0e21e 1package Benchmark;
2
f06db76b 3=head1 NAME
4
5Benchmark - benchmark running times of code
6
7timethis - run a chunk of code several times
8
9timethese - run several chunks of code several times
10
11timeit - run a chunk of code and see how long it goes
12
13=head1 SYNOPSIS
14
15 timethis ($count, "code");
16
523cc92b 17 # Use Perl code in strings...
f06db76b 18 timethese($count, {
19 'Name1' => '...code1...',
20 'Name2' => '...code2...',
21 });
22
523cc92b 23 # ... or use subroutine references.
24 timethese($count, {
25 'Name1' => sub { ...code1... },
26 'Name2' => sub { ...code2... },
27 });
28
f06db76b 29 $t = timeit($count, '...other code...')
30 print "$count loops of other code took:",timestr($t),"\n";
31
32=head1 DESCRIPTION
33
34The Benchmark module encapsulates a number of routines to help you
35figure out how long it takes to execute some code.
36
37=head2 Methods
38
39=over 10
40
41=item new
42
43Returns 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);
a24a9dfe 50 print "the code took:",timestr($td),"\n";
f06db76b 51
52=item debug
53
54Enables or disable debugging by setting the C<$Benchmark::Debug> flag:
55
523cc92b 56 debug Benchmark 1;
f06db76b 57 $t = timeit(10, ' 5 ** $Global ');
523cc92b 58 debug Benchmark 0;
f06db76b 59
60=back
61
62=head2 Standard Exports
63
523cc92b 64The following routines will be exported into your namespace
f06db76b 65if you use the Benchmark module:
66
67=over 10
68
69=item timeit(COUNT, CODE)
70
523cc92b 71Arguments: COUNT is the number of times to run the loop, and CODE is
72the code to run. CODE may be either a code reference or a string to
73be eval'd; either way it will be run in the caller's package.
74
75Returns: a Benchmark object.
76
77=item timethis ( COUNT, CODE, [ TITLE, [ STYLE ]] )
78
79Time COUNT iterations of CODE. CODE may be a string to eval or a
80code reference; either way the CODE will run in the caller's package.
81Results will be printed to STDOUT as TITLE followed by the times.
82TITLE defaults to "timethis COUNT" if none is provided. STYLE
83determines the format of the output, as described for timestr() below.
84
6ee623d5 85The COUNT can be zero or negative: this means the I<minimum number of
86CPU seconds> to run. A zero signifies the default of 3 seconds. For
87example to run at least for 10 seconds:
88
89 timethis(-10, $code)
90
91or to run two pieces of code tests for at least 3 seconds:
92
93 timethese(0, { test1 => '...', test2 => '...'})
94
95CPU seconds is, in UNIX terms, the user time plus the system time of
96the process itself, as opposed to the real (wallclock) time and the
97time spent by the child processes. Less than 0.1 seconds is not
98accepted (-0.01 as the count, for example, will cause a fatal runtime
99exception).
100
101Note that the CPU seconds is the B<minimum> time: CPU scheduling and
102other operating system factors may complicate the attempt so that a
103little bit more time is spent. The benchmark output will, however,
104also tell the number of C<$code> runs/second, which should be a more
105interesting number than the actually spent seconds.
106
107Returns a Benchmark object.
108
523cc92b 109=item timethese ( COUNT, CODEHASHREF, [ STYLE ] )
f06db76b 110
523cc92b 111The CODEHASHREF is a reference to a hash containing names as keys
112and either a string to eval or a code reference for each value.
113For each (KEY, VALUE) pair in the CODEHASHREF, this routine will
114call
f06db76b 115
523cc92b 116 timethis(COUNT, VALUE, KEY, STYLE)
f06db76b 117
1d2dff63 118The routines are called in string comparison order of KEY.
119
120The COUNT can be zero or negative, see timethis().
6ee623d5 121
523cc92b 122=item timediff ( T1, T2 )
f06db76b 123
523cc92b 124Returns the difference between two Benchmark times as a Benchmark
125object suitable for passing to timestr().
f06db76b 126
6ee623d5 127=item timestr ( TIMEDIFF, [ STYLE, [ FORMAT ] ] )
f06db76b 128
523cc92b 129Returns a string that formats the times in the TIMEDIFF object in
130the requested STYLE. TIMEDIFF is expected to be a Benchmark object
131similar to that returned by timediff().
132
133STYLE can be any of 'all', 'noc', 'nop' or 'auto'. 'all' shows each
134of the 5 times available ('wallclock' time, user time, system time,
135user time of children, and system time of children). 'noc' shows all
136except the two children times. 'nop' shows only wallclock and the
137two children times. 'auto' (the default) will act as 'all' unless
138the children times are both zero, in which case it acts as 'noc'.
139
140FORMAT is the L<printf(3)>-style format specifier (without the
141leading '%') to use to print the times. It defaults to '5.2f'.
f06db76b 142
143=back
144
145=head2 Optional Exports
146
147The following routines will be exported into your namespace
148if you specifically ask that they be imported:
149
150=over 10
151
523cc92b 152=item clearcache ( COUNT )
153
154Clear the cached time for COUNT rounds of the null loop.
155
156=item clearallcache ( )
f06db76b 157
523cc92b 158Clear all cached times.
f06db76b 159
523cc92b 160=item disablecache ( )
f06db76b 161
523cc92b 162Disable caching of timings for the null loop. This will force Benchmark
163to recalculate these timings for each new piece of code timed.
164
165=item enablecache ( )
166
167Enable caching of timings for the null loop. The time taken for COUNT
168rounds of the null loop will be calculated only once for each
169different COUNT used.
f06db76b 170
171=back
172
173=head1 NOTES
174
175The data is stored as a list of values from the time and times
523cc92b 176functions:
f06db76b 177
178 ($real, $user, $system, $children_user, $children_system)
179
180in seconds for the whole loop (not divided by the number of rounds).
181
182The timing is done using time(3) and times(3).
183
184Code is executed in the caller's package.
185
f06db76b 186The time of the null loop (a loop with the same
187number of rounds but empty loop body) is subtracted
188from the time of the real loop.
189
190The null loop times are cached, the key being the
191number of rounds. The caching can be controlled using
192calls like these:
193
523cc92b 194 clearcache($key);
f06db76b 195 clearallcache();
196
523cc92b 197 disablecache();
f06db76b 198 enablecache();
199
200=head1 INHERITANCE
201
202Benchmark inherits from no other class, except of course
203for Exporter.
204
205=head1 CAVEATS
206
80eab818 207Comparing eval'd strings with code references will give you
208inaccurate results: a code reference will show a slower
209execution time than the equivalent eval'd string.
210
f06db76b 211The real time timing is done using time(2) and
212the granularity is therefore only one second.
213
214Short tests may produce negative figures because perl
523cc92b 215can appear to take longer to execute the empty loop
216than a short test; try:
f06db76b 217
218 timethis(100,'1');
219
220The system time of the null loop might be slightly
221more than the system time of the loop with the actual
a24a9dfe 222code and therefore the difference might end up being E<lt> 0.
f06db76b 223
f06db76b 224=head1 AUTHORS
225
5aabfad6 226Jarkko Hietaniemi <F<jhi@iki.fi>>, Tim Bunce <F<Tim.Bunce@ig.co.uk>>
f06db76b 227
228=head1 MODIFICATION HISTORY
229
230September 8th, 1994; by Tim Bunce.
231
523cc92b 232March 28th, 1997; by Hugo van der Sanden: added support for code
233references and the already documented 'debug' method; revamped
234documentation.
f06db76b 235
6ee623d5 236April 04-07th, 1997: by Jarkko Hietaniemi, added the run-for-some-time
237functionality.
238
523cc92b 239=cut
a0d0e21e 240
3f943bd9 241# evaluate something in a clean lexical environment
242sub _doeval { eval shift }
243
244#
245# put any lexicals at file scope AFTER here
246#
247
4aa0a1f7 248use Carp;
a0d0e21e 249use Exporter;
250@ISA=(Exporter);
251@EXPORT=qw(timeit timethis timethese timediff timestr);
252@EXPORT_OK=qw(clearcache clearallcache disablecache enablecache);
253
254&init;
255
256sub init {
257 $debug = 0;
258 $min_count = 4;
259 $min_cpu = 0.4;
260 $defaultfmt = '5.2f';
261 $defaultstyle = 'auto';
262 # The cache can cause a slight loss of sys time accuracy. If a
263 # user does many tests (>10) with *very* large counts (>10000)
264 # or works on a very slow machine the cache may be useful.
265 &disablecache;
266 &clearallcache;
267}
268
523cc92b 269sub debug { $debug = ($_[1] != 0); }
270
a0d0e21e 271sub clearcache { delete $cache{$_[0]}; }
272sub clearallcache { %cache = (); }
273sub enablecache { $cache = 1; }
274sub disablecache { $cache = 0; }
275
a0d0e21e 276# --- Functions to process the 'time' data type
277
6ee623d5 278sub new { my @t = (time, times, @_ == 2 ? $_[1] : 0);
279 print "new=@t\n" if $debug;
280 bless \@t; }
a0d0e21e 281
282sub cpu_p { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps ; }
283sub cpu_c { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $cu+$cs ; }
284sub cpu_a { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps+$cu+$cs ; }
285sub real { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $r ; }
286
523cc92b 287sub timediff {
a0d0e21e 288 my($a, $b) = @_;
523cc92b 289 my @r;
3f943bd9 290 for (my $i=0; $i < @$a; ++$i) {
a0d0e21e 291 push(@r, $a->[$i] - $b->[$i]);
292 }
293 bless \@r;
294}
295
523cc92b 296sub timestr {
a0d0e21e 297 my($tr, $style, $f) = @_;
523cc92b 298 my @t = @$tr;
6ee623d5 299 warn "bad time value (@t)" unless @t==6;
300 my($r, $pu, $ps, $cu, $cs, $n) = @t;
a0d0e21e 301 my($pt, $ct, $t) = ($tr->cpu_p, $tr->cpu_c, $tr->cpu_a);
523cc92b 302 $f = $defaultfmt unless defined $f;
a0d0e21e 303 # format a time in the required style, other formats may be added here
80eab818 304 $style ||= $defaultstyle;
523cc92b 305 $style = ($ct>0) ? 'all' : 'noc' if $style eq 'auto';
306 my $s = "@t $style"; # default for unknown style
7be077a2 307 $s=sprintf("%2d wallclock secs (%$f usr %$f sys + %$f cusr %$f csys = %$f CPU)",
523cc92b 308 @t,$t) if $style eq 'all';
7be077a2 309 $s=sprintf("%2d wallclock secs (%$f usr + %$f sys = %$f CPU)",
310 $r,$pu,$ps,$pt) if $style eq 'noc';
311 $s=sprintf("%2d wallclock secs (%$f cusr + %$f csys = %$f CPU)",
312 $r,$cu,$cs,$ct) if $style eq 'nop';
6ee623d5 313 $s .= sprintf(" @ %$f/s (n=$n)", $n / ( $pu + $ps )) if $n;
a0d0e21e 314 $s;
315}
523cc92b 316
317sub timedebug {
a0d0e21e 318 my($msg, $t) = @_;
523cc92b 319 print STDERR "$msg",timestr($t),"\n" if $debug;
a0d0e21e 320}
321
a0d0e21e 322# --- Functions implementing low-level support for timing loops
323
324sub runloop {
325 my($n, $c) = @_;
4aa0a1f7 326
327 $n+=0; # force numeric now, so garbage won't creep into the eval
523cc92b 328 croak "negative loopcount $n" if $n<0;
329 confess "Usage: runloop(number, [string | coderef])" unless defined $c;
a0d0e21e 330 my($t0, $t1, $td); # before, after, difference
331
332 # find package of caller so we can execute code there
523cc92b 333 my($curpack) = caller(0);
334 my($i, $pack)= 0;
a0d0e21e 335 while (($pack) = caller(++$i)) {
336 last if $pack ne $curpack;
337 }
338
3f943bd9 339 my ($subcode, $subref);
340 if (ref $c eq 'CODE') {
341 $subcode = "sub { for (1 .. $n) { local \$_; package $pack; &\$c; } }";
342 $subref = eval $subcode;
343 }
344 else {
345 $subcode = "sub { for (1 .. $n) { local \$_; package $pack; $c;} }";
346 $subref = _doeval($subcode);
347 }
4aa0a1f7 348 croak "runloop unable to compile '$c': $@\ncode: $subcode\n" if $@;
523cc92b 349 print STDERR "runloop $n '$subcode'\n" if $debug;
a0d0e21e 350
6ee623d5 351 $t0 = Benchmark->new(0);
a0d0e21e 352 &$subref;
6ee623d5 353 $t1 = Benchmark->new($n);
a0d0e21e 354 $td = &timediff($t1, $t0);
355
356 timedebug("runloop:",$td);
357 $td;
358}
359
360
361sub timeit {
362 my($n, $code) = @_;
363 my($wn, $wc, $wd);
364
365 printf STDERR "timeit $n $code\n" if $debug;
366
523cc92b 367 if ($cache && exists $cache{$n}) {
a0d0e21e 368 $wn = $cache{$n};
523cc92b 369 } else {
a0d0e21e 370 $wn = &runloop($n, '');
371 $cache{$n} = $wn;
372 }
373
374 $wc = &runloop($n, $code);
375
376 $wd = timediff($wc, $wn);
377
378 timedebug("timeit: ",$wc);
379 timedebug(" - ",$wn);
380 timedebug(" = ",$wd);
381
382 $wd;
383}
384
6ee623d5 385
386my $default_for = 3;
387my $min_for = 0.1;
388
389sub runfor {
390 my ($code, $tmax) = @_;
391
392 if ( not defined $tmax or $tmax == 0 ) {
393 $tmax = $default_for;
394 } elsif ( $tmax < 0 ) {
395 $tmax = -$tmax;
396 }
397
398 die "runfor(..., $tmax): timelimit cannot be less than $min_for.\n"
399 if $tmax < $min_for;
400
401 my ($n, $td, $tc, $ntot, $rtot, $utot, $stot, $cutot, $cstot );
402
403 # First find the minimum $n that gives a non-zero timing.
404
405 my $nmin;
406
407 for ($n = 1, $tc = 0; $tc <= 0; $n *= 2 ) {
408 $td = timeit($n, $code);
409 $tc = $td->[1] + $td->[2];
410 }
411
412 $nmin = $n;
413
414 my $ttot = 0;
415 my $tpra = 0.05 * $tmax; # Target/time practice.
416
417 # Double $n until we have think we have practiced enough.
418 for ( $n = 1; $ttot < $tpra; $n *= 2 ) {
419 $td = timeit($n, $code);
420 $tc = $td->cpu_p;
421 $ntot += $n;
422 $rtot += $td->[0];
423 $utot += $td->[1];
424 $stot += $td->[2];
425 $ttot = $utot + $stot;
426 $cutot += $td->[3];
427 $cstot += $td->[4];
428 }
429
430 my $r;
431
432 # Then iterate towards the $tmax.
433 while ( $ttot < $tmax ) {
434 $r = $tmax / $ttot - 1; # Linear approximation.
435 $n = int( $r * $n );
436 $n = $nmin if $n < $nmin;
437 $td = timeit($n, $code);
438 $ntot += $n;
439 $rtot += $td->[0];
440 $utot += $td->[1];
441 $stot += $td->[2];
442 $ttot = $utot + $stot;
443 $cutot += $td->[3];
444 $cstot += $td->[4];
445 }
446
447 return bless [ $rtot, $utot, $stot, $cutot, $cstot, $ntot ];
448}
449
a0d0e21e 450# --- Functions implementing high-level time-then-print utilities
451
6ee623d5 452sub n_to_for {
453 my $n = shift;
454 return $n == 0 ? $default_for : $n < 0 ? -$n : undef;
455}
456
a0d0e21e 457sub timethis{
458 my($n, $code, $title, $style) = @_;
6ee623d5 459 my($t, $for, $forn);
460
461 if ( $n > 0 ) {
462 croak "non-integer loopcount $n, stopped" if int($n)<$n;
463 $t = timeit($n, $code);
464 $title = "timethis $n" unless defined $title;
465 } else {
466 $fort = n_to_for( $n );
467 $t = runfor($code, $fort);
468 $title = "timethis for $fort" unless defined $title;
469 $forn = $t->[-1];
470 }
523cc92b 471 local $| = 1;
523cc92b 472 $style = "" unless defined $style;
a0d0e21e 473 printf("%10s: ", $title);
6ee623d5 474 print timestr($t, $style, $defaultfmt),"\n";
475
476 $n = $forn if defined $forn;
523cc92b 477
a0d0e21e 478 # A conservative warning to spot very silly tests.
479 # Don't assume that your benchmark is ok simply because
480 # you don't get this warning!
481 print " (warning: too few iterations for a reliable count)\n"
523cc92b 482 if $n < $min_count
a0d0e21e 483 || ($t->real < 1 && $n < 1000)
523cc92b 484 || $t->cpu_a < $min_cpu;
a0d0e21e 485 $t;
486}
487
a0d0e21e 488sub timethese{
489 my($n, $alt, $style) = @_;
490 die "usage: timethese(count, { 'Name1'=>'code1', ... }\n"
491 unless ref $alt eq HASH;
523cc92b 492 my @names = sort keys %$alt;
493 $style = "" unless defined $style;
6ee623d5 494 print "Benchmark: ";
495 if ( $n > 0 ) {
496 croak "non-integer loopcount $n, stopped" if int($n)<$n;
497 print "timing $n iterations of";
498 } else {
499 print "running";
500 }
501 print " ", join(', ',@names);
502 unless ( $n > 0 ) {
503 my $for = n_to_for( $n );
504 print ", each for at least $for CPU seconds";
505 }
506 print "...\n";
523cc92b 507
508 # we could save the results in an array and produce a summary here
a0d0e21e 509 # sum, min, max, avg etc etc
4dbb2df9 510 foreach my $name (@names) {
511 timethis ($n, $alt -> {$name}, $name, $style);
512 }
a0d0e21e 513}
514
a0d0e21e 5151;