Beefy Boxes and Bandwidth Generously Provided by pair Networks
laziness, impatience, and hubris

Re: nytprof warning

by Old_Gray_Bear (Bishop)
on Jun 03, 2011 at 23:40 UTC ( #908082=note: print w/replies, xml ) Need Help??

in reply to nytprof warning

I seem to remember reading somewhere (probably the NYTP POD) that negative times could come about on multi-core/multi-cpu SMP (Symetric Multi-Processor) machines where the code being profiled got started on one CP, took and interupt, and was re-dispatched on another CP. Since almost all modern hardware is some form SMP architecture, this probably applies to your problem. Let me go digging ...

Found it -- it's in the POD under CAVEATS -- basically each processor maintains its own personal Time Register that is synchronized with the master time-source at regular intervals. Between synch-points the Time Register may drift. There is circuitry that attempts to limit the excursion off of the synch-point, and the synch-points occur frequently enough to limit the drift, as well.

From the Fine manual:

The Processors in an SMP system do not start all at exactly the same time, therefore the timer registers are typically running at an offset. ...

In summary, SMP systems are likely to give 'noisy' profiles. Setting a "Processor Affinity" may help.

I've seen negative durations in the current profiling project, but they have been associated with routines that I expect to be interrupt-able (mostly socket-based I/O). And, the number of times the routine gets called doesn't make it a candidate for serious work -- when you have one routine that gets called 10K times at 200 milliseconds a pop, and your I/O routine gets called twice with an exclusive-time of -0.0001, who you going to concentrate on?

I Go Back to Sleep, Now.


Replies are listed 'Best First'.
Re^2: nytprof warning
by erwan (Sexton) on Jun 04, 2011 at 14:10 UTC

    Hi again,

    thank you for these explanations. I tried to profile my code using a different machine, and I did not had this problem anymore. btw I still wonder why it happens with the first machine, since my code does not contain any networking or threading stuff. Here is what happens with the negative time call:

    # spent -323s (281ms+-323) within Text::TextAnalytics::computeSimilari +tyBetweenTexts which was called

    whereas the right version gives:

    # spent 209s (521ms+208) within Text::TextAnalytics::computeSimilarity +BetweenTexts which was called

    I was not able to interpret the trace log (not sure whether there is something to interpret though?).

    Anyway, by comparing I saw that this problem does not affect the other results, so this is not a big deal (this sub is not the one I need to observe actually). Now what I would like to know is whether the following output from NYTProf looks normal to you:

    # spent 454s (262+192) within Text::TextAnalytics::CharsNGrams::getVal +ueFromKey which was called 37878646 times, avg 12Ás/call: # 37878646 +times (262s+192s) by Text::TextAnalytics::ChiSquare::chiSquareByDegre +eOfFreedomNGrams at line 85 of Text/TextAnalytics/, avg 1 +2Ás/call sub getValueFromKey { # my ($self, $ngram) = @_; # return $self->getValue($ngram); return $_[0]->getValue($_[1]); # spent 192s making 37878646 calls to Text::TextAnalytics::Cha +rsNGrams::getValue, avg 5Ás/call 115 }

    As you can see, this sub (which is crucial since it's called very often) contains only one call to another sub (almost nothing), but its exclusive time is very high -> is it due to the cost of calling it / passing parameters? Is it really so costly? This is unclear to me.


Re^2: nytprof warning
by Anonymous Monk on Aug 19, 2011 at 15:26 UTC
    I'm seeing this problem too. How exactly would I set the processor addinity?

Log In?

What's my password?
Create A New User
Node Status?
node history
Node Type: note [id://908082]
and all is quiet...

How do I use this? | Other CB clients
Other Users?
Others examining the Monastery: (4)
As of 2018-04-23 15:34 GMT
Find Nodes?
    Voting Booth?