DProf %time ?

Discussion in 'Perl Misc' started by Walter Roberson, Feb 3, 2004.

  1. I am trying to do some measurements with Devel::DProf but am having
    difficulty interpreting portions of the results.

    My program is taking the time after initialization and again after
    the run, and under -d:DProf reports 199 seconds lapsed time.

    dprofpp reports:

    Total Elapsed Time = 7.964565 Seconds
    User+System Time = 6.544565 Seconds

    which is decidedly false even when I run without profiling.

    dproff continues on to report,

    Exclusive Times
    %Time ExclSec CumulS #Calls sec/call Csec/c Name
    428. 28.06 62.969 50000 0.0006 0.0013 main::parse_line
    165. 10.83 19.502 30271 0.0004 0.0006 main::fmt_deny_acl
    74.6 4.884 4.884 233430 0.0000 0.0000 main::r_opts
    [...]

    Notice the %Time figures. One routine is taking 428% of the time??

    I can't see any relationship between "428" and any of the other times
    or sums of times.

    The CumulS figures are wrong compared to the lapsed time of
    the run with profiling enabled, but they are in the right range for
    the timing with profiling disabled. (Mind you, there's not really
    a lot of point in giving times to 3 decimal places if they can be 10%
    off of the actual times...)

    A simple "split" run over each line of the input file [the heart
    of my parse_line routine] takes about 22 seconds, so I'm working on
    tracking the other 2/3 of the time, but if the measurement tool
    is producing strange numbers, it is hard to know what to trust.
    --
    I've been working on a kernel
    All the livelong night.
    I've been working on a kernel
    And it still won't work quite right. -- J. Benson & J. Doll
    Walter Roberson, Feb 3, 2004
    #1
    1. Advertising

  2. [A complimentary Cc of this posting was sent to
    Walter Roberson
    <-cnrc.gc.ca>], who wrote in article <bvovun$fpj$>:
    > the run, and under -d:DProf reports 199 seconds lapsed time.


    > dprofpp reports:


    > Total Elapsed Time = 7.964565 Seconds
    > User+System Time = 6.544565 Seconds


    > Exclusive Times
    > %Time ExclSec CumulS #Calls sec/call Csec/c Name
    > 428. 28.06 62.969 50000 0.0006 0.0013 main::parse_line
    > 165. 10.83 19.502 30271 0.0004 0.0006 main::fmt_deny_acl
    > 74.6 4.884 4.884 233430 0.0000 0.0000 main::r_opts
    > [...]
    >
    > Notice the %Time figures. One routine is taking 428% of the time??
    >
    > I can't see any relationship between "428" and any of the other times
    > or sums of times.


    I can. 428:165:74.6 = 28.06:10.83:4.884.

    So %s are just scaled relative to a wrong total duration.

    The produced tmon.out file is mostly user-readable, and dprofpp itself
    should be quite readable. This may help your investigation...

    Hope this helps,
    Ilya
    Ilya Zakharevich, Feb 3, 2004
    #2
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. flazan

    Dprof in a multiprocess script

    flazan, May 4, 2004, in forum: Perl Misc
    Replies:
    0
    Views:
    131
    flazan
    May 4, 2004
  2. crez

    System::DProf and system()

    crez, Oct 27, 2006, in forum: Perl Misc
    Replies:
    1
    Views:
    74
  3. howa

    Profiling using DProf

    howa, Oct 31, 2008, in forum: Perl Misc
    Replies:
    2
    Views:
    99
    brian d foy
    Oct 31, 2008
  4. ++imanshu

    #calls to main::BEGIN = 6 with -d:DProf

    ++imanshu, Jan 1, 2010, in forum: Perl Misc
    Replies:
    0
    Views:
    92
    ++imanshu
    Jan 1, 2010
  5. zikester

    dprof: alternate path

    zikester, Feb 22, 2010, in forum: Perl Misc
    Replies:
    0
    Views:
    92
    zikester
    Feb 22, 2010
Loading...

Share This Page