Making sense of some dprof output

PoorLuzer has asked for the wisdom of the Perl Monks concerning the following 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::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

Comment on Making sense of some dprof output Download Code

Replies are listed 'Best First'.
Re: Making sense of some dprof output by BrowserUk (Patriarch) on May 18, 2009 at 22:29 UTC
Here is some dprofpp -I output, for almost the same program on different input sizes "almost the same" means different. "different input sizes" also different. That's at least four possible combinations. And you've posted what appear to be three different sets of timings. And a reference to one piece of code. You then ask: The question is why is the elapsed time always double for this program? "double" what? Which "this program" are you refering to? And to what are you comparing it? As the saying goes: insufficient data. 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. "Too many [] have been sedated by an oppressive environment of political correctness and risk aversion."	[reply]
Re^2: Making sense of some dprof output by PoorLuzer (Beadle) on May 19, 2009 at 03:36 UTC
Extremely valid points . the programs are just simple variants of each other and I felt posting the same code would not make much sense. Anyways, I will ditch dproff and use NYT, and then come back with more data!	[reply]
Re: Making sense of some dprof output by jethro (Monsignor) on May 19, 2009 at 00:44 UTC
If you are so concerned about speed why are you still using Tie::File ? Most answers to Improving dismal performance - Part 1 suggested dropping that module and using simple open and <> for reading and writing. That the total elapsed time is higher than your user+system time could have different reasons (I'm guessing since I haven't used dprof): 1. Other programs on your system might produce load that is counted in the total time 2. Accessing the hard disc produces waits (because the disc is slow compared to the processor) which is not counted in system time. While your program waits for the I/O other programs get to run or if all other programs wait the CPU goes into a sleep state 3. You could be on a double-core system and maybe dprof produces wrong output in this case. In the other thread tim.bunce said dprof was broken, maybe this is one of the parts that is broken. I would say that 2. is the most likely answer. The %Time percentages of more than 100% might be because of imprecisions in the time measurements or because of broken dprof on a double-core system. Or simply because dprof is broken (I'll just assume tim.bunces word as fact here).	[reply]
Re: Making sense of some dprof output by dreadpiratepeter (Priest) on May 19, 2009 at 00:00 UTC
You might get better results by posting your code, rather than have us guess about what you need optimizing. With the code and some sample input and output, I'm sure we can tell you how to proceed. -pete "Worry is like a rocking chair. It gives you something to do, but it doesn't get you anywhere."	[reply]
Re: Making sense of some dprof output by perrin (Chancellor) on May 19, 2009 at 03:19 UTC
Why is the elapsed time double the user+system time? Because the elapsed time is real time and includes things like waiting for I/O operations. In other words, when working on a program that manipulates files, it's the number you should be paying attention to. I'd also suggest you ditch Devel::DProf and start using Devel::NYTProf.	[reply]
Re^2: Making sense of some dprof output by PoorLuzer (Beadle) on May 19, 2009 at 05:24 UTC
Nah.. I tried using Devel::NYTProf, but it does not come installed like dprof. I tried installing it by hand ONLY to find out that it uses XS. So me using Devel::NYTProf is pretty much out of question because I am not admin.	[reply]
Re^3: Making sense of some dprof output by tim.bunce (Scribe) on May 19, 2009 at 08:06 UTC
Devel::DProf is broken. The results are mostly garbage. See the first few minutes of http://timbunce.blip.tv/file/1130150/ for an example. You can build and install any perl module, including XS modules, into a perl library directory of your own. You don't need admin rights.	[reply]