Re: mosbench revisited

On Wed, Aug 3, 2011 at 9:16 PM, Robert Haas <robertmhaas(at)gmail(dot)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