On Jun 18, 10:17 am, Tim Bunce <[email protected]> wrote:
> Thanks for sending me the profile Martin.
>
> On Thu, Jun 17, 2010 at 11:04:11AM -0700, Martin wrote:
> > Before I get further lost in this I wonder if anyone else believes or
> > has comments on the following extract of a Devel::NYTProf run. The
> > code uses LWP::UserAgent in a POE server to retrieve ~ 30Mb file on
> > the local 1Gb network (and it takes over 400s).
>
> The overall numbers make sense though. The application run really does
> take the amount of time nytprof says, and the subroutine times and
> statement times are consistent. So I suspect perl not nytprof.
The application run really does take that time, I agree and I should
have stated that to avoid confusion - sorry.
>
>
> > I fail to see how line 158 below can take 320s.
> > Run outside of the POE Server the same POST takes around 5s with this
> > code: [...]
> > and this is the same code being run inside the POE Server.
> > Devel::NYTProf reports the top time in HTTP::Message::add_content like
> > this:
>
> > 149 sub add_content
> > ...
> > 151 7585 12.0ms my $self = shift;
> > 152 7585 22.4ms $self->_content unless exists
> > $self->{_content};
> > 153 7585 14.5ms my $chunkref = \$_[0];
> > 154 7585 14.7ms $chunkref = $$chunkref if
> > ref($$chunkref); # legacy
> > 155
> > 156 7585 66.2ms 7585 149ms _utf8_downgrade($$chunkref);
> > 157
> > 158 7585 320s my $ref = ref($self->{_content});
> > 159 7585 53.9ms if (!$ref) {
> > 160 7585 365ms $self->{_content} .= $$chunkref;
> > 161 }
>
> Something very strange is going on.
Yes in deed.
> Looking at the stream of statement timings I can see that that that line
> in that file (fid 68) starts out only taking a small amount of time
>
> Read 68:156 11 ticks
> Read 68:158 35 ticks
> Read 68:159 18 ticks
> Read 68:160 67 ticks
>
> but the time taken grows steadily, so later it's:
>
> Read 68:156 11 ticks
> Read 68:158 22197 ticks
> Read 68:159 33 ticks
> Read 68:160 284 ticks
>
> and so it grows and grows until the final execution is:
>
> Read 68:156 12 ticks
> Read 68:158 888959 ticks
> Read 68:159 64 ticks
> Read 68:160 244 ticks
Very interesting.
The code in question is:
my $ref = ref($self->{_content});
if (!$ref) {
$self->{_content} .= $$chunkref;
}
and I could see the concatenation perhaps taking longer and longer as
it is concatenating 4K chunks each time until it reaches 30Mb. I
didn't understand why the 320s was reported on the ref() though and
that is what confused me.
> Nick, does this ring any bells with you?
>
> Martin, please try with perl 5.10.1 as your 5.10.0 may be buggy.
>
> Tim.
It may take a bit longer to try 5.10.1 as we have a huge number of
modules in use but I'll have a go.
I'm now also getting negative times for some statements time in subs:
49 1 19µs 1 -90.1s $out = $q->sendRequest(\%r);
# spent - 90.1s making 1 call to XXX::Queue::sendRequest
so very strange things are happening.
Thanks for looking at it.
I'm still looking at it so I'll come back with what I find.
Martin
--
You've received this message because you are subscribed to
the Devel::NYTProf Development User group.
Group hosted at: http://groups.google.com/group/develnytprof-dev
Project hosted at: http://perl-devel-nytprof.googlecode.com
CPAN distribution: http://search.cpan.org/dist/Devel-NYTProf
To post, email: [email protected]
To unsubscribe, email: [email protected]
