Devel::SmallProf claims "return 1" needs much time !?
- From: whumann <w.c.humann@xxxxxxxx>
- Date: Wed, 30 Apr 2008 05:51:21 -0700 (PDT)
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):
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 ) {
0 0.00000 0.00000 111: seek( $fh, $loc + $self-
0 0.00000 0.00000 112: }
0 0.00000 0.00000 113:
314000 3.46850 6.32000 114: print( $fh @_ ) or die
"Internal Error
0 0.00000 0.00000 115:
314000 6.65324 9.86000 116: return 1;
0 0.00000 0.00000 117:}
0 0.00000 0.00000 118:
0 0.00000 0.00000 119:sub read_at {
500507 1.43996 6.05000 120: my $self = shift;
500507 1.60207 5.78000 121: my ($loc, $size) = @_;
0 0.00000 0.00000 122:
500507 2.44265 7.01000 123: local ($/,$\);
0 0.00000 0.00000 124:
500507 1.43653 5.88000 125: my $fh = $self->{fh};
500507 7.14111 11.73000 126: if ( defined $loc ) {
0 0.00000 0.00000 127: seek( $fh, $loc + $self-
0 0.00000 0.00000 128: }
0 0.00000 0.00000 129:
500507 1.41859 6.08000 130: my $buffer;
500507 4.36185 8.77000 131: read( $fh, $buffer, $size);
0 0.00000 0.00000 132:
500507 7.96107 12.04000 133: return $buffer;
0 0.00000 0.00000 134:}
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. Is this an artifact of the
perl debugger? Or what else is the cause for this?
Thanks for any help understanding this.
Wolfram
.
- Follow-Ups:
- Prev by Date: Re: Windows mail.
- Next by Date: FAQ 3.6 How do I profile my Perl programs?
- Previous by thread: What's wrong with transparency by GD?
- Next by thread: Re: Devel::SmallProf claims "return 1" needs much time !?
- Index(es):
Relevant Pages
|
