DProf %time ?

[Walter Roberson]

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

My program is taking the time after initialization and again after
the run, and under -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:arse_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.

 

[Ilya Zakharevich]

[A complimentary Cc of this posting was sent to
Walter Roberson

the run, and under -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:arse_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