[win32] tweak Benchmark.pm to restore old timestr() behavior--show wall secs
[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
6ee623d5 118The Count can be zero or negative, see timethis().
119
523cc92b 120=item timediff ( T1, T2 )
f06db76b 121
523cc92b 122Returns the difference between two Benchmark times as a Benchmark
123object suitable for passing to timestr().
f06db76b 124
6ee623d5 125=item timestr ( TIMEDIFF, [ STYLE, [ FORMAT ] ] )
f06db76b 126
523cc92b 127Returns a string that formats the times in the TIMEDIFF object in
128the requested STYLE. TIMEDIFF is expected to be a Benchmark object
129similar to that returned by timediff().
130
131STYLE can be any of 'all', 'noc', 'nop' or 'auto'. 'all' shows each
132of the 5 times available ('wallclock' time, user time, system time,
133user time of children, and system time of children). 'noc' shows all
134except the two children times. 'nop' shows only wallclock and the
135two children times. 'auto' (the default) will act as 'all' unless
136the children times are both zero, in which case it acts as 'noc'.
137
138FORMAT is the L<printf(3)>-style format specifier (without the
139leading '%') to use to print the times. It defaults to '5.2f'.
f06db76b 140
141=back
142
143=head2 Optional Exports
144
145The following routines will be exported into your namespace
146if you specifically ask that they be imported:
147
148=over 10
149
523cc92b 150=item clearcache ( COUNT )
151
152Clear the cached time for COUNT rounds of the null loop.
153
154=item clearallcache ( )
f06db76b 155
523cc92b 156Clear all cached times.
f06db76b 157
523cc92b 158=item disablecache ( )
f06db76b 159
523cc92b 160Disable caching of timings for the null loop. This will force Benchmark
161to recalculate these timings for each new piece of code timed.
162
163=item enablecache ( )
164
165Enable caching of timings for the null loop. The time taken for COUNT
166rounds of the null loop will be calculated only once for each
167different COUNT used.
f06db76b 168
169=back
170
171=head1 NOTES
172
173The data is stored as a list of values from the time and times
523cc92b 174functions:
f06db76b 175
176 ($real, $user, $system, $children_user, $children_system)
177
178in seconds for the whole loop (not divided by the number of rounds).
179
180The timing is done using time(3) and times(3).
181
182Code is executed in the caller's package.
183
f06db76b 184The time of the null loop (a loop with the same
185number of rounds but empty loop body) is subtracted
186from the time of the real loop.
187
188The null loop times are cached, the key being the
189number of rounds. The caching can be controlled using
190calls like these:
191
523cc92b 192 clearcache($key);
f06db76b 193 clearallcache();
194
523cc92b 195 disablecache();
f06db76b 196 enablecache();
197
198=head1 INHERITANCE
199
200Benchmark inherits from no other class, except of course
201for Exporter.
202
203=head1 CAVEATS
204
80eab818 205Comparing eval'd strings with code references will give you
206inaccurate results: a code reference will show a slower
207execution time than the equivalent eval'd string.
208
f06db76b 209The real time timing is done using time(2) and
210the granularity is therefore only one second.
211
212Short tests may produce negative figures because perl
523cc92b 213can appear to take longer to execute the empty loop
214than a short test; try:
f06db76b 215
216 timethis(100,'1');
217
218The system time of the null loop might be slightly
219more than the system time of the loop with the actual
a24a9dfe 220code and therefore the difference might end up being E<lt> 0.
f06db76b 221
f06db76b 222=head1 AUTHORS
223
5aabfad6 224Jarkko Hietaniemi <F<jhi@iki.fi>>, Tim Bunce <F<Tim.Bunce@ig.co.uk>>
f06db76b 225
226=head1 MODIFICATION HISTORY
227
228September 8th, 1994; by Tim Bunce.
229
523cc92b 230March 28th, 1997; by Hugo van der Sanden: added support for code
231references and the already documented 'debug' method; revamped
232documentation.
f06db76b 233
6ee623d5 234April 04-07th, 1997: by Jarkko Hietaniemi, added the run-for-some-time
235functionality.
236
523cc92b 237=cut
a0d0e21e 238
4aa0a1f7 239use Carp;
a0d0e21e 240use Exporter;
241@ISA=(Exporter);
242@EXPORT=qw(timeit timethis timethese timediff timestr);
243@EXPORT_OK=qw(clearcache clearallcache disablecache enablecache);
244
245&init;
246
247sub init {
248 $debug = 0;
249 $min_count = 4;
250 $min_cpu = 0.4;
251 $defaultfmt = '5.2f';
252 $defaultstyle = 'auto';
253 # The cache can cause a slight loss of sys time accuracy. If a
254 # user does many tests (>10) with *very* large counts (>10000)
255 # or works on a very slow machine the cache may be useful.
256 &disablecache;
257 &clearallcache;
258}
259
523cc92b 260sub debug { $debug = ($_[1] != 0); }
261
a0d0e21e 262sub clearcache { delete $cache{$_[0]}; }
263sub clearallcache { %cache = (); }
264sub enablecache { $cache = 1; }
265sub disablecache { $cache = 0; }
266
a0d0e21e 267# --- Functions to process the 'time' data type
268
6ee623d5 269sub new { my @t = (time, times, @_ == 2 ? $_[1] : 0);
270 print "new=@t\n" if $debug;
271 bless \@t; }
a0d0e21e 272
273sub cpu_p { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps ; }
274sub cpu_c { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $cu+$cs ; }
275sub cpu_a { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps+$cu+$cs ; }
276sub real { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $r ; }
277
523cc92b 278sub timediff {
a0d0e21e 279 my($a, $b) = @_;
523cc92b 280 my @r;
281 for ($i=0; $i < @$a; ++$i) {
a0d0e21e 282 push(@r, $a->[$i] - $b->[$i]);
283 }
284 bless \@r;
285}
286
523cc92b 287sub timestr {
a0d0e21e 288 my($tr, $style, $f) = @_;
523cc92b 289 my @t = @$tr;
6ee623d5 290 warn "bad time value (@t)" unless @t==6;
291 my($r, $pu, $ps, $cu, $cs, $n) = @t;
a0d0e21e 292 my($pt, $ct, $t) = ($tr->cpu_p, $tr->cpu_c, $tr->cpu_a);
523cc92b 293 $f = $defaultfmt unless defined $f;
a0d0e21e 294 # format a time in the required style, other formats may be added here
80eab818 295 $style ||= $defaultstyle;
523cc92b 296 $style = ($ct>0) ? 'all' : 'noc' if $style eq 'auto';
297 my $s = "@t $style"; # default for unknown style
7be077a2 298 $s=sprintf("%2d wallclock secs (%$f usr %$f sys + %$f cusr %$f csys = %$f CPU)",
523cc92b 299 @t,$t) if $style eq 'all';
7be077a2 300 $s=sprintf("%2d wallclock secs (%$f usr + %$f sys = %$f CPU)",
301 $r,$pu,$ps,$pt) if $style eq 'noc';
302 $s=sprintf("%2d wallclock secs (%$f cusr + %$f csys = %$f CPU)",
303 $r,$cu,$cs,$ct) if $style eq 'nop';
6ee623d5 304 $s .= sprintf(" @ %$f/s (n=$n)", $n / ( $pu + $ps )) if $n;
a0d0e21e 305 $s;
306}
523cc92b 307
308sub timedebug {
a0d0e21e 309 my($msg, $t) = @_;
523cc92b 310 print STDERR "$msg",timestr($t),"\n" if $debug;
a0d0e21e 311}
312
a0d0e21e 313# --- Functions implementing low-level support for timing loops
314
315sub runloop {
316 my($n, $c) = @_;
4aa0a1f7 317
318 $n+=0; # force numeric now, so garbage won't creep into the eval
523cc92b 319 croak "negative loopcount $n" if $n<0;
320 confess "Usage: runloop(number, [string | coderef])" unless defined $c;
a0d0e21e 321 my($t0, $t1, $td); # before, after, difference
322
323 # find package of caller so we can execute code there
523cc92b 324 my($curpack) = caller(0);
325 my($i, $pack)= 0;
a0d0e21e 326 while (($pack) = caller(++$i)) {
327 last if $pack ne $curpack;
328 }
329
0d72c55d 330 my $subcode = (ref $c eq 'CODE')
331 ? "sub { package $pack; my(\$_i)=$n; while (\$_i--){&\$c;} }"
332 : "sub { package $pack; my(\$_i)=$n; while (\$_i--){$c;} }";
a0d0e21e 333 my $subref = eval $subcode;
4aa0a1f7 334 croak "runloop unable to compile '$c': $@\ncode: $subcode\n" if $@;
523cc92b 335 print STDERR "runloop $n '$subcode'\n" if $debug;
a0d0e21e 336
6ee623d5 337 $t0 = Benchmark->new(0);
a0d0e21e 338 &$subref;
6ee623d5 339 $t1 = Benchmark->new($n);
a0d0e21e 340 $td = &timediff($t1, $t0);
341
342 timedebug("runloop:",$td);
343 $td;
344}
345
346
347sub timeit {
348 my($n, $code) = @_;
349 my($wn, $wc, $wd);
350
351 printf STDERR "timeit $n $code\n" if $debug;
352
523cc92b 353 if ($cache && exists $cache{$n}) {
a0d0e21e 354 $wn = $cache{$n};
523cc92b 355 } else {
a0d0e21e 356 $wn = &runloop($n, '');
357 $cache{$n} = $wn;
358 }
359
360 $wc = &runloop($n, $code);
361
362 $wd = timediff($wc, $wn);
363
364 timedebug("timeit: ",$wc);
365 timedebug(" - ",$wn);
366 timedebug(" = ",$wd);
367
368 $wd;
369}
370
6ee623d5 371
372my $default_for = 3;
373my $min_for = 0.1;
374
375sub runfor {
376 my ($code, $tmax) = @_;
377
378 if ( not defined $tmax or $tmax == 0 ) {
379 $tmax = $default_for;
380 } elsif ( $tmax < 0 ) {
381 $tmax = -$tmax;
382 }
383
384 die "runfor(..., $tmax): timelimit cannot be less than $min_for.\n"
385 if $tmax < $min_for;
386
387 my ($n, $td, $tc, $ntot, $rtot, $utot, $stot, $cutot, $cstot );
388
389 # First find the minimum $n that gives a non-zero timing.
390
391 my $nmin;
392
393 for ($n = 1, $tc = 0; $tc <= 0; $n *= 2 ) {
394 $td = timeit($n, $code);
395 $tc = $td->[1] + $td->[2];
396 }
397
398 $nmin = $n;
399
400 my $ttot = 0;
401 my $tpra = 0.05 * $tmax; # Target/time practice.
402
403 # Double $n until we have think we have practiced enough.
404 for ( $n = 1; $ttot < $tpra; $n *= 2 ) {
405 $td = timeit($n, $code);
406 $tc = $td->cpu_p;
407 $ntot += $n;
408 $rtot += $td->[0];
409 $utot += $td->[1];
410 $stot += $td->[2];
411 $ttot = $utot + $stot;
412 $cutot += $td->[3];
413 $cstot += $td->[4];
414 }
415
416 my $r;
417
418 # Then iterate towards the $tmax.
419 while ( $ttot < $tmax ) {
420 $r = $tmax / $ttot - 1; # Linear approximation.
421 $n = int( $r * $n );
422 $n = $nmin if $n < $nmin;
423 $td = timeit($n, $code);
424 $ntot += $n;
425 $rtot += $td->[0];
426 $utot += $td->[1];
427 $stot += $td->[2];
428 $ttot = $utot + $stot;
429 $cutot += $td->[3];
430 $cstot += $td->[4];
431 }
432
433 return bless [ $rtot, $utot, $stot, $cutot, $cstot, $ntot ];
434}
435
a0d0e21e 436# --- Functions implementing high-level time-then-print utilities
437
6ee623d5 438sub n_to_for {
439 my $n = shift;
440 return $n == 0 ? $default_for : $n < 0 ? -$n : undef;
441}
442
a0d0e21e 443sub timethis{
444 my($n, $code, $title, $style) = @_;
6ee623d5 445 my($t, $for, $forn);
446
447 if ( $n > 0 ) {
448 croak "non-integer loopcount $n, stopped" if int($n)<$n;
449 $t = timeit($n, $code);
450 $title = "timethis $n" unless defined $title;
451 } else {
452 $fort = n_to_for( $n );
453 $t = runfor($code, $fort);
454 $title = "timethis for $fort" unless defined $title;
455 $forn = $t->[-1];
456 }
523cc92b 457 local $| = 1;
523cc92b 458 $style = "" unless defined $style;
a0d0e21e 459 printf("%10s: ", $title);
6ee623d5 460 print timestr($t, $style, $defaultfmt),"\n";
461
462 $n = $forn if defined $forn;
523cc92b 463
a0d0e21e 464 # A conservative warning to spot very silly tests.
465 # Don't assume that your benchmark is ok simply because
466 # you don't get this warning!
467 print " (warning: too few iterations for a reliable count)\n"
523cc92b 468 if $n < $min_count
a0d0e21e 469 || ($t->real < 1 && $n < 1000)
523cc92b 470 || $t->cpu_a < $min_cpu;
a0d0e21e 471 $t;
472}
473
a0d0e21e 474sub timethese{
475 my($n, $alt, $style) = @_;
476 die "usage: timethese(count, { 'Name1'=>'code1', ... }\n"
477 unless ref $alt eq HASH;
523cc92b 478 my @names = sort keys %$alt;
479 $style = "" unless defined $style;
6ee623d5 480 print "Benchmark: ";
481 if ( $n > 0 ) {
482 croak "non-integer loopcount $n, stopped" if int($n)<$n;
483 print "timing $n iterations of";
484 } else {
485 print "running";
486 }
487 print " ", join(', ',@names);
488 unless ( $n > 0 ) {
489 my $for = n_to_for( $n );
490 print ", each for at least $for CPU seconds";
491 }
492 print "...\n";
523cc92b 493
494 # we could save the results in an array and produce a summary here
a0d0e21e 495 # sum, min, max, avg etc etc
4dbb2df9 496 foreach my $name (@names) {
497 timethis ($n, $alt -> {$name}, $name, $style);
498 }
a0d0e21e 499}
500
a0d0e21e 5011;