package Benchmark;
-=head1 NAME
-
-Benchmark - benchmark running times of code
+use strict;
-timethis - run a chunk of code several times
-timethese - run several chunks of code several times
+=head1 NAME
-timeit - run a chunk of code and see how long it goes
+Benchmark - benchmark running times of Perl code
=head1 SYNOPSIS
+ use Benchmark qw(:all) ;
+
timethis ($count, "code");
+ # Use Perl code in strings...
+ timethese($count, {
+ 'Name1' => '...code1...',
+ 'Name2' => '...code2...',
+ });
+
+ # ... or use subroutine references.
timethese($count, {
+ 'Name1' => sub { ...code1... },
+ 'Name2' => sub { ...code2... },
+ });
+
+ # cmpthese can be used both ways as well
+ cmpthese($count, {
'Name1' => '...code1...',
'Name2' => '...code2...',
});
+ cmpthese($count, {
+ 'Name1' => sub { ...code1... },
+ 'Name2' => sub { ...code2... },
+ });
+
+ # ...or in two stages
+ $results = timethese($count,
+ {
+ 'Name1' => sub { ...code1... },
+ 'Name2' => sub { ...code2... },
+ },
+ 'none'
+ );
+ cmpthese( $results ) ;
+
$t = timeit($count, '...other code...')
print "$count loops of other code took:",timestr($t),"\n";
+ $t = countit($time, '...other code...')
+ $count = $t->iters ;
+ print "$count loops of other code took:",timestr($t),"\n";
+
+ # enable hires wallclock timing if possible
+ use Benchmark ':hireswallclock';
+
=head1 DESCRIPTION
The Benchmark module encapsulates a number of routines to help you
figure out how long it takes to execute some code.
+timethis - run a chunk of code several times
+
+timethese - run several chunks of code several times
+
+cmpthese - print results of timethese as a comparison chart
+
+timeit - run a chunk of code and see how long it goes
+
+countit - see how many times a chunk of code runs in a given time
+
+
=head2 Methods
=over 10
Returns the current time. Example:
use Benchmark;
- $t0 = new Benchmark;
+ $t0 = Benchmark->new;
# ... your code here ...
- $t1 = new Benchmark;
+ $t1 = Benchmark->new;
$td = timediff($t1, $t0);
- print "the code took:",timestr($dt),"\n";
+ print "the code took:",timestr($td),"\n";
=item debug
Enables or disable debugging by setting the C<$Benchmark::Debug> flag:
- debug Benchmark 1;
+ Benchmark->debug(1);
$t = timeit(10, ' 5 ** $Global ');
- debug Benchmark 0;
+ Benchmark->debug(0);
+
+=item iters
+
+Returns the number of iterations.
=back
=head2 Standard Exports
-The following routines will be exported into your namespace
+The following routines will be exported into your namespace
if you use the Benchmark module:
=over 10
=item timeit(COUNT, CODE)
-Arguments: COUNT is the number of time to run the loop, and
-the second is the code to run. CODE may be a string containing the code,
-a reference to the function to run, or a reference to a hash containing
-keys which are names and values which are more CODE specs.
+Arguments: COUNT is the number of times to run the loop, and CODE is
+the code to run. CODE may be either a code reference or a string to
+be eval'd; either way it will be run in the caller's package.
+
+Returns: a Benchmark object.
+
+=item timethis ( COUNT, CODE, [ TITLE, [ STYLE ]] )
+
+Time COUNT iterations of CODE. CODE may be a string to eval or a
+code reference; either way the CODE will run in the caller's package.
+Results will be printed to STDOUT as TITLE followed by the times.
+TITLE defaults to "timethis COUNT" if none is provided. STYLE
+determines the format of the output, as described for timestr() below.
+
+The COUNT can be zero or negative: this means the I<minimum number of
+CPU seconds> to run. A zero signifies the default of 3 seconds. For
+example to run at least for 10 seconds:
+
+ timethis(-10, $code)
+
+or to run two pieces of code tests for at least 3 seconds:
+
+ timethese(0, { test1 => '...', test2 => '...'})
+
+CPU seconds is, in UNIX terms, the user time plus the system time of
+the process itself, as opposed to the real (wallclock) time and the
+time spent by the child processes. Less than 0.1 seconds is not
+accepted (-0.01 as the count, for example, will cause a fatal runtime
+exception).
+
+Note that the CPU seconds is the B<minimum> time: CPU scheduling and
+other operating system factors may complicate the attempt so that a
+little bit more time is spent. The benchmark output will, however,
+also tell the number of C<$code> runs/second, which should be a more
+interesting number than the actually spent seconds.
+
+Returns a Benchmark object.
+
+=item timethese ( COUNT, CODEHASHREF, [ STYLE ] )
+
+The CODEHASHREF is a reference to a hash containing names as keys
+and either a string to eval or a code reference for each value.
+For each (KEY, VALUE) pair in the CODEHASHREF, this routine will
+call
+
+ timethis(COUNT, VALUE, KEY, STYLE)
+
+The routines are called in string comparison order of KEY.
+
+The COUNT can be zero or negative, see timethis().
-Side-effects: prints out noise to standard out.
+Returns a hash reference of Benchmark objects, keyed by name.
-Returns: a Benchmark object.
+=item timediff ( T1, T2 )
-=item timethis
+Returns the difference between two Benchmark times as a Benchmark
+object suitable for passing to timestr().
-=item timethese
+=item timestr ( TIMEDIFF, [ STYLE, [ FORMAT ] ] )
-=item timediff
+Returns a string that formats the times in the TIMEDIFF object in
+the requested STYLE. TIMEDIFF is expected to be a Benchmark object
+similar to that returned by timediff().
-=item timestr
+STYLE can be any of 'all', 'none', 'noc', 'nop' or 'auto'. 'all' shows
+each of the 5 times available ('wallclock' time, user time, system time,
+user time of children, and system time of children). 'noc' shows all
+except the two children times. 'nop' shows only wallclock and the
+two children times. 'auto' (the default) will act as 'all' unless
+the children times are both zero, in which case it acts as 'noc'.
+'none' prevents output.
+
+FORMAT is the L<printf(3)>-style format specifier (without the
+leading '%') to use to print the times. It defaults to '5.2f'.
=back
=over 10
-clearcache
+=item clearcache ( COUNT )
+
+Clear the cached time for COUNT rounds of the null loop.
+
+=item clearallcache ( )
+
+Clear all cached times.
+
+=item cmpthese ( COUNT, CODEHASHREF, [ STYLE ] )
+
+=item cmpthese ( RESULTSHASHREF, [ STYLE ] )
+
+Optionally calls timethese(), then outputs comparison chart. This:
+
+ cmpthese( -1, { a => "++\$i", b => "\$i *= 2" } ) ;
+
+outputs a chart like:
+
+ Rate b a
+ b 2831802/s -- -61%
+ a 7208959/s 155% --
+
+This chart is sorted from slowest to fastest, and shows the percent speed
+difference between each pair of tests.
+
+C<cmpthese> can also be passed the data structure that timethese() returns:
+
+ $results = timethese( -1,
+ { a => "++\$i", b => "\$i *= 2" } ) ;
+ cmpthese( $results );
+
+in case you want to see both sets of results.
+If the first argument is an unblessed hash reference,
+that is RESULTSHASHREF; otherwise that is COUNT.
+
+Returns a reference to an ARRAY of rows, each row is an ARRAY of cells from the
+above chart, including labels. This:
-clearallcache
+ my $rows = cmpthese( -1,
+ { a => '++$i', b => '$i *= 2' }, "none" );
-disablecache
+returns a data structure like:
-enablecache
+ [
+ [ '', 'Rate', 'b', 'a' ],
+ [ 'b', '2885232/s', '--', '-59%' ],
+ [ 'a', '7099126/s', '146%', '--' ],
+ ]
+
+B<NOTE>: This result value differs from previous versions, which returned
+the C<timethese()> result structure. If you want that, just use the two
+statement C<timethese>...C<cmpthese> idiom shown above.
+
+Incidentally, note the variance in the result values between the two examples;
+this is typical of benchmarking. If this were a real benchmark, you would
+probably want to run a lot more iterations.
+
+=item countit(TIME, CODE)
+
+Arguments: TIME is the minimum length of time to run CODE for, and CODE is
+the code to run. CODE may be either a code reference or a string to
+be eval'd; either way it will be run in the caller's package.
+
+TIME is I<not> negative. countit() will run the loop many times to
+calculate the speed of CODE before running it for TIME. The actual
+time run for will usually be greater than TIME due to system clock
+resolution, so it's best to look at the number of iterations divided
+by the times that you are concerned with, not just the iterations.
+
+Returns: a Benchmark object.
+
+=item disablecache ( )
+
+Disable caching of timings for the null loop. This will force Benchmark
+to recalculate these timings for each new piece of code timed.
+
+=item enablecache ( )
+
+Enable caching of timings for the null loop. The time taken for COUNT
+rounds of the null loop will be calculated only once for each
+different COUNT used.
+
+=item timesum ( T1, T2 )
+
+Returns the sum of two Benchmark times as a Benchmark object suitable
+for passing to timestr().
=back
+=head2 :hireswallclock
+
+If the Time::HiRes module has been installed, you can specify the
+special tag C<:hireswallclock> for Benchmark (if Time::HiRes is not
+available, the tag will be silently ignored). This tag will cause the
+wallclock time to be measured in microseconds, instead of integer
+seconds. Note though that the speed computations are still conducted
+in CPU time, not wallclock time.
+
+=head1 Benchmark Object
+
+Many of the functions in this module return a Benchmark object,
+or in the case of C<timethese()>, a reference to a hash, the values of
+which are Benchmark objects. This is useful if you want to store or
+further process results from Benchmark functions.
+
+Internally the Benchmark object holds timing values,
+described in L</"NOTES"> below.
+The following methods can be used to access them:
+
+=over 4
+
+=item cpu_p
+
+Total CPU (User + System) of the main (parent) process.
+
+=item cpu_c
+
+Total CPU (User + System) of any children processes.
+
+=item cpu_a
+
+Total CPU of parent and any children processes.
+
+=item real
+
+Real elapsed time "wallclock seconds".
+
+=item iters
+
+Number of iterations run.
+
+=back
+
+The following illustrates use of the Benchmark object:
+
+ $result = timethis(100000, sub { ... });
+ print "total CPU = ", $result->cpu_a, "\n";
+
=head1 NOTES
The data is stored as a list of values from the time and times
-functions:
+functions:
- ($real, $user, $system, $children_user, $children_system)
+ ($real, $user, $system, $children_user, $children_system, $iters)
in seconds for the whole loop (not divided by the number of rounds).
Code is executed in the caller's package.
-Enable debugging by:
-
- $Benchmark::debug = 1;
-
The time of the null loop (a loop with the same
number of rounds but empty loop body) is subtracted
from the time of the real loop.
-The null loop times are cached, the key being the
+The null loop times can be cached, the key being the
number of rounds. The caching can be controlled using
calls like these:
- clearcache($key);
+ clearcache($key);
clearallcache();
- disablecache();
+ disablecache();
enablecache();
+Caching is off by default, as it can (usually slightly) decrease
+accuracy and does not usually noticeably affect runtimes.
+
+=head1 EXAMPLES
+
+For example,
+
+ use Benchmark qw( cmpthese ) ;
+ $x = 3;
+ cmpthese( -5, {
+ a => sub{$x*$x},
+ b => sub{$x**2},
+ } );
+
+outputs something like this:
+
+ Benchmark: running a, b, each for at least 5 CPU seconds...
+ Rate b a
+ b 1559428/s -- -62%
+ a 4152037/s 166% --
+
+
+while
+
+ use Benchmark qw( timethese cmpthese ) ;
+ $x = 3;
+ $r = timethese( -5, {
+ a => sub{$x*$x},
+ b => sub{$x**2},
+ } );
+ cmpthese $r;
+
+outputs something like this:
+
+ Benchmark: running a, b, each for at least 5 CPU seconds...
+ a: 10 wallclock secs ( 5.14 usr + 0.13 sys = 5.27 CPU) @ 3835055.60/s (n=20210743)
+ b: 5 wallclock secs ( 5.41 usr + 0.00 sys = 5.41 CPU) @ 1574944.92/s (n=8520452)
+ Rate b a
+ b 1574945/s -- -59%
+ a 3835056/s 144% --
+
+
=head1 INHERITANCE
Benchmark inherits from no other class, except of course
-for Exporter.
+from Exporter.
=head1 CAVEATS
+Comparing eval'd strings with code references will give you
+inaccurate results: a code reference will show a slightly slower
+execution time than the equivalent eval'd string.
+
The real time timing is done using time(2) and
the granularity is therefore only one second.
Short tests may produce negative figures because perl
-can appear to take longer to execute the empty loop
-than a short test; try:
+can appear to take longer to execute the empty loop
+than a short test; try:
timethis(100,'1');
The system time of the null loop might be slightly
more than the system time of the loop with the actual
-code and therefore the difference might end up being < 0.
+code and therefore the difference might end up being E<lt> 0.
+
+=head1 SEE ALSO
-More documentation is needed :-( especially for styles and formats.
+L<Devel::NYTProf> - a Perl code profiler
=head1 AUTHORS
-Jarkko Hietaniemi <Jarkko.Hietaniemi@hut.fi>,
-Tim Bunce <Tim.Bunce@ig.co.uk>
+Jarkko Hietaniemi <F<jhi@iki.fi>>, Tim Bunce <F<Tim.Bunce@ig.co.uk>>
=head1 MODIFICATION HISTORY
September 8th, 1994; by Tim Bunce.
+March 28th, 1997; by Hugo van der Sanden: added support for code
+references and the already documented 'debug' method; revamped
+documentation.
+
+April 04-07th, 1997: by Jarkko Hietaniemi, added the run-for-some-time
+functionality.
+
+September, 1999; by Barrie Slaymaker: math fixes and accuracy and
+efficiency tweaks. Added cmpthese(). A result is now returned from
+timethese(). Exposed countit() (was runfor()).
+
+December, 2001; by Nicholas Clark: make timestr() recognise the style 'none'
+and return an empty string. If cmpthese is calling timethese, make it pass the
+style in. (so that 'none' will suppress output). Make sub new dump its
+debugging output to STDERR, to be consistent with everything else.
+All bugs found while writing a regression test.
+
+September, 2002; by Jarkko Hietaniemi: add ':hireswallclock' special tag.
+
+February, 2004; by Chia-liang Kao: make cmpthese and timestr use time
+statistics for children instead of parent when the style is 'nop'.
+
+November, 2007; by Christophe Grosjean: make cmpthese and timestr compute
+time consistently with style argument, default is 'all' not 'noc' any more.
+
=cut
-# Purpose: benchmark running times of code.
-#
-#
-# Usage - to time code snippets and print results:
-#
-# timethis($count, '...code...');
-#
-# prints:
-# timethis 100: 2 secs ( 0.23 usr 0.10 sys = 0.33 cpu)
-#
-#
-# timethese($count, {
-# Name1 => '...code1...',
-# Name2 => '...code2...',
-# ... });
-# prints:
-# Benchmark: timing 100 iterations of Name1, Name2...
-# Name1: 2 secs ( 0.50 usr 0.00 sys = 0.50 cpu)
-# Name2: 1 secs ( 0.48 usr 0.00 sys = 0.48 cpu)
-#
-# The default display style will automatically add child process
-# values if non-zero.
-#
-#
-# Usage - to time sections of your own code:
-#
-# use Benchmark;
-# $t0 = new Benchmark;
-# ... your code here ...
-# $t1 = new Benchmark;
-# $td = &timediff($t1, $t0);
-# print "the code took:",timestr($td),"\n";
-#
-# $t = &timeit($count, '...other code...')
-# print "$count loops of other code took:",timestr($t),"\n";
-#
-#
-# Data format:
-# The data is stored as a list of values from the time and times
-# functions: ($real, $user, $system, $children_user, $children_system)
-# in seconds for the whole loop (not divided by the number of rounds).
-#
-# Internals:
-# The timing is done using time(3) and times(3).
-#
-# Code is executed in the callers package
-#
-# Enable debugging by: $Benchmark::debug = 1;
-#
-# The time of the null loop (a loop with the same
-# number of rounds but empty loop body) is substracted
-# from the time of the real loop.
-#
-# The null loop times are cached, the key being the
-# number of rounds. The caching can be controlled using
-# &clearcache($key); &clearallcache;
-# &disablecache; &enablecache;
-#
-# Caveats:
-#
-# The real time timing is done using time(2) and
-# the granularity is therefore only one second.
-#
-# Short tests may produce negative figures because perl
-# can appear to take longer to execute the empty loop
-# than a short test: try timethis(100,'1');
-#
-# The system time of the null loop might be slightly
-# more than the system time of the loop with the actual
-# code and therefore the difference might end up being < 0
-#
-# More documentation is needed :-(
-# Especially for styles and formats.
-#
-# Authors: Jarkko Hietaniemi <Jarkko.Hietaniemi@hut.fi>
-# Tim Bunce <Tim.Bunce@ig.co.uk>
-#
+# evaluate something in a clean lexical environment
+sub _doeval { no strict; eval shift }
+
#
-# Last updated: Sept 8th 94 by Tim Bunce
+# put any lexicals at file scope AFTER here
#
+use Carp;
use Exporter;
-@ISA=(Exporter);
+
+our(@ISA, @EXPORT, @EXPORT_OK, %EXPORT_TAGS, $VERSION);
+
+@ISA=qw(Exporter);
@EXPORT=qw(timeit timethis timethese timediff timestr);
-@EXPORT_OK=qw(clearcache clearallcache disablecache enablecache);
+@EXPORT_OK=qw(timesum cmpthese countit
+ clearcache clearallcache disablecache enablecache);
+%EXPORT_TAGS=( all => [ @EXPORT, @EXPORT_OK ] ) ;
+
+$VERSION = 1.23;
+
+# --- ':hireswallclock' special handling
-&init;
+my $hirestime;
+
+sub mytime () { time }
+
+init();
+
+sub BEGIN {
+ if (eval 'require Time::HiRes') {
+ import Time::HiRes qw(time);
+ $hirestime = \&Time::HiRes::time;
+ }
+}
+
+sub import {
+ my $class = shift;
+ if (grep { $_ eq ":hireswallclock" } @_) {
+ @_ = grep { $_ ne ":hireswallclock" } @_;
+ local $^W=0;
+ *mytime = $hirestime if defined $hirestime;
+ }
+ Benchmark->export_to_level(1, $class, @_);
+}
+
+our($Debug, $Min_Count, $Min_CPU, $Default_Format, $Default_Style,
+ %_Usage, %Cache, $Do_Cache);
sub init {
- $debug = 0;
- $min_count = 4;
- $min_cpu = 0.4;
- $defaultfmt = '5.2f';
- $defaultstyle = 'auto';
+ $Debug = 0;
+ $Min_Count = 4;
+ $Min_CPU = 0.4;
+ $Default_Format = '5.2f';
+ $Default_Style = 'auto';
# The cache can cause a slight loss of sys time accuracy. If a
# user does many tests (>10) with *very* large counts (>10000)
# or works on a very slow machine the cache may be useful.
- &disablecache;
- &clearallcache;
+ disablecache();
+ clearallcache();
}
-sub clearcache { delete $cache{$_[0]}; }
-sub clearallcache { %cache = (); }
-sub enablecache { $cache = 1; }
-sub disablecache { $cache = 0; }
+sub debug { $Debug = ($_[1] != 0); }
+
+sub usage {
+ my $calling_sub = (caller(1))[3];
+ $calling_sub =~ s/^Benchmark:://;
+ return $_Usage{$calling_sub} || '';
+}
+
+# The cache needs two branches: 's' for strings and 'c' for code. The
+# empty loop is different in these two cases.
+
+$_Usage{clearcache} = <<'USAGE';
+usage: clearcache($count);
+USAGE
+
+sub clearcache {
+ die usage unless @_ == 1;
+ delete $Cache{"$_[0]c"}; delete $Cache{"$_[0]s"};
+}
+
+$_Usage{clearallcache} = <<'USAGE';
+usage: clearallcache();
+USAGE
+
+sub clearallcache {
+ die usage if @_;
+ %Cache = ();
+}
+
+$_Usage{enablecache} = <<'USAGE';
+usage: enablecache();
+USAGE
+
+sub enablecache {
+ die usage if @_;
+ $Do_Cache = 1;
+}
+
+$_Usage{disablecache} = <<'USAGE';
+usage: disablecache();
+USAGE
+
+sub disablecache {
+ die usage if @_;
+ $Do_Cache = 0;
+}
# --- Functions to process the 'time' data type
-sub new { my(@t)=(time, times); print "new=@t\n" if $debug; bless \@t; }
+sub new { my @t = (mytime, times, @_ == 2 ? $_[1] : 0);
+ print STDERR "new=@t\n" if $Debug;
+ bless \@t; }
sub cpu_p { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps ; }
sub cpu_c { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $cu+$cs ; }
sub cpu_a { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $pu+$ps+$cu+$cs ; }
sub real { my($r,$pu,$ps,$cu,$cs) = @{$_[0]}; $r ; }
+sub iters { $_[0]->[5] ; }
+
+# return the sum of various times: which ones depending on $style
-sub timediff{
+sub elapsed {
+ my ($self, $style) = @_;
+ $style = "" unless defined $style;
+
+ return $self->cpu_c if $style eq 'nop';
+ return $self->cpu_p if $style eq 'noc';
+ return $self->cpu_a;
+}
+
+
+$_Usage{timediff} = <<'USAGE';
+usage: $result_diff = timediff($result1, $result2);
+USAGE
+
+sub timediff {
my($a, $b) = @_;
- my(@r);
- for($i=0; $i < @$a; ++$i){
+
+ die usage unless ref $a and ref $b;
+
+ my @r;
+ for (my $i=0; $i < @$a; ++$i) {
push(@r, $a->[$i] - $b->[$i]);
}
+ #die "Bad timediff(): ($r[1] + $r[2]) <= 0 (@$a[1,2]|@$b[1,2])\n"
+ # if ($r[1] + $r[2]) < 0;
+ bless \@r;
+}
+
+$_Usage{timesum} = <<'USAGE';
+usage: $sum = timesum($result1, $result2);
+USAGE
+
+sub timesum {
+ my($a, $b) = @_;
+
+ die usage unless ref $a and ref $b;
+
+ my @r;
+ for (my $i=0; $i < @$a; ++$i) {
+ push(@r, $a->[$i] + $b->[$i]);
+ }
bless \@r;
}
-sub timestr{
+
+$_Usage{timestr} = <<'USAGE';
+usage: $formatted_result = timestr($result1);
+USAGE
+
+sub timestr {
my($tr, $style, $f) = @_;
- my(@t) = @$tr;
- warn "bad time value" unless @t==5;
- my($r, $pu, $ps, $cu, $cs) = @t;
- my($pt, $ct, $t) = ($tr->cpu_p, $tr->cpu_c, $tr->cpu_a);
- $f = $defaultfmt unless $f;
+
+ die usage unless ref $tr;
+
+ my @t = @$tr;
+ warn "bad time value (@t)" unless @t==6;
+ my($r, $pu, $ps, $cu, $cs, $n) = @t;
+ my($pt, $ct, $tt) = ($tr->cpu_p, $tr->cpu_c, $tr->cpu_a);
+ $f = $Default_Format unless defined $f;
# format a time in the required style, other formats may be added here
- $style = $defaultstyle unless $style;
- $style = ($ct>0) ? 'all' : 'noc' if $style=~/^auto$/;
- my($s) = "@t $style"; # default for unknown style
- $s=sprintf("%2d secs (%$f usr %$f sys + %$f cusr %$f csys = %$f cpu)",
- @t,$t) if $style =~ /^all$/;
- $s=sprintf("%2d secs (%$f usr %$f sys = %$f cpu)",
- $r,$pu,$ps,$pt) if $style =~ /^noc$/;
- $s=sprintf("%2d secs (%$f cusr %$f csys = %$f cpu)",
- $r,$cu,$cs,$ct) if $style =~ /^nop$/;
+ $style ||= $Default_Style;
+ return '' if $style eq 'none';
+ $style = ($ct>0) ? 'all' : 'noc' if $style eq 'auto';
+ my $s = "@t $style"; # default for unknown style
+ my $w = $hirestime ? "%2g" : "%2d";
+ $s = sprintf("$w wallclock secs (%$f usr %$f sys + %$f cusr %$f csys = %$f CPU)",
+ $r,$pu,$ps,$cu,$cs,$tt) if $style eq 'all';
+ $s = sprintf("$w wallclock secs (%$f usr + %$f sys = %$f CPU)",
+ $r,$pu,$ps,$pt) if $style eq 'noc';
+ $s = sprintf("$w wallclock secs (%$f cusr + %$f csys = %$f CPU)",
+ $r,$cu,$cs,$ct) if $style eq 'nop';
+ my $elapsed = $tr->elapsed($style);
+ $s .= sprintf(" @ %$f/s (n=$n)",$n/($elapsed)) if $n && $elapsed;
$s;
}
-sub timedebug{
+
+sub timedebug {
my($msg, $t) = @_;
- print STDERR "$msg",timestr($t),"\n" if ($debug);
+ print STDERR "$msg",timestr($t),"\n" if $Debug;
}
-
# --- Functions implementing low-level support for timing loops
+$_Usage{runloop} = <<'USAGE';
+usage: runloop($number, [$string | $coderef])
+USAGE
+
sub runloop {
my($n, $c) = @_;
+
+ $n+=0; # force numeric now, so garbage won't creep into the eval
+ croak "negative loopcount $n" if $n<0;
+ confess usage unless defined $c;
my($t0, $t1, $td); # before, after, difference
# find package of caller so we can execute code there
- my ($curpack) = caller(0);
- my ($i, $pack)= 0;
+ my($curpack) = caller(0);
+ my($i, $pack)= 0;
while (($pack) = caller(++$i)) {
last if $pack ne $curpack;
}
- my $subcode = "sub { package $pack; my(\$_i)=$n; while (\$_i--){$c;} }";
- my $subref = eval $subcode;
- die "runloop unable to compile '$c': $@\ncode: $subcode\n" if $@;
- print STDERR "runloop $n '$subcode'\n" if ($debug);
-
- $t0 = &new;
- &$subref;
- $t1 = &new;
+ my ($subcode, $subref);
+ if (ref $c eq 'CODE') {
+ $subcode = "sub { for (1 .. $n) { local \$_; package $pack; &\$c; } }";
+ $subref = eval $subcode;
+ }
+ else {
+ $subcode = "sub { for (1 .. $n) { local \$_; package $pack; $c;} }";
+ $subref = _doeval($subcode);
+ }
+ croak "runloop unable to compile '$c': $@\ncode: $subcode\n" if $@;
+ print STDERR "runloop $n '$subcode'\n" if $Debug;
+
+ # Wait for the user timer to tick. This makes the error range more like
+ # -0.01, +0. If we don't wait, then it's more like -0.01, +0.01. This
+ # may not seem important, but it significantly reduces the chances of
+ # getting a too low initial $n in the initial, 'find the minimum' loop
+ # in &countit. This, in turn, can reduce the number of calls to
+ # &runloop a lot, and thus reduce additive errors.
+ #
+ # Note that its possible for the act of reading the system clock to
+ # burn lots of system CPU while we burn very little user clock in the
+ # busy loop, which can cause the loop to run for a very long wall time.
+ # So gradually ramp up the duration of the loop. See RT #122003
+ #
+ my $tbase = Benchmark->new(0)->[1];
+ my $limit = 1;
+ while ( ( $t0 = Benchmark->new(0) )->[1] == $tbase ) {
+ for (my $i=0; $i < $limit; $i++) { my $x = $i / 1.5 } # burn user CPU
+ $limit *= 1.1;
+ }
+ $subref->();
+ $t1 = Benchmark->new($n);
$td = &timediff($t1, $t0);
-
timedebug("runloop:",$td);
$td;
}
+$_Usage{timeit} = <<'USAGE';
+usage: $result = timeit($count, 'code' ); or
+ $result = timeit($count, sub { code } );
+USAGE
sub timeit {
my($n, $code) = @_;
my($wn, $wc, $wd);
- printf STDERR "timeit $n $code\n" if $debug;
-
- if ($cache && exists $cache{$n}){
- $wn = $cache{$n};
- }else{
- $wn = &runloop($n, '');
- $cache{$n} = $wn;
+ die usage unless defined $code and
+ (!ref $code or ref $code eq 'CODE');
+
+ printf STDERR "timeit $n $code\n" if $Debug;
+ my $cache_key = $n . ( ref( $code ) ? 'c' : 's' );
+ if ($Do_Cache && exists $Cache{$cache_key} ) {
+ $wn = $Cache{$cache_key};
+ } else {
+ $wn = &runloop($n, ref( $code ) ? sub { } : '' );
+ # Can't let our baseline have any iterations, or they get subtracted
+ # out of the result.
+ $wn->[5] = 0;
+ $Cache{$cache_key} = $wn;
}
$wc = &runloop($n, $code);
$wd = timediff($wc, $wn);
-
timedebug("timeit: ",$wc);
timedebug(" - ",$wn);
timedebug(" = ",$wd);
}
+my $default_for = 3;
+my $min_for = 0.1;
+
+
+$_Usage{countit} = <<'USAGE';
+usage: $result = countit($time, 'code' ); or
+ $result = countit($time, sub { code } );
+USAGE
+
+sub countit {
+ my ( $tmax, $code ) = @_;
+
+ die usage unless @_;
+
+ if ( not defined $tmax or $tmax == 0 ) {
+ $tmax = $default_for;
+ } elsif ( $tmax < 0 ) {
+ $tmax = -$tmax;
+ }
+
+ die "countit($tmax, ...): timelimit cannot be less than $min_for.\n"
+ if $tmax < $min_for;
+
+ my ($n, $tc);
+
+ # First find the minimum $n that gives a significant timing.
+ my $zeros=0;
+ for ($n = 1; ; $n *= 2 ) {
+ my $t0 = Benchmark->new(0);
+ my $td = timeit($n, $code);
+ my $t1 = Benchmark->new(0);
+ $tc = $td->[1] + $td->[2];
+ if ( $tc <= 0 and $n > 1024 ) {
+ my $d = timediff($t1, $t0);
+ # note that $d is the total CPU time taken to call timeit(),
+ # while $tc is the difference in CPU secs between the empty run
+ # and the code run. If the code is trivial, its possible
+ # for $d to get large while $tc is still zero (or slightly
+ # negative). Bail out once timeit() starts taking more than a
+ # few seconds without noticeable difference.
+ if ($d->[1] + $d->[2] > 8
+ || ++$zeros > 16)
+ {
+ die "Timing is consistently zero in estimation loop, cannot benchmark. N=$n\n";
+ }
+ } else {
+ $zeros = 0;
+ }
+ last if $tc > 0.1;
+ }
+
+ my $nmin = $n;
+
+ # Get $n high enough that we can guess the final $n with some accuracy.
+ my $tpra = 0.1 * $tmax; # Target/time practice.
+ while ( $tc < $tpra ) {
+ # The 5% fudge is to keep us from iterating again all
+ # that often (this speeds overall responsiveness when $tmax is big
+ # and we guess a little low). This does not noticeably affect
+ # accuracy since we're not counting these times.
+ $n = int( $tpra * 1.05 * $n / $tc ); # Linear approximation.
+ my $td = timeit($n, $code);
+ my $new_tc = $td->[1] + $td->[2];
+ # Make sure we are making progress.
+ $tc = $new_tc > 1.2 * $tc ? $new_tc : 1.2 * $tc;
+ }
+
+ # Now, do the 'for real' timing(s), repeating until we exceed
+ # the max.
+ my $ntot = 0;
+ my $rtot = 0;
+ my $utot = 0.0;
+ my $stot = 0.0;
+ my $cutot = 0.0;
+ my $cstot = 0.0;
+ my $ttot = 0.0;
+
+ # The 5% fudge is because $n is often a few % low even for routines
+ # with stable times and avoiding extra timeit()s is nice for
+ # accuracy's sake.
+ $n = int( $n * ( 1.05 * $tmax / $tc ) );
+ $zeros=0;
+ while () {
+ my $td = timeit($n, $code);
+ $ntot += $n;
+ $rtot += $td->[0];
+ $utot += $td->[1];
+ $stot += $td->[2];
+ $cutot += $td->[3];
+ $cstot += $td->[4];
+ $ttot = $utot + $stot;
+ last if $ttot >= $tmax;
+ if ( $ttot <= 0 ) {
+ ++$zeros > 16
+ and die "Timing is consistently zero, cannot benchmark. N=$n\n";
+ } else {
+ $zeros = 0;
+ }
+ $ttot = 0.01 if $ttot < 0.01;
+ my $r = $tmax / $ttot - 1; # Linear approximation.
+ $n = int( $r * $ntot );
+ $n = $nmin if $n < $nmin;
+ }
+
+ return bless [ $rtot, $utot, $stot, $cutot, $cstot, $ntot ];
+}
+
# --- Functions implementing high-level time-then-print utilities
+sub n_to_for {
+ my $n = shift;
+ return $n == 0 ? $default_for : $n < 0 ? -$n : undef;
+}
+
+$_Usage{timethis} = <<'USAGE';
+usage: $result = timethis($time, 'code' ); or
+ $result = timethis($time, sub { code } );
+USAGE
+
sub timethis{
my($n, $code, $title, $style) = @_;
- my($t) = timeit($n, $code);
- local($|) = 1;
- $title = "timethis $n" unless $title;
- $style = "" unless $style;
- printf("%10s: ", $title);
- print timestr($t, $style),"\n";
+ my($t, $forn);
+
+ die usage unless defined $code and
+ (!ref $code or ref $code eq 'CODE');
+
+ if ( $n > 0 ) {
+ croak "non-integer loopcount $n, stopped" if int($n)<$n;
+ $t = timeit($n, $code);
+ $title = "timethis $n" unless defined $title;
+ } else {
+ my $fort = n_to_for( $n );
+ $t = countit( $fort, $code );
+ $title = "timethis for $fort" unless defined $title;
+ $forn = $t->[-1];
+ }
+ local $| = 1;
+ $style = "" unless defined $style;
+ printf("%10s: ", $title) unless $style eq 'none';
+ print timestr($t, $style, $Default_Format),"\n" unless $style eq 'none';
+
+ $n = $forn if defined $forn;
+
+ if ($t->elapsed($style) < 0) {
+ # due to clock granularity and variable CPU speed and load,
+ # on quick code with a small number of loops, it's possible for
+ # the empty loop to appear to take longer than the real loop
+ # (e.g. 1 tick versus 0 ticks). This leads to a negative elapsed
+ # time. In this case, floor it at zero, to stop bizarre results.
+ print " (warning: too few iterations for a reliable count)\n";
+ $t->[$_] = 0 for 1..4;
+ }
+
# A conservative warning to spot very silly tests.
# Don't assume that your benchmark is ok simply because
# you don't get this warning!
print " (warning: too few iterations for a reliable count)\n"
- if ( $n < $min_count
+ if $n < $Min_Count
|| ($t->real < 1 && $n < 1000)
- || $t->cpu_a < $min_cpu);
+ || $t->cpu_a < $Min_CPU;
$t;
}
+$_Usage{timethese} = <<'USAGE';
+usage: timethese($count, { Name1 => 'code1', ... }); or
+ timethese($count, { Name1 => sub { code1 }, ... });
+USAGE
+
sub timethese{
my($n, $alt, $style) = @_;
- die "usage: timethese(count, { 'Name1'=>'code1', ... }\n"
- unless ref $alt eq HASH;
- my(@all);
- my(@names) = sort keys %$alt;
- $style = "" unless $style;
- print "Benchmark: timing $n iterations of ",join(', ',@names),"...\n";
- foreach(@names){
- $t = timethis($n, $alt->{$_}, $_, $style);
- push(@all, $t);
+ die usage unless ref $alt eq 'HASH';
+
+ my @names = sort keys %$alt;
+ $style = "" unless defined $style;
+ print "Benchmark: " unless $style eq 'none';
+ if ( $n > 0 ) {
+ croak "non-integer loopcount $n, stopped" if int($n)<$n;
+ print "timing $n iterations of" unless $style eq 'none';
+ } else {
+ print "running" unless $style eq 'none';
}
- # we could produce a summary from @all here
+ print " ", join(', ',@names) unless $style eq 'none';
+ unless ( $n > 0 ) {
+ my $for = n_to_for( $n );
+ print ", each" if $n > 1 && $style ne 'none';
+ print " for at least $for CPU seconds" unless $style eq 'none';
+ }
+ print "...\n" unless $style eq 'none';
+
+ # we could save the results in an array and produce a summary here
# sum, min, max, avg etc etc
- @all;
+ my %results;
+ foreach my $name (@names) {
+ $results{$name} = timethis ($n, $alt -> {$name}, $name, $style);
+ }
+
+ return \%results;
+}
+
+
+$_Usage{cmpthese} = <<'USAGE';
+usage: cmpthese($count, { Name1 => 'code1', ... }); or
+ cmpthese($count, { Name1 => sub { code1 }, ... }); or
+ cmpthese($result, $style);
+USAGE
+
+sub cmpthese{
+ my ($results, $style);
+
+ # $count can be a blessed object.
+ if ( ref $_[0] eq 'HASH' ) {
+ ($results, $style) = @_;
+ }
+ else {
+ my($count, $code) = @_[0,1];
+ $style = $_[2] if defined $_[2];
+
+ die usage unless ref $code eq 'HASH';
+
+ $results = timethese($count, $code, ($style || "none"));
+ }
+
+ $style = "" unless defined $style;
+
+ # Flatten in to an array of arrays with the name as the first field
+ my @vals = map{ [ $_, @{$results->{$_}} ] } keys %$results;
+
+ for (@vals) {
+ # recreate the pre-flattened Benchmark object
+ my $tmp_bm = bless [ @{$_}[1..$#$_] ];
+ my $elapsed = $tmp_bm->elapsed($style);
+ # The epsilon fudge here is to prevent div by 0. Since clock
+ # resolutions are much larger, it's below the noise floor.
+ my $rate = $_->[6]/(($elapsed)+0.000000000000001);
+ $_->[7] = $rate;
+ }
+
+ # Sort by rate
+ @vals = sort { $a->[7] <=> $b->[7] } @vals;
+
+ # If more than half of the rates are greater than one...
+ my $display_as_rate = @vals ? ($vals[$#vals>>1]->[7] > 1) : 0;
+
+ my @rows;
+ my @col_widths;
+
+ my @top_row = (
+ '',
+ $display_as_rate ? 'Rate' : 's/iter',
+ map { $_->[0] } @vals
+ );
+
+ push @rows, \@top_row;
+ @col_widths = map { length( $_ ) } @top_row;
+
+ # Build the data rows
+ # We leave the last column in even though it never has any data. Perhaps
+ # it should go away. Also, perhaps a style for a single column of
+ # percentages might be nice.
+ for my $row_val ( @vals ) {
+ my @row;
+
+ # Column 0 = test name
+ push @row, $row_val->[0];
+ $col_widths[0] = length( $row_val->[0] )
+ if length( $row_val->[0] ) > $col_widths[0];
+
+ # Column 1 = performance
+ my $row_rate = $row_val->[7];
+
+ # We assume that we'll never get a 0 rate.
+ my $rate = $display_as_rate ? $row_rate : 1 / $row_rate;
+
+ # Only give a few decimal places before switching to sci. notation,
+ # since the results aren't usually that accurate anyway.
+ my $format =
+ $rate >= 100 ?
+ "%0.0f" :
+ $rate >= 10 ?
+ "%0.1f" :
+ $rate >= 1 ?
+ "%0.2f" :
+ $rate >= 0.1 ?
+ "%0.3f" :
+ "%0.2e";
+
+ $format .= "/s"
+ if $display_as_rate;
+
+ my $formatted_rate = sprintf( $format, $rate );
+ push @row, $formatted_rate;
+ $col_widths[1] = length( $formatted_rate )
+ if length( $formatted_rate ) > $col_widths[1];
+
+ # Columns 2..N = performance ratios
+ my $skip_rest = 0;
+ for ( my $col_num = 0 ; $col_num < @vals ; ++$col_num ) {
+ my $col_val = $vals[$col_num];
+ my $out;
+ if ( $skip_rest ) {
+ $out = '';
+ }
+ elsif ( $col_val->[0] eq $row_val->[0] ) {
+ $out = "--";
+ # $skip_rest = 1;
+ }
+ else {
+ my $col_rate = $col_val->[7];
+ $out = sprintf( "%.0f%%", 100*$row_rate/$col_rate - 100 );
+ }
+ push @row, $out;
+ $col_widths[$col_num+2] = length( $out )
+ if length( $out ) > $col_widths[$col_num+2];
+
+ # A little weirdness to set the first column width properly
+ $col_widths[$col_num+2] = length( $col_val->[0] )
+ if length( $col_val->[0] ) > $col_widths[$col_num+2];
+ }
+ push @rows, \@row;
+ }
+
+ return \@rows if $style eq "none";
+
+ # Equalize column widths in the chart as much as possible without
+ # exceeding 80 characters. This does not use or affect cols 0 or 1.
+ my @sorted_width_refs =
+ sort { $$a <=> $$b } map { \$_ } @col_widths[2..$#col_widths];
+ my $max_width = ${$sorted_width_refs[-1]};
+
+ my $total = @col_widths - 1 ;
+ for ( @col_widths ) { $total += $_ }
+
+ STRETCHER:
+ while ( $total < 80 ) {
+ my $min_width = ${$sorted_width_refs[0]};
+ last
+ if $min_width == $max_width;
+ for ( @sorted_width_refs ) {
+ last
+ if $$_ > $min_width;
+ ++$$_;
+ ++$total;
+ last STRETCHER
+ if $total >= 80;
+ }
+ }
+
+ # Dump the output
+ my $format = join( ' ', map { "%${_}s" } @col_widths ) . "\n";
+ substr( $format, 1, 0 ) = '-';
+ for ( @rows ) {
+ printf $format, @$_;
+ }
+
+ return \@rows ;
}
https://perl5.git.perl.org / perl5.git / blobdiff