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!

*affinity