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?

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
[download]

whereas the right version gives:

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

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                    }
[download]

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

Set trace level to N. 0 is off (the default). Higher values cause more detailed trace output.

Not sure if trolling or just didn't realize he linked to the same node....