This is a live mirror of the Perl 5 development currently hosted at https://github.com/perl/perl5
Fix deparsing of glob(my $x) and CORE::glob
[perl5.git] / lib / Benchmark.pm
CommitLineData
a0d0e21e
LW
1package Benchmark;
2
53aa2791
MS
3use strict;
4
5
f06db76b
AD
6=head1 NAME
7
8a4f6ac2 8Benchmark - benchmark running times of Perl code
431d98c2 9
f06db76b
AD
10=head1 SYNOPSIS
11
f36484b0
BS
12 use Benchmark qw(:all) ;
13
f06db76b
AD
14 timethis ($count, "code");
15
523cc92b 16 # Use Perl code in strings...
f06db76b
AD
17 timethese($count, {
18 'Name1' => '...code1...',
19 'Name2' => '...code2...',
20 });
21
523cc92b
CS
22 # ... or use subroutine references.
23 timethese($count, {
24 'Name1' => sub { ...code1... },
25 'Name2' => sub { ...code2... },
26 });
27
431d98c2
BS
28 # cmpthese can be used both ways as well
29 cmpthese($count, {
30 'Name1' => '...code1...',
31 'Name2' => '...code2...',
32 });
33
34 cmpthese($count, {
35 'Name1' => sub { ...code1... },
36 'Name2' => sub { ...code2... },
37 });
38
39 # ...or in two stages
5f7d9242 40 $results = timethese($count,
431d98c2
BS
41 {
42 'Name1' => sub { ...code1... },
43 'Name2' => sub { ...code2... },
44 },
45 'none'
46 );
47 cmpthese( $results ) ;
48
f06db76b
AD
49 $t = timeit($count, '...other code...')
50 print "$count loops of other code took:",timestr($t),"\n";
51
431d98c2
BS
52 $t = countit($time, '...other code...')
53 $count = $t->iters ;
54 print "$count loops of other code took:",timestr($t),"\n";
55
e3d6de9a
JH
56 # enable hires wallclock timing if possible
57 use Benchmark ':hireswallclock';
58
f06db76b
AD
59=head1 DESCRIPTION
60
61The Benchmark module encapsulates a number of routines to help you
62figure out how long it takes to execute some code.
63
8a4f6ac2
GS
64timethis - run a chunk of code several times
65
66timethese - run several chunks of code several times
67
68cmpthese - print results of timethese as a comparison chart
69
70timeit - run a chunk of code and see how long it goes
71
72countit - see how many times a chunk of code runs in a given time
73
74
f06db76b
AD
75=head2 Methods
76
77=over 10
78
79=item new
80
81Returns the current time. Example:
82
83 use Benchmark;
2b393bf4 84 $t0 = Benchmark->new;
f06db76b 85 # ... your code here ...
2b393bf4 86 $t1 = Benchmark->new;
f06db76b 87 $td = timediff($t1, $t0);
a24a9dfe 88 print "the code took:",timestr($td),"\n";
f06db76b
AD
89
90=item debug
91
92Enables or disable debugging by setting the C<$Benchmark::Debug> flag:
93
2b393bf4 94 Benchmark->debug(1);
f06db76b 95 $t = timeit(10, ' 5 ** $Global ');
2b393bf4 96 Benchmark->debug(0);
f06db76b 97
431d98c2
BS
98=item iters
99
100Returns the number of iterations.
101
f06db76b
AD
102=back
103
104=head2 Standard Exports
105
523cc92b 106The following routines will be exported into your namespace
f06db76b
AD
107if you use the Benchmark module:
108
109=over 10
110
111=item timeit(COUNT, CODE)
112
523cc92b
CS
113Arguments: COUNT is the number of times to run the loop, and CODE is
114the code to run. CODE may be either a code reference or a string to
115be eval'd; either way it will be run in the caller's package.
116
117Returns: a Benchmark object.
118
119=item timethis ( COUNT, CODE, [ TITLE, [ STYLE ]] )
120
121Time COUNT iterations of CODE. CODE may be a string to eval or a
122code reference; either way the CODE will run in the caller's package.
123Results will be printed to STDOUT as TITLE followed by the times.
124TITLE defaults to "timethis COUNT" if none is provided. STYLE
125determines the format of the output, as described for timestr() below.
126
6ee623d5
GS
127The COUNT can be zero or negative: this means the I<minimum number of
128CPU seconds> to run. A zero signifies the default of 3 seconds. For
129example to run at least for 10 seconds:
130
131 timethis(-10, $code)
132
133or to run two pieces of code tests for at least 3 seconds:
134
135 timethese(0, { test1 => '...', test2 => '...'})
136
137CPU seconds is, in UNIX terms, the user time plus the system time of
138the process itself, as opposed to the real (wallclock) time and the
139time spent by the child processes. Less than 0.1 seconds is not
140accepted (-0.01 as the count, for example, will cause a fatal runtime
141exception).
142
143Note that the CPU seconds is the B<minimum> time: CPU scheduling and
144other operating system factors may complicate the attempt so that a
145little bit more time is spent. The benchmark output will, however,
146also tell the number of C<$code> runs/second, which should be a more
147interesting number than the actually spent seconds.
148
149Returns a Benchmark object.
150
523cc92b 151=item timethese ( COUNT, CODEHASHREF, [ STYLE ] )
f06db76b 152
523cc92b
CS
153The CODEHASHREF is a reference to a hash containing names as keys
154and either a string to eval or a code reference for each value.
155For each (KEY, VALUE) pair in the CODEHASHREF, this routine will
156call
f06db76b 157
523cc92b 158 timethis(COUNT, VALUE, KEY, STYLE)
f06db76b 159
1d2dff63
GS
160The routines are called in string comparison order of KEY.
161
162The COUNT can be zero or negative, see timethis().
6ee623d5 163
72372890 164Returns a hash reference of Benchmark objects, keyed by name.
3c6312e9 165
523cc92b 166=item timediff ( T1, T2 )
f06db76b 167
523cc92b
CS
168Returns the difference between two Benchmark times as a Benchmark
169object suitable for passing to timestr().
f06db76b 170
6ee623d5 171=item timestr ( TIMEDIFF, [ STYLE, [ FORMAT ] ] )
f06db76b 172
523cc92b
CS
173Returns a string that formats the times in the TIMEDIFF object in
174the requested STYLE. TIMEDIFF is expected to be a Benchmark object
175similar to that returned by timediff().
176
3c6312e9
BS
177STYLE can be any of 'all', 'none', 'noc', 'nop' or 'auto'. 'all' shows
178each of the 5 times available ('wallclock' time, user time, system time,
523cc92b
CS
179user time of children, and system time of children). 'noc' shows all
180except the two children times. 'nop' shows only wallclock and the
181two children times. 'auto' (the default) will act as 'all' unless
182the children times are both zero, in which case it acts as 'noc'.
3c6312e9 183'none' prevents output.
523cc92b
CS
184
185FORMAT is the L<printf(3)>-style format specifier (without the
186leading '%') to use to print the times. It defaults to '5.2f'.
f06db76b
AD
187
188=back
189
190=head2 Optional Exports
191
192The following routines will be exported into your namespace
193if you specifically ask that they be imported:
194
195=over 10
196
523cc92b
CS
197=item clearcache ( COUNT )
198
199Clear the cached time for COUNT rounds of the null loop.
200
201=item clearallcache ( )
f06db76b 202
523cc92b 203Clear all cached times.
f06db76b 204
8962dfd6 205=item cmpthese ( COUNT, CODEHASHREF, [ STYLE ] )
ac8eabc1 206
d1083c7a 207=item cmpthese ( RESULTSHASHREF, [ STYLE ] )
ac8eabc1 208
d1083c7a 209Optionally calls timethese(), then outputs comparison chart. This:
ac8eabc1 210
d1083c7a
BS
211 cmpthese( -1, { a => "++\$i", b => "\$i *= 2" } ) ;
212
213outputs a chart like:
214
215 Rate b a
216 b 2831802/s -- -61%
217 a 7208959/s 155% --
218
219This chart is sorted from slowest to fastest, and shows the percent speed
220difference between each pair of tests.
221
3b46207f 222C<cmpthese> can also be passed the data structure that timethese() returns:
d1083c7a 223
555bd962
BG
224 $results = timethese( -1,
225 { a => "++\$i", b => "\$i *= 2" } ) ;
ac8eabc1
JH
226 cmpthese( $results );
227
d1083c7a 228in case you want to see both sets of results.
72372890
TS
229If the first argument is an unblessed hash reference,
230that is RESULTSHASHREF; otherwise that is COUNT.
d1083c7a
BS
231
232Returns a reference to an ARRAY of rows, each row is an ARRAY of cells from the
233above chart, including labels. This:
234
555bd962
BG
235 my $rows = cmpthese( -1,
236 { a => '++$i', b => '$i *= 2' }, "none" );
d1083c7a
BS
237
238returns a data structure like:
239
240 [
241 [ '', 'Rate', 'b', 'a' ],
242 [ 'b', '2885232/s', '--', '-59%' ],
243 [ 'a', '7099126/s', '146%', '--' ],
244 ]
245
246B<NOTE>: This result value differs from previous versions, which returned
247the C<timethese()> result structure. If you want that, just use the two
248statement C<timethese>...C<cmpthese> idiom shown above.
249
98dc9551 250Incidentally, note the variance in the result values between the two examples;
d1083c7a
BS
251this is typical of benchmarking. If this were a real benchmark, you would
252probably want to run a lot more iterations.
ac8eabc1
JH
253
254=item countit(TIME, CODE)
255
256Arguments: TIME is the minimum length of time to run CODE for, and CODE is
257the code to run. CODE may be either a code reference or a string to
258be eval'd; either way it will be run in the caller's package.
259
260TIME is I<not> negative. countit() will run the loop many times to
261calculate the speed of CODE before running it for TIME. The actual
262time run for will usually be greater than TIME due to system clock
263resolution, so it's best to look at the number of iterations divided
264by the times that you are concerned with, not just the iterations.
265
266Returns: a Benchmark object.
267
523cc92b 268=item disablecache ( )
f06db76b 269
523cc92b
CS
270Disable caching of timings for the null loop. This will force Benchmark
271to recalculate these timings for each new piece of code timed.
272
273=item enablecache ( )
274
275Enable caching of timings for the null loop. The time taken for COUNT
276rounds of the null loop will be calculated only once for each
277different COUNT used.
f06db76b 278
ac8eabc1
JH
279=item timesum ( T1, T2 )
280
281Returns the sum of two Benchmark times as a Benchmark object suitable
282for passing to timestr().
283
f06db76b
AD
284=back
285
e3d6de9a
JH
286=head2 :hireswallclock
287
288If the Time::HiRes module has been installed, you can specify the
289special tag C<:hireswallclock> for Benchmark (if Time::HiRes is not
290available, the tag will be silently ignored). This tag will cause the
291wallclock time to be measured in microseconds, instead of integer
702fa71c
HS
292seconds. Note though that the speed computations are still conducted
293in CPU time, not wallclock time.
e3d6de9a 294
394f4329
NB
295=head1 Benchmark Object
296
297Many of the functions in this module return a Benchmark object,
298or in the case of C<timethese()>, a reference to a hash, the values of
299which are Benchmark objects. This is useful if you want to store or
300further process results from Benchmark functions.
301
302Internally the Benchmark object holds timing values,
303described in L</"NOTES"> below.
304The following methods can be used to access them:
305
306=over 4
307
308=item cpu_p
309
310Total CPU (User + System) of the main (parent) process.
311
312=item cpu_c
313
314Total CPU (User + System) of any children processes.
315
316=item cpu_a
317
318Total CPU of parent and any children processes.
319
320=item real
321
322Real elapsed time "wallclock seconds".
323
324=item iters
325
326Number of iterations run.
327
328=back
329
330The following illustrates use of the Benchmark object:
331
332 $result = timethis(100000, sub { ... });
333 print "total CPU = ", $result->cpu_a, "\n";
334
f06db76b
AD
335=head1 NOTES
336
337The data is stored as a list of values from the time and times
523cc92b 338functions:
f06db76b 339
431d98c2 340 ($real, $user, $system, $children_user, $children_system, $iters)
f06db76b
AD
341
342in seconds for the whole loop (not divided by the number of rounds).
343
344The timing is done using time(3) and times(3).
345
346Code is executed in the caller's package.
347
f06db76b
AD
348The time of the null loop (a loop with the same
349number of rounds but empty loop body) is subtracted
350from the time of the real loop.
351
3c6312e9 352The null loop times can be cached, the key being the
f06db76b
AD
353number of rounds. The caching can be controlled using
354calls like these:
355
523cc92b 356 clearcache($key);
f06db76b
AD
357 clearallcache();
358
523cc92b 359 disablecache();
f06db76b
AD
360 enablecache();
361
3c6312e9 362Caching is off by default, as it can (usually slightly) decrease
98dc9551 363accuracy and does not usually noticeably affect runtimes.
3c6312e9 364
54e82ce5
GS
365=head1 EXAMPLES
366
367For example,
368
14393033
BS
369 use Benchmark qw( cmpthese ) ;
370 $x = 3;
371 cmpthese( -5, {
372 a => sub{$x*$x},
373 b => sub{$x**2},
374 } );
54e82ce5
GS
375
376outputs something like this:
377
378 Benchmark: running a, b, each for at least 5 CPU seconds...
14393033
BS
379 Rate b a
380 b 1559428/s -- -62%
381 a 4152037/s 166% --
382
54e82ce5 383
5f7d9242 384while
54e82ce5 385
14393033
BS
386 use Benchmark qw( timethese cmpthese ) ;
387 $x = 3;
388 $r = timethese( -5, {
389 a => sub{$x*$x},
390 b => sub{$x**2},
391 } );
392 cmpthese $r;
54e82ce5
GS
393
394outputs something like this:
395
14393033
BS
396 Benchmark: running a, b, each for at least 5 CPU seconds...
397 a: 10 wallclock secs ( 5.14 usr + 0.13 sys = 5.27 CPU) @ 3835055.60/s (n=20210743)
398 b: 5 wallclock secs ( 5.41 usr + 0.00 sys = 5.41 CPU) @ 1574944.92/s (n=8520452)
399 Rate b a
400 b 1574945/s -- -59%
401 a 3835056/s 144% --
54e82ce5
GS
402
403
f06db76b
AD
404=head1 INHERITANCE
405
406Benchmark inherits from no other class, except of course
407for Exporter.
408
409=head1 CAVEATS
410
80eab818 411Comparing eval'd strings with code references will give you
431d98c2 412inaccurate results: a code reference will show a slightly slower
80eab818
CS
413execution time than the equivalent eval'd string.
414
f06db76b
AD
415The real time timing is done using time(2) and
416the granularity is therefore only one second.
417
418Short tests may produce negative figures because perl
523cc92b
CS
419can appear to take longer to execute the empty loop
420than a short test; try:
f06db76b
AD
421
422 timethis(100,'1');
423
424The system time of the null loop might be slightly
425more than the system time of the loop with the actual
a24a9dfe 426code and therefore the difference might end up being E<lt> 0.
f06db76b 427
8a4f6ac2
GS
428=head1 SEE ALSO
429
c9dab4e9 430L<Devel::NYTProf> - a Perl code profiler
8a4f6ac2 431
f06db76b
AD
432=head1 AUTHORS
433
5aabfad6 434Jarkko Hietaniemi <F<jhi@iki.fi>>, Tim Bunce <F<Tim.Bunce@ig.co.uk>>
f06db76b
AD
435
436=head1 MODIFICATION HISTORY
437
438September 8th, 1994; by Tim Bunce.
439
523cc92b
CS
440March 28th, 1997; by Hugo van der Sanden: added support for code
441references and the already documented 'debug' method; revamped
442documentation.
f06db76b 443
6ee623d5
GS
444April 04-07th, 1997: by Jarkko Hietaniemi, added the run-for-some-time
445functionality.
446
5f7d9242
DS
447September, 1999; by Barrie Slaymaker: math fixes and accuracy and
448efficiency tweaks. Added cmpthese(). A result is now returned from
431d98c2 449timethese(). Exposed countit() (was runfor()).
3c6312e9 450
0e74ff8e
JH
451December, 2001; by Nicholas Clark: make timestr() recognise the style 'none'
452and return an empty string. If cmpthese is calling timethese, make it pass the
453style in. (so that 'none' will suppress output). Make sub new dump its
454debugging output to STDERR, to be consistent with everything else.
455All bugs found while writing a regression test.
456
e3d6de9a
JH
457September, 2002; by Jarkko Hietaniemi: add ':hireswallclock' special tag.
458
33e4b5a9
CK
459February, 2004; by Chia-liang Kao: make cmpthese and timestr use time
460statistics for children instead of parent when the style is 'nop'.
461
ebfe4dae
CG
462November, 2007; by Christophe Grosjean: make cmpthese and timestr compute
463time consistently with style argument, default is 'all' not 'noc' any more.
464
523cc92b 465=cut
a0d0e21e 466
3f943bd9 467# evaluate something in a clean lexical environment
53aa2791 468sub _doeval { no strict; eval shift }
3f943bd9
GS
469
470#
471# put any lexicals at file scope AFTER here
472#
473
4aa0a1f7 474use Carp;
a0d0e21e 475use Exporter;
53aa2791
MS
476
477our(@ISA, @EXPORT, @EXPORT_OK, %EXPORT_TAGS, $VERSION);
478
479@ISA=qw(Exporter);
ac8eabc1
JH
480@EXPORT=qw(timeit timethis timethese timediff timestr);
481@EXPORT_OK=qw(timesum cmpthese countit
482 clearcache clearallcache disablecache enablecache);
f36484b0 483%EXPORT_TAGS=( all => [ @EXPORT, @EXPORT_OK ] ) ;
a0d0e21e 484
24755e36 485$VERSION = 1.18;
e3d6de9a
JH
486
487# --- ':hireswallclock' special handling
488
489my $hirestime;
490
491sub mytime () { time }
8a4f6ac2 492
359218de 493init();
a0d0e21e 494
e3d6de9a
JH
495sub BEGIN {
496 if (eval 'require Time::HiRes') {
497 import Time::HiRes qw(time);
498 $hirestime = \&Time::HiRes::time;
499 }
500}
501
502sub import {
503 my $class = shift;
504 if (grep { $_ eq ":hireswallclock" } @_) {
505 @_ = grep { $_ ne ":hireswallclock" } @_;
92dfaf87 506 local $^W=0;
e3d6de9a
JH
507 *mytime = $hirestime if defined $hirestime;
508 }
509 Benchmark->export_to_level(1, $class, @_);
510}
511
53aa2791
MS
512our($Debug, $Min_Count, $Min_CPU, $Default_Format, $Default_Style,
513 %_Usage, %Cache, $Do_Cache);
514
a0d0e21e 515sub init {
53aa2791
MS
516 $Debug = 0;
517 $Min_Count = 4;
518 $Min_CPU = 0.4;
519 $Default_Format = '5.2f';
520 $Default_Style = 'auto';
a0d0e21e
LW
521 # The cache can cause a slight loss of sys time accuracy. If a
522 # user does many tests (>10) with *very* large counts (>10000)
523 # or works on a very slow machine the cache may be useful.
359218de
JH
524 disablecache();
525 clearallcache();
a0d0e21e
LW
526}
527
53aa2791
MS
528sub debug { $Debug = ($_[1] != 0); }
529
5f7d9242 530sub usage {
53aa2791
MS
531 my $calling_sub = (caller(1))[3];
532 $calling_sub =~ s/^Benchmark:://;
533 return $_Usage{$calling_sub} || '';
534}
535
bba8fca5 536# The cache needs two branches: 's' for strings and 'c' for code. The
359218de 537# empty loop is different in these two cases.
53aa2791 538
f695f0e6
JH
539$_Usage{clearcache} = <<'USAGE';
540usage: clearcache($count);
541USAGE
542
5f7d9242 543sub clearcache {
f695f0e6 544 die usage unless @_ == 1;
5f7d9242 545 delete $Cache{"$_[0]c"}; delete $Cache{"$_[0]s"};
53aa2791
MS
546}
547
f695f0e6
JH
548$_Usage{clearallcache} = <<'USAGE';
549usage: clearallcache();
550USAGE
551
5f7d9242 552sub clearallcache {
f695f0e6 553 die usage if @_;
5f7d9242 554 %Cache = ();
53aa2791
MS
555}
556
f695f0e6
JH
557$_Usage{enablecache} = <<'USAGE';
558usage: enablecache();
559USAGE
560
561sub enablecache {
562 die usage if @_;
5f7d9242 563 $Do_Cache = 1;
53aa2791
MS
564}
565
f695f0e6
JH
566$_Usage{disablecache} = <<'USAGE';
567usage: disablecache();
568USAGE
569
570sub disablecache {
571 die usage if @_;
5f7d9242 572 $Do_Cache = 0;
53aa2791
MS
573}
574
a0d0e21e 575
a0d0e21e
LW
576# --- Functions to process the 'time' data type
577
e3d6de9a 578sub new { my @t = (mytime, times, @_ == 2 ? $_[1] : 0);
53aa2791 579 print STDERR "new=@t\n" if $Debug;
6ee623d5 580 bless \@t; }
a0d0e21e
LW
581
582sub cpu_p { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps ; }
583sub cpu_c { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $cu+$cs ; }
584sub cpu_a { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps+$cu+$cs ; }
585sub real { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $r ; }
431d98c2 586sub iters { $_[0]->[5] ; }
a0d0e21e 587
53aa2791
MS
588
589$_Usage{timediff} = <<'USAGE';
590usage: $result_diff = timediff($result1, $result2);
591USAGE
592
523cc92b 593sub timediff {
a0d0e21e 594 my($a, $b) = @_;
53aa2791
MS
595
596 die usage unless ref $a and ref $b;
597
523cc92b 598 my @r;
3f943bd9 599 for (my $i=0; $i < @$a; ++$i) {
a0d0e21e
LW
600 push(@r, $a->[$i] - $b->[$i]);
601 }
e68ec53f
YO
602 #die "Bad timediff(): ($r[1] + $r[2]) <= 0 (@$a[1,2]|@$b[1,2])\n"
603 # if ($r[1] + $r[2]) < 0;
a0d0e21e
LW
604 bless \@r;
605}
606
53aa2791
MS
607$_Usage{timesum} = <<'USAGE';
608usage: $sum = timesum($result1, $result2);
609USAGE
610
705cc255 611sub timesum {
53aa2791
MS
612 my($a, $b) = @_;
613
614 die usage unless ref $a and ref $b;
615
616 my @r;
617 for (my $i=0; $i < @$a; ++$i) {
705cc255 618 push(@r, $a->[$i] + $b->[$i]);
53aa2791
MS
619 }
620 bless \@r;
705cc255
TB
621}
622
53aa2791
MS
623
624$_Usage{timestr} = <<'USAGE';
625usage: $formatted_result = timestr($result1);
626USAGE
627
523cc92b 628sub timestr {
a0d0e21e 629 my($tr, $style, $f) = @_;
53aa2791
MS
630
631 die usage unless ref $tr;
632
523cc92b 633 my @t = @$tr;
6ee623d5
GS
634 warn "bad time value (@t)" unless @t==6;
635 my($r, $pu, $ps, $cu, $cs, $n) = @t;
ce9550df 636 my($pt, $ct, $tt) = ($tr->cpu_p, $tr->cpu_c, $tr->cpu_a);
53aa2791 637 $f = $Default_Format unless defined $f;
a0d0e21e 638 # format a time in the required style, other formats may be added here
53aa2791 639 $style ||= $Default_Style;
0e74ff8e 640 return '' if $style eq 'none';
523cc92b
CS
641 $style = ($ct>0) ? 'all' : 'noc' if $style eq 'auto';
642 my $s = "@t $style"; # default for unknown style
e3d6de9a 643 my $w = $hirestime ? "%2g" : "%2d";
ebfe4dae 644 $s = sprintf("$w wallclock secs (%$f usr %$f sys + %$f cusr %$f csys = %$f CPU)",
ce9550df 645 $r,$pu,$ps,$cu,$cs,$tt) if $style eq 'all';
ebfe4dae 646 $s = sprintf("$w wallclock secs (%$f usr + %$f sys = %$f CPU)",
7be077a2 647 $r,$pu,$ps,$pt) if $style eq 'noc';
ebfe4dae 648 $s = sprintf("$w wallclock secs (%$f cusr + %$f csys = %$f CPU)",
7be077a2 649 $r,$cu,$cs,$ct) if $style eq 'nop';
ebfe4dae
CG
650 my $elapsed = do {
651 if ($style eq 'nop') {$cu+$cs}
652 elsif ($style eq 'noc') {$pu+$ps}
653 else {$cu+$cs+$pu+$ps}
654 };
655 $s .= sprintf(" @ %$f/s (n=$n)",$n/($elapsed)) if $n && $elapsed;
a0d0e21e
LW
656 $s;
657}
523cc92b
CS
658
659sub timedebug {
a0d0e21e 660 my($msg, $t) = @_;
53aa2791 661 print STDERR "$msg",timestr($t),"\n" if $Debug;
a0d0e21e
LW
662}
663
a0d0e21e
LW
664# --- Functions implementing low-level support for timing loops
665
53aa2791
MS
666$_Usage{runloop} = <<'USAGE';
667usage: runloop($number, [$string | $coderef])
668USAGE
669
a0d0e21e
LW
670sub runloop {
671 my($n, $c) = @_;
4aa0a1f7
AD
672
673 $n+=0; # force numeric now, so garbage won't creep into the eval
523cc92b 674 croak "negative loopcount $n" if $n<0;
53aa2791 675 confess usage unless defined $c;
a0d0e21e
LW
676 my($t0, $t1, $td); # before, after, difference
677
678 # find package of caller so we can execute code there
523cc92b
CS
679 my($curpack) = caller(0);
680 my($i, $pack)= 0;
a0d0e21e
LW
681 while (($pack) = caller(++$i)) {
682 last if $pack ne $curpack;
683 }
684
3f943bd9
GS
685 my ($subcode, $subref);
686 if (ref $c eq 'CODE') {
687 $subcode = "sub { for (1 .. $n) { local \$_; package $pack; &\$c; } }";
688 $subref = eval $subcode;
689 }
690 else {
691 $subcode = "sub { for (1 .. $n) { local \$_; package $pack; $c;} }";
692 $subref = _doeval($subcode);
693 }
4aa0a1f7 694 croak "runloop unable to compile '$c': $@\ncode: $subcode\n" if $@;
53aa2791 695 print STDERR "runloop $n '$subcode'\n" if $Debug;
a0d0e21e 696
5f7d9242 697 # Wait for the user timer to tick. This makes the error range more like
3c6312e9
BS
698 # -0.01, +0. If we don't wait, then it's more like -0.01, +0.01. This
699 # may not seem important, but it significantly reduces the chances of
700 # getting a too low initial $n in the initial, 'find the minimum' loop
431d98c2 701 # in &countit. This, in turn, can reduce the number of calls to
bba8fca5
BS
702 # &runloop a lot, and thus reduce additive errors.
703 my $tbase = Benchmark->new(0)->[1];
277427cf 704 while ( ( $t0 = Benchmark->new(0) )->[1] == $tbase ) {} ;
f265d4df 705 $subref->();
6ee623d5 706 $t1 = Benchmark->new($n);
a0d0e21e 707 $td = &timediff($t1, $t0);
a0d0e21e
LW
708 timedebug("runloop:",$td);
709 $td;
710}
711
53aa2791
MS
712$_Usage{timeit} = <<'USAGE';
713usage: $result = timeit($count, 'code' ); or
714 $result = timeit($count, sub { code } );
715USAGE
a0d0e21e
LW
716
717sub timeit {
718 my($n, $code) = @_;
719 my($wn, $wc, $wd);
720
53aa2791
MS
721 die usage unless defined $code and
722 (!ref $code or ref $code eq 'CODE');
723
724 printf STDERR "timeit $n $code\n" if $Debug;
3c6312e9 725 my $cache_key = $n . ( ref( $code ) ? 'c' : 's' );
53aa2791
MS
726 if ($Do_Cache && exists $Cache{$cache_key} ) {
727 $wn = $Cache{$cache_key};
523cc92b 728 } else {
6bf773bc 729 $wn = &runloop($n, ref( $code ) ? sub { } : '' );
3c6312e9
BS
730 # Can't let our baseline have any iterations, or they get subtracted
731 # out of the result.
732 $wn->[5] = 0;
53aa2791 733 $Cache{$cache_key} = $wn;
a0d0e21e
LW
734 }
735
736 $wc = &runloop($n, $code);
737
738 $wd = timediff($wc, $wn);
a0d0e21e
LW
739 timedebug("timeit: ",$wc);
740 timedebug(" - ",$wn);
741 timedebug(" = ",$wd);
742
743 $wd;
744}
745
6ee623d5
GS
746
747my $default_for = 3;
748my $min_for = 0.1;
749
3c6312e9 750
53aa2791
MS
751$_Usage{countit} = <<'USAGE';
752usage: $result = countit($time, 'code' ); or
753 $result = countit($time, sub { code } );
754USAGE
755
431d98c2
BS
756sub countit {
757 my ( $tmax, $code ) = @_;
6ee623d5 758
53aa2791
MS
759 die usage unless @_;
760
6ee623d5
GS
761 if ( not defined $tmax or $tmax == 0 ) {
762 $tmax = $default_for;
763 } elsif ( $tmax < 0 ) {
764 $tmax = -$tmax;
765 }
766
431d98c2 767 die "countit($tmax, ...): timelimit cannot be less than $min_for.\n"
6ee623d5
GS
768 if $tmax < $min_for;
769
3c6312e9 770 my ($n, $tc);
6ee623d5 771
bba8fca5 772 # First find the minimum $n that gives a significant timing.
e68ec53f 773 my $zeros=0;
3c6312e9 774 for ($n = 1; ; $n *= 2 ) {
24755e36 775 my $t0 = Benchmark->new(0);
3c6312e9 776 my $td = timeit($n, $code);
24755e36 777 my $t1 = Benchmark->new(0);
3c6312e9 778 $tc = $td->[1] + $td->[2];
e68ec53f 779 if ( $tc <= 0 and $n > 1024 ) {
24755e36
DM
780 my $d = timediff($t1, $t0);
781 # note that $d is the total CPU time taken to call timeit(),
782 # while $tc is is difference in CPU secs between the empty run
783 # and the code run. If the code is trivial, its possible
784 # for $d to get large while $tc is still zero (or slightly
785 # negative). Bail out once timeit() starts taking more than a
786 # few seconds without noticeable difference.
787 if ($d->[1] + $d->[2] > 8
788 || ++$zeros > 16)
789 {
790 die "Timing is consistently zero in estimation loop, cannot benchmark. N=$n\n";
791 }
e68ec53f
YO
792 } else {
793 $zeros = 0;
794 }
3c6312e9
BS
795 last if $tc > 0.1;
796 }
6ee623d5 797
3c6312e9
BS
798 my $nmin = $n;
799
800 # Get $n high enough that we can guess the final $n with some accuracy.
801 my $tpra = 0.1 * $tmax; # Target/time practice.
802 while ( $tc < $tpra ) {
803 # The 5% fudge is to keep us from iterating again all
804 # that often (this speeds overall responsiveness when $tmax is big
5f7d9242 805 # and we guess a little low). This does not noticeably affect
98dc9551 806 # accuracy since we're not counting these times.
3c6312e9
BS
807 $n = int( $tpra * 1.05 * $n / $tc ); # Linear approximation.
808 my $td = timeit($n, $code);
c5d57293
A
809 my $new_tc = $td->[1] + $td->[2];
810 # Make sure we are making progress.
811 $tc = $new_tc > 1.2 * $tc ? $new_tc : 1.2 * $tc;
6ee623d5
GS
812 }
813
3c6312e9
BS
814 # Now, do the 'for real' timing(s), repeating until we exceed
815 # the max.
816 my $ntot = 0;
817 my $rtot = 0;
818 my $utot = 0.0;
819 my $stot = 0.0;
820 my $cutot = 0.0;
821 my $cstot = 0.0;
822 my $ttot = 0.0;
823
824 # The 5% fudge is because $n is often a few % low even for routines
825 # with stable times and avoiding extra timeit()s is nice for
826 # accuracy's sake.
827 $n = int( $n * ( 1.05 * $tmax / $tc ) );
e68ec53f 828 $zeros=0;
3c6312e9
BS
829 while () {
830 my $td = timeit($n, $code);
831 $ntot += $n;
832 $rtot += $td->[0];
833 $utot += $td->[1];
834 $stot += $td->[2];
6ee623d5
GS
835 $cutot += $td->[3];
836 $cstot += $td->[4];
3c6312e9
BS
837 $ttot = $utot + $stot;
838 last if $ttot >= $tmax;
e68ec53f
YO
839 if ( $ttot <= 0 ) {
840 ++$zeros > 16
841 and die "Timing is consistently zero, cannot benchmark. N=$n\n";
842 } else {
843 $zeros = 0;
844 }
c5d57293 845 $ttot = 0.01 if $ttot < 0.01;
3c6312e9 846 my $r = $tmax / $ttot - 1; # Linear approximation.
bba8fca5 847 $n = int( $r * $ntot );
6ee623d5 848 $n = $nmin if $n < $nmin;
6ee623d5
GS
849 }
850
851 return bless [ $rtot, $utot, $stot, $cutot, $cstot, $ntot ];
852}
853
a0d0e21e
LW
854# --- Functions implementing high-level time-then-print utilities
855
6ee623d5
GS
856sub n_to_for {
857 my $n = shift;
858 return $n == 0 ? $default_for : $n < 0 ? -$n : undef;
859}
860
53aa2791
MS
861$_Usage{timethis} = <<'USAGE';
862usage: $result = timethis($time, 'code' ); or
863 $result = timethis($time, sub { code } );
864USAGE
865
a0d0e21e
LW
866sub timethis{
867 my($n, $code, $title, $style) = @_;
53aa2791
MS
868 my($t, $forn);
869
870 die usage unless defined $code and
871 (!ref $code or ref $code eq 'CODE');
6ee623d5
GS
872
873 if ( $n > 0 ) {
874 croak "non-integer loopcount $n, stopped" if int($n)<$n;
875 $t = timeit($n, $code);
876 $title = "timethis $n" unless defined $title;
877 } else {
53aa2791 878 my $fort = n_to_for( $n );
431d98c2 879 $t = countit( $fort, $code );
6ee623d5
GS
880 $title = "timethis for $fort" unless defined $title;
881 $forn = $t->[-1];
882 }
523cc92b 883 local $| = 1;
523cc92b 884 $style = "" unless defined $style;
3c6312e9 885 printf("%10s: ", $title) unless $style eq 'none';
53aa2791 886 print timestr($t, $style, $Default_Format),"\n" unless $style eq 'none';
6ee623d5
GS
887
888 $n = $forn if defined $forn;
523cc92b 889
a0d0e21e
LW
890 # A conservative warning to spot very silly tests.
891 # Don't assume that your benchmark is ok simply because
892 # you don't get this warning!
a2656c4a 893 print " (warning: too few iterations for a reliable count)\n"
53aa2791 894 if $n < $Min_Count
a0d0e21e 895 || ($t->real < 1 && $n < 1000)
53aa2791 896 || $t->cpu_a < $Min_CPU;
a0d0e21e
LW
897 $t;
898}
899
53aa2791
MS
900
901$_Usage{timethese} = <<'USAGE';
902usage: timethese($count, { Name1 => 'code1', ... }); or
903 timethese($count, { Name1 => sub { code1 }, ... });
904USAGE
905
a0d0e21e
LW
906sub timethese{
907 my($n, $alt, $style) = @_;
53aa2791
MS
908 die usage unless ref $alt eq 'HASH';
909
523cc92b
CS
910 my @names = sort keys %$alt;
911 $style = "" unless defined $style;
3c6312e9 912 print "Benchmark: " unless $style eq 'none';
6ee623d5
GS
913 if ( $n > 0 ) {
914 croak "non-integer loopcount $n, stopped" if int($n)<$n;
3c6312e9 915 print "timing $n iterations of" unless $style eq 'none';
6ee623d5 916 } else {
3c6312e9 917 print "running" unless $style eq 'none';
6ee623d5 918 }
3c6312e9 919 print " ", join(', ',@names) unless $style eq 'none';
6ee623d5
GS
920 unless ( $n > 0 ) {
921 my $for = n_to_for( $n );
df7779cf
T
922 print ", each" if $n > 1 && $style ne 'none';
923 print " for at least $for CPU seconds" unless $style eq 'none';
6ee623d5 924 }
3c6312e9 925 print "...\n" unless $style eq 'none';
523cc92b
CS
926
927 # we could save the results in an array and produce a summary here
a0d0e21e 928 # sum, min, max, avg etc etc
3c6312e9 929 my %results;
4dbb2df9 930 foreach my $name (@names) {
3c6312e9 931 $results{$name} = timethis ($n, $alt -> {$name}, $name, $style);
4dbb2df9 932 }
3c6312e9
BS
933
934 return \%results;
a0d0e21e
LW
935}
936
53aa2791
MS
937
938$_Usage{cmpthese} = <<'USAGE';
939usage: cmpthese($count, { Name1 => 'code1', ... }); or
940 cmpthese($count, { Name1 => sub { code1 }, ... }); or
941 cmpthese($result, $style);
942USAGE
943
3c6312e9 944sub cmpthese{
53aa2791
MS
945 my ($results, $style);
946
72372890
TS
947 # $count can be a blessed object.
948 if ( ref $_[0] eq 'HASH' ) {
53aa2791
MS
949 ($results, $style) = @_;
950 }
951 else {
952 my($count, $code) = @_[0,1];
953 $style = $_[2] if defined $_[2];
954
955 die usage unless ref $code eq 'HASH';
956
957 $results = timethese($count, $code, ($style || "none"));
958 }
3c6312e9 959
d1083c7a 960 $style = "" unless defined $style;
3c6312e9
BS
961
962 # Flatten in to an array of arrays with the name as the first field
963 my @vals = map{ [ $_, @{$results->{$_}} ] } keys %$results;
964
965 for (@vals) {
966 # The epsilon fudge here is to prevent div by 0. Since clock
967 # resolutions are much larger, it's below the noise floor.
ebfe4dae
CG
968 my $elapsed = do {
969 if ($style eq 'nop') {$_->[4]+$_->[5]}
970 elsif ($style eq 'noc') {$_->[2]+$_->[3]}
971 else {$_->[2]+$_->[3]+$_->[4]+$_->[5]}
972 };
973 my $rate = $_->[6]/(($elapsed)+0.000000000000001);
3c6312e9
BS
974 $_->[7] = $rate;
975 }
976
977 # Sort by rate
978 @vals = sort { $a->[7] <=> $b->[7] } @vals;
979
980 # If more than half of the rates are greater than one...
d598cef2 981 my $display_as_rate = @vals ? ($vals[$#vals>>1]->[7] > 1) : 0;
3c6312e9
BS
982
983 my @rows;
984 my @col_widths;
985
5f7d9242
DS
986 my @top_row = (
987 '',
988 $display_as_rate ? 'Rate' : 's/iter',
989 map { $_->[0] } @vals
3c6312e9
BS
990 );
991
992 push @rows, \@top_row;
993 @col_widths = map { length( $_ ) } @top_row;
994
995 # Build the data rows
996 # We leave the last column in even though it never has any data. Perhaps
997 # it should go away. Also, perhaps a style for a single column of
998 # percentages might be nice.
999 for my $row_val ( @vals ) {
1000 my @row;
1001
1002 # Column 0 = test name
1003 push @row, $row_val->[0];
1004 $col_widths[0] = length( $row_val->[0] )
1005 if length( $row_val->[0] ) > $col_widths[0];
1006
1007 # Column 1 = performance
1008 my $row_rate = $row_val->[7];
1009
1010 # We assume that we'll never get a 0 rate.
53aa2791 1011 my $rate = $display_as_rate ? $row_rate : 1 / $row_rate;
3c6312e9
BS
1012
1013 # Only give a few decimal places before switching to sci. notation,
1014 # since the results aren't usually that accurate anyway.
5f7d9242
DS
1015 my $format =
1016 $rate >= 100 ?
1017 "%0.0f" :
53aa2791 1018 $rate >= 10 ?
3c6312e9 1019 "%0.1f" :
53aa2791 1020 $rate >= 1 ?
3c6312e9 1021 "%0.2f" :
53aa2791 1022 $rate >= 0.1 ?
3c6312e9
BS
1023 "%0.3f" :
1024 "%0.2e";
1025
1026 $format .= "/s"
1027 if $display_as_rate;
53aa2791
MS
1028
1029 my $formatted_rate = sprintf( $format, $rate );
1030 push @row, $formatted_rate;
1031 $col_widths[1] = length( $formatted_rate )
1032 if length( $formatted_rate ) > $col_widths[1];
3c6312e9
BS
1033
1034 # Columns 2..N = performance ratios
1035 my $skip_rest = 0;
1036 for ( my $col_num = 0 ; $col_num < @vals ; ++$col_num ) {
1037 my $col_val = $vals[$col_num];
1038 my $out;
1039 if ( $skip_rest ) {
1040 $out = '';
1041 }
1042 elsif ( $col_val->[0] eq $row_val->[0] ) {
1043 $out = "--";
1044 # $skip_rest = 1;
1045 }
1046 else {
1047 my $col_rate = $col_val->[7];
1048 $out = sprintf( "%.0f%%", 100*$row_rate/$col_rate - 100 );
1049 }
1050 push @row, $out;
1051 $col_widths[$col_num+2] = length( $out )
1052 if length( $out ) > $col_widths[$col_num+2];
1053
5f7d9242 1054 # A little weirdness to set the first column width properly
3c6312e9
BS
1055 $col_widths[$col_num+2] = length( $col_val->[0] )
1056 if length( $col_val->[0] ) > $col_widths[$col_num+2];
1057 }
1058 push @rows, \@row;
1059 }
1060
d1083c7a
BS
1061 return \@rows if $style eq "none";
1062
3c6312e9
BS
1063 # Equalize column widths in the chart as much as possible without
1064 # exceeding 80 characters. This does not use or affect cols 0 or 1.
5f7d9242 1065 my @sorted_width_refs =
3c6312e9
BS
1066 sort { $$a <=> $$b } map { \$_ } @col_widths[2..$#col_widths];
1067 my $max_width = ${$sorted_width_refs[-1]};
1068
277427cf 1069 my $total = @col_widths - 1 ;
3c6312e9
BS
1070 for ( @col_widths ) { $total += $_ }
1071
1072 STRETCHER:
1073 while ( $total < 80 ) {
1074 my $min_width = ${$sorted_width_refs[0]};
1075 last
1076 if $min_width == $max_width;
1077 for ( @sorted_width_refs ) {
5f7d9242 1078 last
3c6312e9
BS
1079 if $$_ > $min_width;
1080 ++$$_;
1081 ++$total;
1082 last STRETCHER
1083 if $total >= 80;
1084 }
1085 }
1086
1087 # Dump the output
1088 my $format = join( ' ', map { "%${_}s" } @col_widths ) . "\n";
1089 substr( $format, 1, 0 ) = '-';
1090 for ( @rows ) {
1091 printf $format, @$_;
1092 }
1093
d1083c7a 1094 return \@rows ;
3c6312e9
BS
1095}
1096
1097
a0d0e21e 10981;