Re: pgbench vs. wait events

Robert,

This contention on WAL reminds me of another scenario I've heard about
that was similar.

To fix things what happened was that anyone that the first person to
block would be responsible for writing out all buffers for anyone
blocked behind "him".

The for example if you have many threads, A, B, C, D

If while A is writing to WAL and hold the lock, then B arrives, B of
course blocks, then C comes along and blocks as well, then D.

Finally A finishes its write and then ....

Now you have two options for resolving this, either

1) A drops its lock, B picks up the lock... B writes its buffer and then
drops the lock. Then C gets the lock, writes its buffer, drops the
lock, then finally D gets the lock, writes its buffer and then drops the
lock.

2) A then writes out B's, C's, and D's buffers, then A drops the lock,
B, C and D wake up, note that their respective buffers are written and
just return. This greatly speeds up the system. (just be careful to
make sure A doesn't do "too much work" otherwise you can get a sort of
livelock if too many threads are blocked behind it, generally only issue
one additional flush on behalf of other threads, do not "loop until the
queue is empty")

I'm not sure if this is actually possible with the way WAL is
implemented, (or perhaps if this strategy is already implemented) but
it's definitely worth if not done already as it can speed things up
enormously.

On 10/6/16 11:38 AM, Robert Haas wrote:
> Hi,
>
> I decided to do some testing on hydra (IBM-provided community
> resource, POWER, 16 cores/64 threads, kernel 3.2.6-3.fc16.ppc64) using
> the newly-enhanced wait event stuff to try to get an idea of what
> we're waiting for during pgbench. I did 30-minute pgbench runs with
> various configurations, but all had max_connections = 200,
> shared_buffers = 8GB, maintenance_work_mem = 4GB, synchronous_commit =
> off, checkpoint_timeout = 15min, checkpoint_completion_target = 0.9,
> log_line_prefix = '%t [%p] ', max_wal_size = 40GB, log_checkpoints =
> on. During each run, I ran this psql script in another window and
> captured the output:
>
> \t
> select wait_event_type, wait_event from pg_stat_activity where pid !=
> pg_backend_pid()
> \watch 0.5
>
> Then, I used a little shell-scripting to count up the number of times
> each wait event occurred in the output. First, I tried scale factor
> 3000 with 32 clients and got these results:
>
> 1 LWLockTranche | buffer_mapping
> 9 LWLockNamed | CLogControlLock
> 14 LWLockNamed | ProcArrayLock
> 16 Lock | tuple
> 25 LWLockNamed | CheckpointerCommLock
> 49 LWLockNamed | WALBufMappingLock
> 122 LWLockTranche | clog
> 182 Lock | transactionid
> 287 LWLockNamed | XidGenLock
> 1300 Client | ClientRead
> 1375 LWLockTranche | buffer_content
> 3990 Lock | extend
> 21014 LWLockNamed | WALWriteLock
> 28497 |
> 58279 LWLockTranche | wal_insert
>
> tps = 1150.803133 (including connections establishing)
>
> What jumps out here is, at least to me, is that there is furious
> contention on both the wal_insert locks and on WALWriteLock.
> Apparently, the system simply can't get WAL on disk fast enough to
> keep up with this workload. Relation extension locks and
> buffer_content locks also are also pretty common, both ahead of
> ClientRead, a relatively uncommon wait event on this test. The load
> average on the system was only about 3 during this test, indicating
> that most processes are in fact spending most of their time off-CPU.
> The first thing I tried was switching to unlogged tables, which
> produces these results:
>
> 1 BufferPin | BufferPin
> 1 LWLockTranche | lock_manager
> 2 LWLockTranche | buffer_mapping
> 8 LWLockNamed | ProcArrayLock
> 9 LWLockNamed | CheckpointerCommLock
> 9 LWLockNamed | CLogControlLock
> 11 LWLockTranche | buffer_content
> 37 LWLockTranche | clog
> 153 Lock | tuple
> 388 LWLockNamed | XidGenLock
> 827 Lock | transactionid
> 1267 Client | ClientRead
> 20631 Lock | extend
> 91767 |
>
> tps = 1223.239416 (including connections establishing)
>
> If you don't look at the TPS number, these results look like a vast
> improvement. The overall amount of time spent not waiting for
> anything is now much higher, and the problematic locks have largely
> disappeared from the picture. However, the load average now shoots up
> to about 30, because most of the time that the backends are "not
> waiting for anything" they are in fact in kernel wait state D; that
> is, they're stuck doing I/O. This suggests that we might want to
> consider advertising a wait state when a backend is doing I/O, so we
> can measure this sort of thing.
>
> Next, I tried lowering the scale factor to something that fits in
> shared buffers. Here are the results at scale factor 300:
>
> 14 Lock | tuple
> 22 LWLockTranche | lock_manager
> 39 LWLockNamed | WALBufMappingLock
> 331 LWLockNamed | CLogControlLock
> 461 LWLockNamed | ProcArrayLock
> 536 Lock | transactionid
> 552 Lock | extend
> 716 LWLockTranche | buffer_content
> 763 LWLockNamed | XidGenLock
> 2113 LWLockNamed | WALWriteLock
> 6190 LWLockTranche | wal_insert
> 25002 Client | ClientRead
> 78466 |
>
> tps = 27651.562835 (including connections establishing)
>
> Obviously, there's a vast increase in TPS, and the backends seem to
> spend most of their time actually doing work. ClientRead is now the
> overwhelmingly dominant wait event, although wal_insert and
> WALWriteLock contention is clearly still a significant problem.
> Contention on other locks is apparently quite rare. Notice that
> client reads are really significant here - more than 20% of the time
> we sample what a backend is doing, it's waiting for the next query.
> It seems unlikely that performance on this workload can be improved
> very much by optimizing anything other than WAL writing, because no
> other wait event appears in more than 1% of the samples. It's not
> clear how much of the WAL-related stuff is artificial lock contention
> and how much of it is the limited speed at which the disk can rotate.
>
> However, I was curious about what's going on with CLogControlLock,
> persuant to the other thread on that topic, so I reran this with
> unlogged tables. At scale factor 300, 32 clients, unlogged tables, I
> get these results:
>
> 6 LWLockTranche | wal_insert
> 12 Lock | tuple
> 26 LWLockTranche | lock_manager
> 39 LWLockTranche | buffer_content
> 353 LWLockNamed | CLogControlLock
> 377 Lock | extend
> 491 Lock | transactionid
> 500 LWLockNamed | ProcArrayLock
> 696 LWLockNamed | XidGenLock
> 27685 Client | ClientRead
> 84930 |
>
> WAL contention is eliminated, and CLog contention doesn't increase.
> Next, I tried ramping up the client count to see what effect that had.
> These next three results are all at scale factor 300 with unlogged
> tables.
>
> 64 clients:
>
> 1 BufferPin | BufferPin
> 2 LWLockTranche | buffer_mapping
> 51 LWLockTranche | wal_insert
> 52 Lock | relation
> 132 LWLockTranche | lock_manager
> 154 LWLockTranche | buffer_content
> 209 Lock | tuple
> 940 Lock | extend
> 1412 LWLockNamed | XidGenLock
> 2337 LWLockNamed | CLogControlLock
> 2813 LWLockNamed | ProcArrayLock
> 3859 Lock | transactionid
> 83760 Client | ClientRead
> 133840 |
>
> tps = 36672.484524 (including connections establishing)
>
> 96 clients:
>
> 1 LWLockTranche | proc
> 53 LWLockTranche | wal_insert
> 305 LWLockTranche | buffer_content
> 391 LWLockTranche | lock_manager
> 797 Lock | tuple
> 1074 Lock | extend
> 2492 LWLockNamed | XidGenLock
> 4185 LWLockNamed | ProcArrayLock
> 6003 LWLockNamed | CLogControlLock
> 11348 Lock | transactionid
> 142881 Client | ClientRead
> 174011 |
>
> tps = 37214.257661 (including connections establishing)
>
> 192 clients:
>
> 1 LWLockTranche | buffer_mapping
> 2 BufferPin | BufferPin
> 4 LWLockTranche | clog
> 8 LWLockTranche | proc
> 87 LWLockTranche | wal_insert
> 708 LWLockTranche | buffer_content
> 1892 LWLockTranche | lock_manager
> 2225 Lock | extend
> 4796 LWLockNamed | ProcArrayLock
> 5105 LWLockNamed | XidGenLock
> 7982 Lock | tuple
> 11882 LWLockNamed | CLogControlLock
> 64091 Lock | transactionid
> 275481 |
> 308627 Client | ClientRead
>
> tps = 35018.906863 (including connections establishing)
>
> There are a couple of interesting things here. First, CLogControlLock
> contention becomes more significant as the number of the clients goes
> up. At 32 clients, it is the 6th-most frequent wait event; at 192
> clients, it's moved up to 4th, and it's clearly growing at a faster
> rate than some of the others. As we go from 32 to 64 to 96 to 192
> clients, ProcArrayLock is captured in 500, 2813, 4185, 4796 samples,
> but CLogControLock is captured in 353, 2337, 6003, 11882 samples, so
> it goes from being only 2/3 of ProcArrayLock to being more than twice
> ProcArrayLock. However, in absolute terms, it's still not very
> significant. Even at 192 clients, where it's the fourth-most-common
> wait event, it appears in only 1.7% of samples, which means backends
> are only waiting for it about 1.7% of the time. It appears that, on
> this system, this workload is NEVER going to get meaningfully faster
> by improving CLogControlLock.
>
> Second, ClientRead becomes a bigger and bigger issue as the number of
> clients increases; by 192 clients, it appears in 45% of the samples.
> That basically means that pgbench is increasingly unable to keep up
> with the server; for whatever reason, it suffers more than the server
> does from the increasing lack of CPU resources. Third,
> Lock/transactionid and Lock/tuple become more and more common as the
> number of clients increases; these happen when two different pgbench
> threads deciding to hit the same row at the same time. Due to the
> birthday paradox this increases pretty quickly as the number of
> clients ramps up, but it's not really a server issue: there's nothing
> the server can do about the possibility that two or more clients pick
> the same random number at the same time.
>