Making sense of some dprof output

Question

Here is some dprofpp -I output, for almost the same program on different input sizes (program uses File:Tie to read input file and does some filtering of lines.

The question is why is the elapsed time always double for this program?

I am asking this because fixing this would make my program faster by 2x without any more magic - is it, perhaps, because of dprof? How do I find this out?

Also confusing is the value of %Time in the last two sets:

Total Elapsed Time = 456.5656 Seconds
  User+System Time = 206.2156 Seconds
Inclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 87.6   25.71 180.65 157920   0.0000 0.0001  Tie::File::FETCH
 75.1   28.96 154.93 157920   0.0000 0.0001  Tie::File::_fetch
 26.0   14.77 53.769 839753   0.0000 0.0001  Tie::File::Cache::insert
 20.2   41.73 41.732 167950   0.0000 0.0000  Tie::File::_read_record
 18.9   11.54 38.998 839753   0.0000 0.0000  Tie::File::Heap::insert
 17.2   21.16 35.610 157920   0.0000 0.0000  Tie::File::Cache::lookup
 12.4   0.566 25.571  14503   0.0000 0.0018  Tie::File::FETCHSIZE
 11.9   6.701 24.732      1   6.7008 24.731  Tie::File::_fill_offsets
 11.5   10.57 23.874 839753   0.0000 0.0000  Tie::File::Heap::_insert_new
 7.00   4.756 14.444 739447   0.0000 0.0000  Tie::File::Heap::lookup
 6.25   11.62 12.893 839755   0.0000 0.0000  Tie::File::_seek
 5.33   10.99 10.991 839753   0.0000 0.0000  Tie::File::Cache::_heap_move
 4.70   6.796  9.688 739447   0.0000 0.0000  Tie::File::Heap::promote
 3.14   6.474  6.474 157920   0.0000 0.0000  Tie::File::Heap::_nseq
 1.12   2.311  2.311 839753   0.0000 0.0000  Tie::File::Heap::_nelts_inc

Total Elapsed Time = 1029.736 Seconds
  User+System Time = 562.5560 Seconds
Inclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 119.   58.01 671.82 304761   0.0000 0.0002  Tie::File::FETCH
 109.   62.95 613.81 304761   0.0000 0.0002  Tie::File::_fetch
 68.6   30.71 385.95 154266   0.0000 0.0003  Tie::File::Cache::insert
 47.2   4.344 265.93 536190   0.0000 0.0005  Tie::File::Cache::flush
 46.5   7.502 261.58 536190   0.0000 0.0005  Tie::File::Cache::reduce_size_to
 45.1   4.131 254.08 636473   0.0000 0.0004  Tie::File::Heap::popheap
 44.4   148.4 249.95 636473   0.0002 0.0004  Tie::File::Heap::remove
 21.7   122.5 122.50 142968   0.0000 0.0000  Tie::File::Cache::_heap_move
 15.9   48.97 89.786 304761   0.0000 0.0000  Tie::File::Cache::lookup
 15.8   25.25 89.314 154266   0.0000 0.0001  Tie::File::Heap::insert
 14.2   80.39 80.394 308533   0.0000 0.0000  Tie::File::_read_record
 10.0   26.06 56.595 154266   0.0000 0.0000  Tie::File::Heap::_insert_new
 9.13   16.15 51.384      1   16.157 51.384  Tie::File::_fill_offsets
 9.13       - 51.384      1        - 51.384  Tie::File::FETCHSIZE
 7.26   15.52 40.815 150494   0.0000 0.0000  Tie::File::Heap::lookup

Total Elapsed Time = 556.7212 Seconds
  User+System Time = 290.2512 Seconds
Inclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 115.   51.05 336.00 335279   0.0000 0.0001  Tie::File::FETCH
 98.1   50.85 284.95 335279   0.0000 0.0001  Tie::File::_fetch
 35.4   45.84 102.90 335279   0.0000 0.0000  Tie::File::Cache::lookup
 29.0   18.79 84.176 107247   0.0000 0.0001  Tie::File::Cache::insert
 22.5   17.16 65.380 107247   0.0000 0.0001  Tie::File::Heap::insert
 19.6   21.19 57.056 228032   0.0000 0.0000  Tie::File::Heap::lookup
 17.2   50.07 50.077 214494   0.0000 0.0000  Tie::File::_read_record
 14.9   16.68 43.486 107247   0.0000 0.0000  Tie::File::Heap::_insert_new
 12.3   25.18 35.862 228032   0.0000 0.0000  Tie::File::Heap::promote
 10.8   9.213 31.547      1   9.2133 31.546  Tie::File::_fill_offsets
 10.8       - 31.546      1        - 31.546  Tie::File::FETCHSIZE
 7.90   22.92 22.923 107247   0.0000 0.0000  Tie::File::Cache::_heap_move
 6.64   15.98 19.280 107247   0.0000 0.0000  Tie::File::_seek
 5.31   15.41 15.411 335279   0.0000 0.0000  Tie::File::Heap::_nseq
 1.34   3.883  3.883 107247   0.0000 0.0000  Tie::File::Heap::_nelts_inc

Here is the kind of code I am talking about : http://www.perlmonks.org/?node_id=763564

Answer 1

1. Tie::File is telling you your bottleneck is reading from disk. So your optimizing is over. Unless of course, you can find a smarter way to not read from disk.

2. Use Devel::NYTProf, its much more comprehensive.

Answer 2

The question is why is the elapsed time always double for this program?

My understanding is it is because the half of the time is spent in I/O [I may be wrong here]

But, to get a better idea of where the actual time is being spent, use

$> dprofpp -I -r 

OR

$>dprofpp -I -r -A