On Jun 18, 11:38 am, Martin <[email protected]> wrote: > 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
I upgraded to Perl 5.10.1 and problem has gone away. It is going to be a PITA to do this permanently but I seem to have little choice. I've no idea what problem was fixed between 5.10.0 and 5.10.1 which caused this, I had a quick look in perldelta but nothing struck me. Thanks Tim for suggesting that. 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]
