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
[download]

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.

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;
...
[download]

---

With the rise and rise of 'Social' network sites: 'Computers are making people easier to use everyday'

Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.

"Science is about questioning the status quo. Questioning authority".

In the absence of evidence, opinion is indistinguishable from prejudice.

The start of some sanity?

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};
}
[download]