Re^6: "Automated" benchmarking

[salva]

in reply to Re^5: "Automated" benchmarking
in thread "Automated" benchmarking

Say you have two Perl sentences A and B. A runs in 10us and is executed 20 times. B runs in 100us and is executed 10 times. Now suppose that the overhead introduced by Devel::SmallProf is 100us per sentence.

Then:

real_time(A) =  20 * 20 =  400us
real_time(B) = 100 * 10 = 1000us

measured_time(A) = ( 20 + 100) * 20 = 2400us
measured_time(B) = (100 + 100) * 10 = 2000us

So, you should be optimizing B, but Devel::SmallProf tells you to look at A.

The current implementation of Devel::SmallProf performs a sub call, a call to caller, a hash lookup, a couple of tests and conditionals and two calls to Time::HiRes::time() for every sentence making the timings completely unreliable.

I tried to reduce that overhead as much as possible on Devel::FastProf writing the DB sub in C/XS. But on Devel::NYTProf, they went further (IIRC) replacing Perl OP loop by their own and eliminating much of the overhead of the DB interface.

[BrowserUk]

Thank you for the concise and clear explanation. But ... :)

Isn't the 'nulltime' compensation code meant to correct for (most of) that?

  # "Null time" compensation code
  $nulltime = 0;
  for (1..100) {
    my($u,$s,$cu,$cs) = times;
    $cstart = $u+$s+$cu+$cs;
    $start = Time::HiRes::time;
    &$testDB;
    ($u,$s,$cu,$cs) = times;
    $cdone = $u+$s+$cu+$cs;
    $done = Time::HiRes::time;
    $diff = $done - $start;
    $nulltime += $diff;
  }
  $nulltime /= 100;
...

  my($delta);
  $delta = $done - $start;
  $delta = ($delta > $nulltime) ? $delta - $nulltime : 0;
...

[salva]

A nulltime compensation is effective when the overhead is relatively small compared to the sentence execution time. But when it is much bigger as in this case, the compensated overhead (aka error) can still be of the same order of magnitude of the time we want to measure.

Guess why the last line you have quoted from the source is there!

package DB;

use Time::HiRes;

my %testDB = ( null => sub {
                   my($pkg,$filename,$line) = caller;
                   $profile || return;
                   %packages && !$packages{$pkg} && return;
               },
               work => sub {
                   $do_something{foo} = 'bar';
                   my($pkg,$filename,$line) = caller;
                   $profile || return;
                   %packages && !$packages{$pkg} && return;
               });



my $n = 10;
for (1..$n) {
    for my $t (keys %testDB) {
        my $testDB = $testDB{$t};
        my $nulltime = 0;
        for (1..100) {
            my($u,$s,$cu,$cs) = times;
            $cstart = $u+$s+$cu+$cs;
            $start = Time::HiRes::time;
            &$testDB;
            ($u,$s,$cu,$cs) = times;
            $cdone = $u+$s+$cu+$cs;
            $done = Time::HiRes::time;
            $diff = $done - $start;
            $nulltime += $diff;
        }
        $time{$t} = $nulltime / 100 * 1e6;
    }
    printf "null: %.2f, work: %.2f, delta: %.2f\n",
        $time{null}, $time{work}, $time{work} - $time{null};
}

[BrowserUk]

I get this output from your code. Is that good, bad or ugly?

null: 6.63, work: 7.41, delta: 0.77
null: 6.45, work: 7.60, delta: 1.14
null: 6.41, work: 7.36, delta: 0.95
null: 6.49, work: 7.25, delta: 0.77
null: 6.47, work: 7.41, delta: 0.93
null: 6.52, work: 7.37, delta: 0.85
null: 6.38, work: 7.30, delta: 0.93
null: 6.44, work: 7.22, delta: 0.78
null: 6.49, work: 7.38, delta: 0.89
null: 6.50, work: 7.29, delta: 0.79