Re: mosbench revisited

On Wed, Aug 3, 2011 at 9:16 PM, Robert Haas <robertmhaas@gmail.com> wrote:
> Spinlocks seem to have a very ugly "tipping point".

And on that note, here are oprofile results from "pgbench -n -T 300 -S
-c 64 -j 64 -M prepared" on the latest master branch, compiled with
"-O2 -fno-omit-frame-pointer".  shared_buffers=8GB, 64-core machine,
RHEL 6.1.  By running with "-M prepared", it dodges the lseek()
problem.

960576   23.7580  postgres                 postgres                 s_lock
562821   13.9203  no-vmlinux               no-vmlinux               /no-vmlinux
321191    7.9440  postgres                 postgres
LWLockRelease
317653    7.8565  postgres                 postgres
LWLockAcquire
224812    5.5603  postgres                 postgres
GetSnapshotData
81156     2.0072  postgres                 postgres                 _bt_compare
78744     1.9476  postgres                 postgres                 PinBuffer
58101     1.4370  postgres                 postgres
hash_search_with_hash_value
43865     1.0849  postgres                 postgres
AllocSetAlloc
25832     0.6389  postgres                 postgres                 PostgresMain

Since SpinLockAcquire() is an in-line macro that only calls s_lock()
if the initial TAS fails, not only the time directly attributed to
s_lock but also a good chunk of the CPU time attributable to
LWLockAcquire and LWLockRelease() is likely time spent fighting over
spinlocks.  Since I compiled with frame pointers, it's pretty easy to
see where those s_lock calls are coming from.  Here's an excerpt from
opreport -c:
5        5.0e-04  postgres                 postgres                 _bt_getbuf 6        6.0e-04  postgres
 postgres
 
_bt_relandgetbuf 14        0.0014  postgres                 postgres
ReleaseAndReadBuffer 85        0.0085  postgres                 postgres
ReadBuffer_common 206       0.0207  postgres                 postgres
GetSnapshotData 18344     1.8437  postgres                 postgres
UnpinBuffer 24977     2.5103  postgres                 postgres                 PinBuffer 406948   40.9009  postgres
            postgres
 
LWLockRelease 544376   54.7133  postgres                 postgres
LWLockAcquire
994947   23.5746  postgres                 postgres                 s_lock

It's also fairly easy to track down who is calling LWLockAcquire and
LWLockRelease.  Nearly all of the calls are from just two
contributors:
 241655   27.6830  postgres                 postgres
ReadBuffer_common 566434   64.8885  postgres                 postgres
GetSnapshotData
328548    7.7847  postgres                 postgres
LWLockAcquire
 176629   23.8917  postgres                 postgres
ReadBuffer_common 524348   70.9259  postgres                 postgres
GetSnapshotData
332333    7.8744  postgres                 postgres
LWLockRelease

So, most of the s_lock calls come from LWLockAcquire, and most of the
LWLockAcquire calls come from GetSnapshotData.  That's not quite
enough to prove that all the spinning going on here is coming from
contention over the spinlock protecting ProcArrayLock, because it
needn't be the case that all calls to LWLockAcquire are equally likely
to end up in s_lock.  You could speculate that ProcArrayLock isn't
actually responsible for many of those s_lock calls and that some
other lock, like maybe the buffer mapping locks, is disproportionately
responsible for the s_lock calls.  But in fact I think it's exactly
the other way around: the buffer mapping locks are partitioned 16
ways, while there's only one ProcArrayLock.  I'm willing to bet that's
where nearly all of the spinning is happening, and I'll further bet
that that spinning accounts for AT LEAST a third of the total CPU time
on this workload.  And maybe closer to half.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company