Lost walsender wakeup stalls synchronous commits until the standby's next reply (16+)

Hi,

Since bc971f4025c (16), a physical walsender can sleep with flushed WAL it hasn't sent. With a single synchronous standby, the committing backend then waits in SyncRep until the standby's next status message: up to wal_receiver_status_interval (10 s by default).

WalSndLoop() resets the latch, and XLogSendPhysical() reads GetFlushRecPtr() and finds nothing to send. Only later does WalSndWait() join wal_flush_cv with ConditionVariablePrepareToSleep(), and it goes straight into WaitEventSetWait() without testing again. A backend whose XLogFlush() completes in between calls WalSndWakeup(), and ConditionVariableBroadcast() sets only the latches of processes already on the waitlist, so the wakeup is lost. ConditionVariablePrepareToSleep()'s header comment requires the exit condition to be tested after preparing. Before 16, WalSndWakeup() set every walsender's latch, so a wakeup after ResetLatch() couldn't be lost.

The backend is released while the walsender processes a standby reply. The walsender then goes on to read the flush pointer and head for WalSndWait(), so a client that commits again straight away often hits the window.

We hit this on 18.6 on Linux, with one synchronous standby in another availability zone and one client committing small transactions: commits stalled for up to 8 s. A probe sampling the primary every 50 ms saw five stalls of 0.2-6.2 s in about 400k commits. Throughout each one, the commit's WAL (184 or 336 bytes from pg_current_wal_insert_lsn() to sent_lsn) was unsent, the walsender was idle in WalSenderMain and the backend was waiting in SyncRep. The stalls ended on the standby's 10 s status-message cycle. With 'ANY 1 (a, b)' and two standbys we saw none in about 2M commits.

Reproduction (attached repro.sh ( http://repro.sh/ ) ): a primary and one streaming standby on one host over unix sockets, synchronous_standby_names naming the standby, and one pgbench client running a one-row insert for 120 s. macOS/arm64 builds from source, plus the Debian package in a Linux container on the same host:

build                              synchronous_commit  commits  stalls > 1 s (with the signature)

15.14                              remote_write        186,164  0, max 124 ms

16.15                              remote_write         89,909  8 (8), max 10.0 s

REL_18_STABLE 19a2002b5db          remote_write        158,943  11 (10), max 10.0 s

REL_18_STABLE 19a2002b5db          on                  104,759  14 (12), max 10.0 s

REL_18_STABLE + patch              on                  434,509  4 (0)

master 57926d757ab + patch, 300 s  remote_write        388,146  2 (0)

18.6-1.pgdg13+2, Linux             remote_write        101,218  4 (3), max 10.0 s

The signature, sampled every 50 ms for the whole stall: 176-432 bytes flushed but unsent, nothing unwritten or unflushed on the standby, the walsender in WalSenderMain and the client in IPC:SyncRep. The other stalls were host pauses, in which neither server's sampler produced any rows.

To check the mechanism directly, a test-only pg_usleep(20 ms) after send_data() in WalSndLoop() (physical, caught up; attached test-race-delay.patch) widens the window. At synchronous_commit = on in 60 s, unpatched completes 14 commits, 9 of them stalling for 4.5-10.0 s. With the fix it completes 1,194, with a maximum of 77 ms.

The attached patch rechecks after joining the waitlist. In WalSndWait(), a physical walsender in its main loop that is caught up with nothing pending compares GetFlushRecPtr() (GetStandbyFlushRecPtr() when cascading) with sentPtr after ConditionVariablePrepareToSleep(), and returns without sleeping if there is WAL to send. An alternative would be to join the CV before send_data() reads the flush pointer; I haven't tried that.

Attached: 0001-Recheck-for-WAL-after-a-physical-walsender-joins-wal.patch (applies to master 6cda9dfc4f9 and REL_18_STABLE), test-race-delay.patch (test only, not for commit), repro.sh ( http://repro.sh/ ) and analyse.py ( http://analyse.py/ ).

WalSndWaitForWal() (logical) reads the flush pointer before WalSndWait() in the same way. I couldn't reproduce a stall with a synchronous subscription and haven't looked further.

Setting wal_receiver_status_interval = 1 on the standby caps the stall at about 1 s.

Thanks,

Alex