Re: Devel::SmallProf claims "return 1" needs much time !?

whumann <w.c.humann@xxxxxxxx> wrote:
I'm trying to do some profiling on DBM::Deep. I started with
Devel::DProf and Devel::Profile but for some subs I had no idea *why*
they took long, so I tried Devel::SmallProf for additional detail.
Much of what I see makes sense but results like this puzzle me (these
are the subs that do the low-level disc read and write):

I often find SmallProf to be unreliable, especially when trying to profile
code portions which are fast on each execution but are executed very often.


count wall tm cpu time line
0 0.00000 0.00000 103:sub print_at {
314000 0.96161 3.67000 104: my $self = shift;
314000 0.88398 3.34000 105: my $loc = shift;
0 0.00000 0.00000 106:
314000 1.51351 3.89000 107: local ($/,$\);
0 0.00000 0.00000 108:
314000 1.07561 3.94000 109: my $fh = $self->{fh};
314000 4.39820 7.83000 110: if ( defined $loc ) {

This just seems weird. My 3GHz machine does an if defined test 32 times
faster, so unless you have an old computer I would say that this casts
doubt on the entire reliability of the SmallProf output.
....
0 0.00000 0.00000 115:
314000 6.65324 9.86000 116: return 1;
0 0.00000 0.00000 117:}
....

Much of the time is spent in "seek", "print" and "read" -- as expected
(although I'm surprised it's only tenths of microseconds per call -- I
suppose disc caches work their wonders...). But even more time is
spent in the two "return" statements, and I don't know why! I thought
that maybe they contain the overhead of function calling/returning but
coudn't verify that in a simple testscript.

Your return is only taking ~50-100% longer than your "if defined". While
both of them are taking absurdly long, that ratio is about what I find in a
simple test script. Is your machine old and slow? Is it perhaps swapping
itself to death during this test, or heavily loaded with other people's
processes?

If you can post the entire harness (provided it is small) you are using to
profile DBM::Deep, I'll play with it a bit.

Xho

--
-------------------- http://NewsReader.Com/ --------------------
The costs of publication of this article were defrayed in part by the
payment of page charges. This article must therefore be hereby marked
advertisement in accordance with 18 U.S.C. Section 1734 solely to indicate
this fact.
.

Relevant Pages