Beefy Boxes and Bandwidth Generously Provided by pair Networks
XP is just a number
 
PerlMonks  

Making sense of some dprof output

by PoorLuzer (Beadle)
on May 18, 2009 at 22:11 UTC ( #764765=perlquestion: print w/replies, xml ) Need Help??

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

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

Replies are listed 'Best First'.
Re: Making sense of some dprof output
by BrowserUk (Pope) 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.
      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!
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).

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."
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.

      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.
        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.

Log In?
Username:
Password:

What's my password?
Create A New User
Node Status?
node history
Node Type: perlquestion [id://764765]
Approved by ikegami
help
Chatterbox?
and the web crawler heard nothing...

How do I use this? | Other CB clients
Other Users?
Others making s'mores by the fire in the courtyard of the Monastery: (5)
As of 2020-09-29 09:39 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?
    If at first I donít succeed, I Ö










    Results (146 votes). Check out past polls.

    Notices?