Re: testing ProcArrayLock patches

On Saturday, November 19, 2011 12:18:07 AM Kevin Grittner wrote:
> Andres Freund <andres(at)anarazel(dot)de> wrote:
> > I think opannotate -a -s produces output with instructions/code
> > intermingled.
>
> Thanks. I'll check out perf later (thanks for the tips!), but for
> now, here's the function which was at the top of my oprofile
> results, annotated with those options. I'm afraid it's a bit
> intimidating to me -- the last time I did much with X86 assembly
> language was in the mid-80s, on an 80286. :-/
While my assembly knoweldge surely isn't from the 80s be assured that I find it
intimidating as well ;)

> Hopefully, since
> this is at the top of the oprofile results when running with
> prepared statements, it will be of use to somebody.
I think in quite many situations hash_search_with_hash_value is rather
noticeable in the profiles. Even without concurrency...

Looking at your annotation output the code seems to be almost entirely stalled
waiting for memory.
The first stall is after the first reading memory access which is likely to be
uncached (the first cacheline of the HTAB is accessed before but that will be
in the cache). The interesting thing is that I would have expected a higher
likelihood for this to stay in the cache.
2225 0.0165 : 70b543: mov (%rdi),%r15
:static inline uint32
:calc_bucket(HASHHDR *hctl, uint32 hash_val)
:{
: uint32 bucket;
:
: bucket = hash_val & hctl->high_mask;
4544 0.0337 : 70b546: and 0x2c(%r15),%ebx
: if (bucket > hctl->max_bucket)
53409 0.3958 : 70b54a: cmp 0x28(%r15),%ebx
: 70b54e: jbe 70b554 <hash_search_with_hash_value+0x34>

So a stall here is not that surprising.

Here we fetch data from memory which is unlikely to be prefetchable and then
require the result from that fetch. Note how segp = hashp->dir[segment_num];
is distributed over line 52, 64, 83.

: segp = hashp->dir[segment_num];
2062 0.0153 : 70b562: shr %cl,%eax
309 0.0023 : 70b564: mov %eax,%eax
643 0.0048 : 70b566: mov (%rdx,%rax,8),%rbp
:
: if (segp == NULL)
43329 0.3211 : 70b56a: test %rbp,%rbp

The next cacheline is referenced here. Again a fetch from memory which is soon
after needed to continue.
Unless I misunderstood the code-flow this disproves my theory that we might
have many collisions as that test seems to be outside the test (
: prevBucketPtr = &segp[segment_ndx];
: currBucket = *prevBucketPtr;
122 9.0e-04 : 70b586: mov 0x0(%rbp),%rbx
:
: /*
: * Follow collision chain looking for matching key
: */
: match = hashp->match; /* save one fetch in inner
loop */
: keysize = hashp->keysize; /* ditto */
99903 0.7404 : 70b58a: mov %rax,0x18(%rsp)
:
: while (currBucket != NULL)
1066 0.0079 : 70b58f: test %rbx,%rbx

line 136 is the first time the contents of the current bucket is needed. Thats
why the test is so noticeable.
: currBucket = *prevBucketPtr;
655 0.0049 : 70b5a3: mov (%rbx),%rbx
: * Follow collision chain looking for matching key
: */
: match = hashp->match; /* save one fetch in inner
loop */
: keysize = hashp->keysize; /* ditto */
:
: while (currBucket != NULL)
608 0.0045 : 70b5a6: test %rbx,%rbx
: 70b5a9: je 70b5d0 <hash_search_with_hash_value+0xb0>
: {
: if (currBucket->hashvalue == hashvalue &&
3504 0.0260 : 70b5ab: cmp %r12d,0x8(%rbx)
98486 0.7299 : 70b5af: nop
1233 0.0091 : 70b5b0: jne 70b5a0 <hash_search_with_hash_value+0x80>

That covers all the slow points in the function. And unless I am missing
something those are all the fetched cachelines of that function... For
HASH_FIND that is.

So I think that reinforces my belive that ordinary cachemisses are the culprit
here. Which is to be excepted in a hashtable...

Andres

PS: No idea whether that rambling made sense to anyone... But I looked at that
function fo the first time ;)