On Fri, Jun 18, 2010 at 03:38:07AM -0700, Martin 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.
No problem. I was just stating it for the record. I often do "stream of thought" emails when I'm working on diagnosing a problem. > I'm now also getting negative times for some statements time in subs: (actually that's a subroutine profiler time for time spent in the sub) > 49 1 19µs 1 -90.1s $out = $q->sendRequest(\%r); > # spent - 90.1s making 1 call to XXX::Queue::sendRequest I don't see sendRequest in the profile you sent me, but I do see some negative times for subroutines. Looking at the table of all subs and sorting by inclusive time gives me: Subroutines Calls P F Exclusive Inclusive 8 1 1 -429s -105s LWP::Protocol::collect 8 1 1 6.28ms -91.3s LWP::Protocol::http::request 8 1 1 2.00ms -91.2s LWP::UserAgent::send_request 8 5 1 1.08ms -91.2s LWP::UserAgent::request 8 1 1 525µs -91.2s LWP::UserAgent::simple_request 4 1 1 10.5ms -80.8s BET::Service::User::get_job_result 5 1 1 72.2ms -80.7s BET::Service::User::call_action 5 1 1 77.4ms -80.5s main::new_request 18 4 3 1.21ms -77.2s POE::Kernel::call 5 1 1 895µs -77.2s main::__ANON__[/home/jason/bet/server/service.pl:269] 5 1 1 534µs -77.2s POE::Wheel::ReadWrite::__ANON__[/usr/local/share/perl/5.10.0/POE/Wheel/ReadWrite.pm:293] 5 1 1 123µs -77.2s POE::Component::Server::TCP::__ANON__[/usr/local/share/perl/5.10.0/POE/Component/Server/TCP.pm:323] 208 2 1 25.5ms -76.8s POE::Kernel::_data_handle_enqueue_ready 250 3 1 12.1ms -74.9s POE::Session::_invoke_state 243 7 4 20.9ms -74.8s POE::Kernel::_dispatch_event Recursion tends to cause odd timings but I'm not sure if that's the case here. I've committed a change to add recursion details to the subroutine table. The way timings are handled for subs that recurse is quite possibly broken. Tim. -- 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]
