On Friday, November 18, 2011 08:36:59 PM Kevin Grittner wrote:
> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> wrote:
> > samples % image name symbol name
> > 495463 3.6718 postgres hash_search_with_hash_value
>
> When lines like these show up in the annotated version, I'm
> impressed that we're still finding gains as big as we are:
>
> 44613 0.3306 : if (segp == NULL)
>
> : hash_corrupted(hashp);
>
> 101910 0.7552 : keysize = hashp->keysize; /* ditto */
When doing line-level profiles I would suggest looking at the instructions.
Quite often the line shown doesn't have much to do whats executed as the
compiler tries to schedule instructions cleverly.
Also in many situations the shown cost doesn't actually lie in the instruction
shown but in some previous one. The shown instruction e.g. has to wait for the
result of the earlier instructions. Pipelining makes that hard to correctly
observe.
A simplified example would be something like:
bool func(int a, int b, int c){ int res = a / b; if(res == c){ return true; } return false;
}
Likely the instruction showing up in the profile would be the comparison. Which
obviously is not the really expensive part...
> There goes over 1% of my server run time, right there!
>
> Of course, these make no sense unless there is cache line
> contention, which is why that area is bearing fruit.
I don't think cache line contention is the most likely candidate here. Simple
cache-misses seem far more likely. In combination with pipeline stalls...
Newer cpus (nehalem+) can measure stalled cycles which can be really useful
when analyzing performance. I don't remember how to do that with oprofile right
now though as I use perf these days (its -e stalled-cycles{frontend|backend}
there}).
Andres