On Oct 8, 11:21 pm, bohica <[email protected]> wrote:
> On Oct 8, 10:56 pm, Tim Bunce <[email protected]> wrote:
>
>
>
>
>
> > On Thu, Oct 08, 2009 at 11:03:29AM -0700, Martin wrote:
>
> > > Hi,
>
> > > Before D::N we used Benchmark::Timer and the code to use it still
> > > remains and we never doubted it until today. We have a server which
> > > accepts jobs, queues them, returns a job ID and then later executes
> > > them - very heavily database intensive and using DBD::Oracle. The part
> > > of the process we are looking at is the accepting a connection,
> > > reading the request, decoding it, queuing it and returning a unique ID
> > > for the job (at this point the job is not executed). Over the last few
> > > months and using D::N (big thank you BTW) we have identified problems
> > > and managed to speed things up a lot. By sheer chance today when
> > > looking at D::N output I noticed is differs massively from B::T for a
> > > particular sub. This sub is called ~600 times and B::T shows
>
> > > GET REQUEST,600 trials of GET REQUEST (32.070s total), 53.450ms/trial
>
> > > where GET_REQUEST is the tag for the _get_request sub, reporting 600
> > > calls and 32.070s in total for all 600.
>
> > > D::N on the other hand reports:
>
> > > # spent 6.03s (107ms+5.92) within main::_get_request which was called
> > > 600 times, avg 10.1ms/call: # 600 times (107ms+5.92s) at line 1277,
> > > avg 10.1ms/call
> > > Where should I start looking to locate this discrepancy?
>
> > Nothing springs to mind, since I assume we can discount recursion.
>
> > You could try using DashProfiler to get a third
> > opinion.http://www.slideshare.net/Tim.Bunce/dashprofiler-200807
>
> > Tim.
>
> We can discount recursion.
>
> Will give DashProfiler a try and report back.
>
> Martin
This is a little strange. I am starting to think D::N is slowing the
code down so it spends less time waiting for data on the socket i.e.,
at the moment as soon as a client connects it is accepted and then it
does a read on the socket and without D::N I think it is getting to
the read faster and hence spending more time blocking.
I can no longer reproduce the result I first posted :-( - I need to
unwind a lot of changes to get back to where I was - perhaps I made a
mistake but:
For B::T, D::N and DashProfiler all running together I get:
GET REQUEST,601 trials of GET REQUEST (4.330s total), 7.204ms/trial
auto > queued.pl > _get_request: dur=4.511748 count=601 (max=0.417300
avg=0.007507)
# spent 4.12s (190ms+3.93) within main::_get_request which was called
601 times, avg 6.85ms/call: # 601 times (190ms+3.93s) at line 1278,
avg 6.85ms/call
For B::T and DashProfiler running the same test case:
GET REQUEST,601 trials of GET REQUEST (15.799s total), 26.289ms/trial
auto > queued.pl > _get_request: dur=15.843982 count=601 (max=1.043370
avg=0.026363)
I think this is perhaps evidence of D:N slowing things down so less
time is spent waiting on the socket?
This also brings to mind something I meant to mention before now
(although I'm sure you are aware of it). Some of the daemons being
profiled call things like select() or wait_any (in oracle this blocks
until an alert is received) - these always come out top as they spend
most of their time waiting for something to happen. Do these subs
which wait skew the stats at all?
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]
-~----------~----~----~----~------~----~------~--~---
