This is a live mirror of the Perl 5 development currently hosted at https://github.com/perl/perl5
Document eval vs. sub in Benchmark
[perl5.git] / lib / Benchmark.pm
CommitLineData
a0d0e21e
LW
1package Benchmark;
2
f06db76b
AD
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
AD
18 timethese($count, {
19 'Name1' => '...code1...',
20 'Name2' => '...code2...',
21 });
22
523cc92b
CS
23 # ... or use subroutine references.
24 timethese($count, {
25 'Name1' => sub { ...code1... },
26 'Name2' => sub { ...code2... },
27 });
28
f06db76b
AD
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
AD
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
AD
59
60=back
61
62=head2 Standard Exports
63
523cc92b 64The following routines will be exported into your namespace
f06db76b
AD
65if you use the Benchmark module:
66
67=over 10
68
69=item timeit(COUNT, CODE)
70
523cc92b
CS
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
85=item timethese ( COUNT, CODEHASHREF, [ STYLE ] )
f06db76b 86
523cc92b
CS
87The CODEHASHREF is a reference to a hash containing names as keys
88and either a string to eval or a code reference for each value.
89For each (KEY, VALUE) pair in the CODEHASHREF, this routine will
90call
f06db76b 91
523cc92b 92 timethis(COUNT, VALUE, KEY, STYLE)
f06db76b 93
523cc92b 94=item timediff ( T1, T2 )
f06db76b 95
523cc92b
CS
96Returns the difference between two Benchmark times as a Benchmark
97object suitable for passing to timestr().
f06db76b 98
523cc92b 99=item timestr ( TIMEDIFF, [ STYLE, [ FORMAT ]] )
f06db76b 100
523cc92b
CS
101Returns a string that formats the times in the TIMEDIFF object in
102the requested STYLE. TIMEDIFF is expected to be a Benchmark object
103similar to that returned by timediff().
104
105STYLE can be any of 'all', 'noc', 'nop' or 'auto'. 'all' shows each
106of the 5 times available ('wallclock' time, user time, system time,
107user time of children, and system time of children). 'noc' shows all
108except the two children times. 'nop' shows only wallclock and the
109two children times. 'auto' (the default) will act as 'all' unless
110the children times are both zero, in which case it acts as 'noc'.
111
112FORMAT is the L<printf(3)>-style format specifier (without the
113leading '%') to use to print the times. It defaults to '5.2f'.
f06db76b
AD
114
115=back
116
117=head2 Optional Exports
118
119The following routines will be exported into your namespace
120if you specifically ask that they be imported:
121
122=over 10
123
523cc92b
CS
124=item clearcache ( COUNT )
125
126Clear the cached time for COUNT rounds of the null loop.
127
128=item clearallcache ( )
f06db76b 129
523cc92b 130Clear all cached times.
f06db76b 131
523cc92b 132=item disablecache ( )
f06db76b 133
523cc92b
CS
134Disable caching of timings for the null loop. This will force Benchmark
135to recalculate these timings for each new piece of code timed.
136
137=item enablecache ( )
138
139Enable caching of timings for the null loop. The time taken for COUNT
140rounds of the null loop will be calculated only once for each
141different COUNT used.
f06db76b
AD
142
143=back
144
145=head1 NOTES
146
147The data is stored as a list of values from the time and times
523cc92b 148functions:
f06db76b
AD
149
150 ($real, $user, $system, $children_user, $children_system)
151
152in seconds for the whole loop (not divided by the number of rounds).
153
154The timing is done using time(3) and times(3).
155
156Code is executed in the caller's package.
157
f06db76b
AD
158The time of the null loop (a loop with the same
159number of rounds but empty loop body) is subtracted
160from the time of the real loop.
161
162The null loop times are cached, the key being the
163number of rounds. The caching can be controlled using
164calls like these:
165
523cc92b 166 clearcache($key);
f06db76b
AD
167 clearallcache();
168
523cc92b 169 disablecache();
f06db76b
AD
170 enablecache();
171
172=head1 INHERITANCE
173
174Benchmark inherits from no other class, except of course
175for Exporter.
176
177=head1 CAVEATS
178
446534a1
HS
179Comparing eval'd strings with code references will give you
180inaccurate results: a code reference will show a slower
181execution time than the equivalent eval'd string.
182
f06db76b
AD
183The real time timing is done using time(2) and
184the granularity is therefore only one second.
185
186Short tests may produce negative figures because perl
523cc92b
CS
187can appear to take longer to execute the empty loop
188than a short test; try:
f06db76b
AD
189
190 timethis(100,'1');
191
192The system time of the null loop might be slightly
193more than the system time of the loop with the actual
a24a9dfe 194code and therefore the difference might end up being E<lt> 0.
f06db76b 195
f06db76b
AD
196=head1 AUTHORS
197
a24a9dfe
PP
198Jarkko Hietaniemi E<lt>F<Jarkko.Hietaniemi@hut.fi>E<gt>,
199Tim Bunce E<lt>F<Tim.Bunce@ig.co.uk>E<gt>
f06db76b
AD
200
201=head1 MODIFICATION HISTORY
202
203September 8th, 1994; by Tim Bunce.
204
523cc92b
CS
205March 28th, 1997; by Hugo van der Sanden: added support for code
206references and the already documented 'debug' method; revamped
207documentation.
f06db76b 208
523cc92b 209=cut
a0d0e21e 210
4aa0a1f7 211use Carp;
a0d0e21e
LW
212use Exporter;
213@ISA=(Exporter);
214@EXPORT=qw(timeit timethis timethese timediff timestr);
215@EXPORT_OK=qw(clearcache clearallcache disablecache enablecache);
216
217&init;
218
219sub init {
220 $debug = 0;
221 $min_count = 4;
222 $min_cpu = 0.4;
223 $defaultfmt = '5.2f';
224 $defaultstyle = 'auto';
225 # The cache can cause a slight loss of sys time accuracy. If a
226 # user does many tests (>10) with *very* large counts (>10000)
227 # or works on a very slow machine the cache may be useful.
228 &disablecache;
229 &clearallcache;
230}
231
523cc92b
CS
232sub debug { $debug = ($_[1] != 0); }
233
a0d0e21e
LW
234sub clearcache { delete $cache{$_[0]}; }
235sub clearallcache { %cache = (); }
236sub enablecache { $cache = 1; }
237sub disablecache { $cache = 0; }
238
a0d0e21e
LW
239# --- Functions to process the 'time' data type
240
523cc92b 241sub new { my @t = (time, times); print "new=@t\n" if $debug; bless \@t; }
a0d0e21e
LW
242
243sub cpu_p { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps ; }
244sub cpu_c { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $cu+$cs ; }
245sub cpu_a { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps+$cu+$cs ; }
246sub real { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $r ; }
247
523cc92b 248sub timediff {
a0d0e21e 249 my($a, $b) = @_;
523cc92b
CS
250 my @r;
251 for ($i=0; $i < @$a; ++$i) {
a0d0e21e
LW
252 push(@r, $a->[$i] - $b->[$i]);
253 }
254 bless \@r;
255}
256
523cc92b 257sub timestr {
a0d0e21e 258 my($tr, $style, $f) = @_;
523cc92b 259 my @t = @$tr;
a0d0e21e
LW
260 warn "bad time value" unless @t==5;
261 my($r, $pu, $ps, $cu, $cs) = @t;
262 my($pt, $ct, $t) = ($tr->cpu_p, $tr->cpu_c, $tr->cpu_a);
523cc92b 263 $f = $defaultfmt unless defined $f;
a0d0e21e 264 # format a time in the required style, other formats may be added here
446534a1 265 $style ||= $defaultstyle;
523cc92b
CS
266 $style = ($ct>0) ? 'all' : 'noc' if $style eq 'auto';
267 my $s = "@t $style"; # default for unknown style
a0d0e21e 268 $s=sprintf("%2d secs (%$f usr %$f sys + %$f cusr %$f csys = %$f cpu)",
523cc92b 269 @t,$t) if $style eq 'all';
a0d0e21e 270 $s=sprintf("%2d secs (%$f usr %$f sys = %$f cpu)",
523cc92b 271 $r,$pu,$ps,$pt) if $style eq 'noc';
a0d0e21e 272 $s=sprintf("%2d secs (%$f cusr %$f csys = %$f cpu)",
523cc92b 273 $r,$cu,$cs,$ct) if $style eq 'nop';
a0d0e21e
LW
274 $s;
275}
523cc92b
CS
276
277sub timedebug {
a0d0e21e 278 my($msg, $t) = @_;
523cc92b 279 print STDERR "$msg",timestr($t),"\n" if $debug;
a0d0e21e
LW
280}
281
a0d0e21e
LW
282# --- Functions implementing low-level support for timing loops
283
284sub runloop {
446534a1 285 my($n, $c) = (shift, shift);
4aa0a1f7
AD
286
287 $n+=0; # force numeric now, so garbage won't creep into the eval
523cc92b
CS
288 croak "negative loopcount $n" if $n<0;
289 confess "Usage: runloop(number, [string | coderef])" unless defined $c;
a0d0e21e
LW
290 my($t0, $t1, $td); # before, after, difference
291
292 # find package of caller so we can execute code there
523cc92b
CS
293 my($curpack) = caller(0);
294 my($i, $pack)= 0;
a0d0e21e
LW
295 while (($pack) = caller(++$i)) {
296 last if $pack ne $curpack;
297 }
298
0d72c55d
HS
299 my $subcode = (ref $c eq 'CODE')
300 ? "sub { package $pack; my(\$_i)=$n; while (\$_i--){&\$c;} }"
301 : "sub { package $pack; my(\$_i)=$n; while (\$_i--){$c;} }";
a0d0e21e 302 my $subref = eval $subcode;
4aa0a1f7 303 croak "runloop unable to compile '$c': $@\ncode: $subcode\n" if $@;
523cc92b 304 print STDERR "runloop $n '$subcode'\n" if $debug;
a0d0e21e
LW
305
306 $t0 = &new;
307 &$subref;
308 $t1 = &new;
309 $td = &timediff($t1, $t0);
310
311 timedebug("runloop:",$td);
312 $td;
313}
314
315
316sub timeit {
317 my($n, $code) = @_;
318 my($wn, $wc, $wd);
319
320 printf STDERR "timeit $n $code\n" if $debug;
321
523cc92b 322 if ($cache && exists $cache{$n}) {
a0d0e21e 323 $wn = $cache{$n};
523cc92b 324 } else {
a0d0e21e
LW
325 $wn = &runloop($n, '');
326 $cache{$n} = $wn;
327 }
328
329 $wc = &runloop($n, $code);
330
331 $wd = timediff($wc, $wn);
332
333 timedebug("timeit: ",$wc);
334 timedebug(" - ",$wn);
335 timedebug(" = ",$wd);
336
337 $wd;
338}
339
a0d0e21e
LW
340# --- Functions implementing high-level time-then-print utilities
341
342sub timethis{
343 my($n, $code, $title, $style) = @_;
523cc92b
CS
344 my $t = timeit($n, $code);
345 local $| = 1;
346 $title = "timethis $n" unless defined $title;
347 $style = "" unless defined $style;
a0d0e21e
LW
348 printf("%10s: ", $title);
349 print timestr($t, $style),"\n";
523cc92b 350
a0d0e21e
LW
351 # A conservative warning to spot very silly tests.
352 # Don't assume that your benchmark is ok simply because
353 # you don't get this warning!
354 print " (warning: too few iterations for a reliable count)\n"
523cc92b 355 if $n < $min_count
a0d0e21e 356 || ($t->real < 1 && $n < 1000)
523cc92b 357 || $t->cpu_a < $min_cpu;
a0d0e21e
LW
358 $t;
359}
360
a0d0e21e
LW
361sub timethese{
362 my($n, $alt, $style) = @_;
363 die "usage: timethese(count, { 'Name1'=>'code1', ... }\n"
364 unless ref $alt eq HASH;
523cc92b
CS
365 my @names = sort keys %$alt;
366 $style = "" unless defined $style;
a0d0e21e 367 print "Benchmark: timing $n iterations of ",join(', ',@names),"...\n";
523cc92b
CS
368
369 # we could save the results in an array and produce a summary here
a0d0e21e 370 # sum, min, max, avg etc etc
523cc92b 371 map timethis($n, $alt->{$_}, $_, $style), @names;
a0d0e21e
LW
372}
373
a0d0e21e 3741;