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::ins
+ert
     20.2   41.73 41.732 167950   0.0000 0.0000  Tie::File::_read_reco
+rd
     18.9   11.54 38.998 839753   0.0000 0.0000  Tie::File::Heap::inse
+rt
     17.2   21.16 35.610 157920   0.0000 0.0000  Tie::File::Cache::loo
+kup
     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_offs
+ets
     11.5   10.57 23.874 839753   0.0000 0.0000  Tie::File::Heap::_ins
+ert_new
     7.00   4.756 14.444 739447   0.0000 0.0000  Tie::File::Heap::look
+up
     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::_he
+ap_move
     4.70   6.796  9.688 739447   0.0000 0.0000  Tie::File::Heap::prom
+ote
     3.14   6.474  6.474 157920   0.0000 0.0000  Tie::File::Heap::_nse
+q
     1.12   2.311  2.311 839753   0.0000 0.0000  Tie::File::Heap::_nel
+ts_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::ins
+ert
     47.2   4.344 265.93 536190   0.0000 0.0005  Tie::File::Cache::flu
+sh
     46.5   7.502 261.58 536190   0.0000 0.0005  Tie::File::Cache::red
+uce_size_to
     45.1   4.131 254.08 636473   0.0000 0.0004  Tie::File::Heap::poph
+eap
     44.4   148.4 249.95 636473   0.0002 0.0004  Tie::File::Heap::remo
+ve
     21.7   122.5 122.50 142968   0.0000 0.0000  Tie::File::Cache::_he
+ap_move
     15.9   48.97 89.786 304761   0.0000 0.0000  Tie::File::Cache::loo
+kup
     15.8   25.25 89.314 154266   0.0000 0.0001  Tie::File::Heap::inse
+rt
     14.2   80.39 80.394 308533   0.0000 0.0000  Tie::File::_read_reco
+rd
     10.0   26.06 56.595 154266   0.0000 0.0000  Tie::File::Heap::_ins
+ert_new
     9.13   16.15 51.384      1   16.157 51.384  Tie::File::_fill_offs
+ets
     9.13       - 51.384      1        - 51.384  Tie::File::FETCHSIZE
     7.26   15.52 40.815 150494   0.0000 0.0000  Tie::File::Heap::look
+up
    
    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::loo
+kup
     29.0   18.79 84.176 107247   0.0000 0.0001  Tie::File::Cache::ins
+ert
     22.5   17.16 65.380 107247   0.0000 0.0001  Tie::File::Heap::inse
+rt
     19.6   21.19 57.056 228032   0.0000 0.0000  Tie::File::Heap::look
+up
     17.2   50.07 50.077 214494   0.0000 0.0000  Tie::File::_read_reco
+rd
     14.9   16.68 43.486 107247   0.0000 0.0000  Tie::File::Heap::_ins
+ert_new
     12.3   25.18 35.862 228032   0.0000 0.0000  Tie::File::Heap::prom
+ote
     10.8   9.213 31.547      1   9.2133 31.546  Tie::File::_fill_offs
+ets
     10.8       - 31.546      1        - 31.546  Tie::File::FETCHSIZE
     7.90   22.92 22.923 107247   0.0000 0.0000  Tie::File::Cache::_he
+ap_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::_nse
+q
     1.34   3.883  3.883 107247   0.0000 0.0000  Tie::File::Heap::_nel
+ts_inc

[download]

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

In reply to Making sense of some dprof output by PoorLuzer

Title:
Use:  <p> text here (a paragraph) </p>
and:  <code> code here </code>
to format your post, it's "PerlMonks-approved HTML":


  • Posts are HTML formatted. Put <p> </p> tags around your paragraphs. Put <code> </code> tags around your code and data!
  • Titles consisting of a single word are discouraged, and in most cases are disallowed outright.
  • Read Where should I post X? if you're not absolutely sure you're posting in the right place.
  • Please read these before you post! —
  • Posts may use any of the Perl Monks Approved HTML tags:
    a, abbr, b, big, blockquote, br, caption, center, col, colgroup, dd, del, details, div, dl, dt, em, font, h1, h2, h3, h4, h5, h6, hr, i, ins, li, ol, p, pre, readmore, small, span, spoiler, strike, strong, sub, summary, sup, table, tbody, td, tfoot, th, thead, tr, tt, u, ul, wbr
  • You may need to use entities for some characters, as follows. (Exception: Within code tags, you can put the characters literally.)
            For:     Use:
    & &amp;
    < &lt;
    > &gt;
    [ &#91;
    ] &#93;
  • Link using PerlMonks shortcuts! What shortcuts can I use for linking?
  • See Writeup Formatting Tips and other pages linked from there for more info.