'From Cache' => sub{ $link->_load_from_database( $criteria ); },
    '  From DBI' => sub{ $link->_load_from_cache   ( $criteria ); }
[download]

Just wanted to note that it looks to me like your results are reversed. Oops.

You are absolutely right. I spotted it just after posting and have a 'fix it' lodged with the appropriate wing of this vast institution.

-- tidiness is the memory loss of environmental mnemonics

#!/usr/bin/perl

use Devel::AutoProfiler;
&do_it();

sub do_it {
   print "Hello world\n";
   for ( 1 .. 20 ) {
      print "$_\n";
   }
}
# OUTPUT BELOW : I have removed code output for legibility
$VAR1 = [
          'main::do_it',
          {
            'total_calls' => '1',
            'file -, line 3' => '1',
            'total_time_in_sub' => '0.003332'
          }
        ];
[download]

#!/usr/bin/perl

# We dont want to profile strict, so place the autoprofiler
# line after that module.
use strict;
use Devel::AutoProfiler;

for ( 1 .. 20 ) {
   &read_file('/etc/passwd');
}

sub read_file {
   my $file = shift();

   open(IN, "$file") || die "Cant access $file\nReason: $!\n";
   while (<IN>) {
      print "$_";
   }
   close(IN);
   return;
}

# Added comments to profiler output and apologies if people
# dont like the overuse of # signs
# OUTPUT BELOW again without actuall code output
#
$VAR1 = [
#
# The subroutine name called
#
          'main::read_file',
          {
#
# file and line in codebase that routine was called from, 
# I did this via STDIN, so file is a -, and the call was on
# line 6
#
            'file -, line 6' => '20',
#
# number of times the routine was called
#
            'total_calls' => '20',
#
# the total time it spent in this particular sub 
#(in seconds)
#
            'total_time_in_sub' => '0.090052'
          }
        ];
[download]

• Wallclocks are the elapsed time from start to end. Which is usually what you want if you are trying to profile the difference between reading data from a file vs a DB, because you care about the acctual time spent. But you have to be warry of wallclock seconds, because if your system is doing nything else while you run the test (ie: if you start surfing the net while waiting for the test to finish) then it will skew the results.
• It's very concievable that your DB time might be faster then your "cache" time -- if you cache is on disk, and your DB caches things in memory.
• Someone else in this thread (i don't remember who at the moment) mentioned that there are ways of profilifng your whole program, not just snippets -- this is a very good idea, for two reasons:
  1. You might spend a lot of time optimizing what you think is the slow part of your code, only to find out later that something else is where the real time is wasted.
  2. running N iterations of hte same piece of code may not give you an accurate picture of what happens when your programm runs "in the wild". if you are working on a DB based App, and you have a caching mechanism for dealing with followup lookups on the same data, then running db_lookup(42) 10,000 times followed by the cache_lookup(42) 10,000 times won't neccessary give you a good picture of reality -- the hardware might start caching the disk page the file is on, or the DB might start caching the rows in memory, making your times much faster then they normally would be if you did 10,000 calls to each on 10,000 different Ids.

I don't use Benchmark that much (not really an issue for the code I write) so I'm not familar with the finer aspects of the module.

Personally if I would look to the table produced at the end of the output over the wallclock secs

As jasonk suggested, running through more iterations may give a clearer difference in results

!unlike

"The price if ignorance, which is of course that you must learn from those who know." Socrates (paraphrased)