Beefy Boxes and Bandwidth Generously Provided by pair Networks
go ahead... be a heretic
 
PerlMonks  

nytprof warning

by erwan (Acolyte)
on Jun 03, 2011 at 20:27 UTC ( #908057=perlquestion: print w/ replies, xml ) Need Help??
erwan has asked for the wisdom of the Perl Monks concerning the following question:

Hi all,

When I use the NYTProf profiler with my code (perl -d:NYTProf ...) I get the following warning:

Warning: 2 subroutine calls had negative time! The clock being used (1 +) is probably unstable, so the results will be as well.

Indeed some results seem weird in the output. Since I'm not familiar with Perl profiling (or with profiling in general!), I'd like to have more information: does it really mean that all the results are possibly corrupted? Do you have any idea about the cause, or a way to avoid this problem? Thank you!

Comment on nytprof warning
Download Code
Re: nytprof warning
by toolic (Chancellor) on Jun 03, 2011 at 20:52 UTC
    I don't know what it means or how to avoid it, but the Devel::NYTProf POD mentions how you might be able to get more info:
    Set trace level to N. 0 is off (the default). Higher values cause more detailed trace output.
    I also used the CPAN grep feature to search for your warning, and it comes from the NYTProf.xs file.
Re: nytprof warning
by Old_Gray_Bear (Bishop) on Jun 03, 2011 at 23:40 UTC
    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.

    OGB

      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/ChiSquare.pm, 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.

      Thanks!

      I'm seeing this problem too. How exactly would I set the processor addinity?
        *affinity
Re: nytprof warning
by tim.bunce (Scribe) on Jun 27, 2012 at 13:24 UTC
      Not sure if trolling or just didn't realize he linked to the same node....

Log In?
Username:
Password:

What's my password?
Create A New User
Node Status?
node history
Node Type: perlquestion [id://908057]
Approved by toolic
help
Chatterbox?
and the web crawler heard nothing...

How do I use this? | Other CB clients
Other Users?
Others avoiding work at the Monastery: (5)
As of 2014-09-22 11:54 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    How do you remember the number of days in each month?











    Results (190 votes), past polls