1193 back ends waiting on an append

1193 backends waiting on an append

1193 backends waiting on an append July 17, 2026We got another Postgres IO incident this week, but this time IORead wasn’t the bottleneck. The instance was an AWS RDS on gp3 with 12k provisioned IOPS, and after a few hours EBSIOBalance slowly dropped to 0%. During peak: 9k IOWrite, 6k connections (200 is the baseline), checkpointlag spiked to 4 hours. At the same time, we hit the antiwraparound threshold of 200M and autovacuum was triggered, starting the scan of 237 databases (yes, the data model in this one is interesting - this instance has 10k+ databases). wait_event_type | wait_event | count -----------------+---------------------+------- LWLock | WALWrite | 1193 IO | DataFileRead | 194 LWLock | pg_stat_statements | 23 | | 23 IPC | CheckpointStart | 14 IPC | BufferIo | 8 Lock | transactionid | 4 IO | DataFileWrite | 4 Client | ClientRead | 3 Lock | frozenid | 2 IO | WalSync | 1 IO | DataFileExtend | 1 IO | SlruRead | 1 IPC | CheckpointDone | 1 1193 LWLock on WALWrite surprised me. This database doesn’t receive many writes. Most of the load is doing scans on big tables, so at first I thought: Oh, ok, another bad monday because of sequential scans. But that wasn’t it. Why are backend processes being locked behind a simple wal write? My first guess, before I looked at pg_stats, was the autovacuum. But look at that: only two processes locked on frozenid. That wasn’t it. DataFileRead also surprised me: 194 against 1193 WALWrite locks. This is basically six to one. Another thing: WALWrite is not an IO wait, it’s a lock event. Processes were waiting on each other. I remember I thought: but why? Appending to WAL is not an expensive operation. A WAL record is small, and writing to it is an append. Well, today, a few days after the incident, I had the chance to dig deeper by reading xlog.c in the source code. The mental model after this: we have two paths the insert side and the flush side. The first thing I found was the insert side. * Inserting to WAL is protected by a small fixed number of WAL insertion * locks. To insert to the WAL, you must hold one of the locks - it doesn't * matter which one. We have 8 NUM_XLOGINSERT_LOCKS. The insert itself is two steps: * 1. Reserve the right amount of space from the WAL. The current head of * reserved space is kept in Insert->CurrBytePos, and is protected by * insertpos_lck. * 2. Copy the record to the reserved WAL space. This involves finding the * correct WAL buffer containing the reserved space, and copying the * record in place. This can be done concurrently in multiple processes. Step 1 is serialized, and they say so in ReserveXLogInsertLocation: * This is the performance critical part of XLogInsert that must be serialized * across backends. The rest can happen mostly in parallel. Try to keep this * section as short as possible, insertpos_lck can be heavily contended on a * busy system. But look at what it does under that spinlock: SpinLockAcquire(&Insert->insertpos_lck);

startbytepos = Insert->CurrBytePos; endbytepos = startbytepos + size; prevbytepos = Insert->PrevBytePos; Insert->CurrBytePos = endbytepos; Insert->PrevBytePos = startbytepos;

SpinLockRelease(&Insert->insertpos_lck); That’s only three reads and two writes. Not that much work. If this was the problem, I would’ve seen LWLock:WALInsertLock. But I didn’t. The flush path is more interesting: * WALWriteLock: must be held to write WAL buffers to disk (XLogWrite or * XLogFlush). (...) * info_lck is only held long enough to read/update the protected variables, * so it's a plain spinlock. The other locks are held longer (potentially * over I/O operations), so we use LWLocks for them. So flush is 1 lock, exclusive. Very different from the 8 locks of the insert path. Since there’s only one WAL stream and one device, this is where successful inserts fall into. It makes sense. XLogWrite does a pg_pwrite under that lock. pwrite is somewhat cheap since it doesn’t persist to disk, but is satisfied once it hits the OS page cache. After that, we get fsync - issue_xlog_fsync, which goes through the block layer, the driver, across the EBS network. So everything is memory except the fsync step. This also makes sense. Out of all those 1193 backends, only one backend was doing something, the other ones are waiting on a futex - D state processes. The EBSIOBalance dropping to 0% doesn’t signal anything to the kernel because there were no errors - things were waiting on a lock, that’s it. Once EBSIOBalance reached zero, requests beyond the baseline were effectively throttled, increasing fsync latency. From the kernel’s point of view the device got slower, and the fsync inside the critical section takes longer, the lock is held longer, and 1193 backends wait longer for the lock. Compare it to the IO:DataFileRead, which is a classical wait event. We had 194 backends issuing a pread, each waiting on their own IO....

1193 back ends waiting on an append

Related Articles

(no title)

Scientists reverse brain aging, with a nasal spray

AI has torched the market for junior programmers

Al Vigier: Canada's AI strategy shouldn't include secret Palantir bills

The Anatomy of an AI-Native Org