On Wed, Aug 3, 2011 at 9:16 PM, Robert Haas <robertmh...@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 -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
