Hi, Thanks for the detailed review.
> Thanks for the patches. I don't see a CF entry yet, so I created one: > https://commitfest.postgresql.org/patch/7294/. Feel free to add > yourself as an author. There is already an entry for this work: I registered https://commitfest.postgresql.org/patch/7252/ in PG20-3 when I posted v1, and cfbot has been testing the v2 series there. Sorry that it was easy to miss — the entry hangs off this old thread's subject. Could you withdraw #7294 so we don't split the history between two entries? > What exactly caused the wait-for-any-in-progress-insertions-to-finish > to receive an LSN past the end of the generated WAL is one problem. An update on that first problem: since my last mail we have identified the in-core path that produced the bogus LSN, and reproduced the whole incident on 15.13 with plain SQL — no fault injection, no extensions involved. The source is the xlog-switch EndPos override in XLogInsertRecord() (quoted from REL_15; master has the identical computation under "class == WALINSERT_SPECIAL_SWITCH"): if (isLogSwitch) { ... if (inserted) { EndPos = StartPos + SizeOfXLogRecord; if (StartPos / XLOG_BLCKSZ != EndPos / XLOG_BLCKSZ) { uint64 offset = XLogSegmentOffset(EndPos, wal_segment_size); if (offset == EndPos % XLOG_BLCKSZ) EndPos += SizeOfXLogLongPHD; else EndPos += SizeOfXLogShortPHD; } } } When the switch record starts exactly SizeOfXLogRecord (24) bytes before a segment boundary, EndPos lands on the boundary, the page-crossing branch fires with offset == 0 == EndPos % XLOG_BLCKSZ, and EndPos becomes boundary + SizeOfXLogLongPHD = boundary + 0x28 — the incident value. The override is intended to return the end of the switch record rather than the end of the reserved segment, but in this exact-boundary case it also skips the next page header, so the result is a start-of-the-next-record position — unlike proper end positions, which stay before the header (compare XLogBytePosToEndRecPtr()). Note where it flows: the shared LogwrtRqst.Write update happens before the override, so it gets the sane pre-override value; the overridden value goes into XactLastRecEnd and the function's return value (which is what pg_switch_wal() reports). Among the in-core paths that can turn into a flush request, XactLastRecEnd is the only sink. Then, because pg_switch_wal() allocates no XID, markXidCommitted is false in RecordTransactionCommit(), so even with synchronous_commit = on the commit takes the async branch and hands exactly that value to XLogSetAsyncXactLSN(). From there the walwriter picks it up, emits the "past end of generated WAL" warning, and — without the fix — performs the header-only flush. Why it is so rare: the window is exactly that one position. If the switch record instead starts 16 or 8 bytes before the boundary, its reservation spills over and ReserveXLogSwitch() consumes the rest of the segment, so reservedUpto advances past the final EndPos and the condition never triggers. The affected installation runs a backup script that issues pg_switch_wal() every ten minutes, and one of those eventually hit the 24-byte window. The reproduction drives the insert position to boundary - 24 with pg_logical_emit_message() padding, with autovacuum disabled to reduce interference, then calls pg_switch_wal(). The primary logs the same warning with request = boundary + 0x28, the standby fails replay with the same prev-link error at + 0x28, and the standby-side segment file shows the recycled-file mechanism directly: the directory listings show the 16MB file already existed before the test with an old mtime, and afterwards its size was unchanged and only its mtime had advanced — walreceiver overwrote just the received bytes. The code involved is unchanged all the way to master. This doesn't change the patch: XLogFlush() already honors the adjusted position — it never writes past the reserved end, and then reports the mismatch with the "is not satisfied" ERROR — and the walwriter must honor the adjustment the same way. But it does mean the first problem is in-core and reproducible with SQL alone. Whether XactLastRecEnd receiving a "start of the next record" position deserves a fix of its own is a fair follow-up question; the other consumers appear to cope with it, so I kept it out of this patch series. It also lets me improve the tests: I plan to replace the C injector module in v2-0002 with a TAP test that reproduces the incident naturally via pg_logical_emit_message() + pg_switch_wal(), which should also settle the earlier injection-points discussion — there is no longer anything to inject. > If I understand correctly, you identified that the walwriter is the > problem by looking at the pid from the "request to flush past end of > generated WAL" log message, right? Nice find. Yes — the warning was logged under the walwriter's pid, and the value shape pointed the same way: a request at sub-page granularity can only reach that path through asyncXactLSN, whose sole consumer is XLogBackgroundFlush(). It also ruled out the scenario the comment in WaitXLogInsertionsToFinish() mentions (a data page with a bogus LSN): that path goes through XLogFlush() — from a backend, bgwriter or checkpointer, not the walwriter — and ends in the "not satisfied" error, and neither was observed. > Also, I'm curious, how did the standby get out of the stuck error loop > "record with incorrect prev-link"? Via the archive. About nine minutes later the segment filled up with regular traffic, was archived on completion, and the standby's restore_command fetched the intact copy over the partial local file; replay then passed the bad spot and streaming resumed. Streaming could not self-heal on its own: the dead walreceiver's flushedUpto stays in shared memory, so the startup process believed data was already available and never waited long enough for a new walreceiver to connect. That is a separate availability problem I intend to raise separately, to keep this patch focused. > Also, did you observe any "xlog flush request %X/%08X is not satisfied > --- flushed only to" or other messages on the primary? No — the only anomalous message on the primary was the "request to flush past end of generated WAL" warning. With the root cause above that is now fully explained: the bogus LSN travelled the async-commit branch, so it never went through XLogFlush(), which is where that error would have come from. The absence of that message was in fact one of the clues pointing at the async path. > And I believe if the primary had crashed before checkpointing this > WAL record, it would have also been stuck in a similar error loop, > right? I don't think it would loop, for two reasons. First, the retry loop is standby-mode behavior: the standby keeps waiting for more WAL because the advertised flush position claims it exists. Crash recovery on the primary treats the first invalid record as end-of-WAL and starts up. Second, the primary's local segment doesn't even contain the prev-link-failing bytes: the walwriter wrote out the initialized WAL buffer page (long header followed by zeros), so at +0x28 crash recovery would see a zero record length, i.e. a clean end of WAL. The standby only saw a prev-link mismatch because walreceiver overwrote just the first 40 bytes of a recycled segment, leaving stale bytes behind them. > 1/ Nit. How about using "adjusted" instead of "clamped" in the > comments and commit message? Fine by me, will do in the next version. > 2/ Why do we need to check the adjusted LSN against the requested LSN > again? Also, is there a reason to compare it with the flush LSN? Why > not just assign the adjusted LSNs like XLogFlush() does? Because the two callers want opposite things from the return value. In XLogFlush() the unconditional assignment is a deliberate group commit optimization — "try to write/flush later additions to XLOG as well" — and writing further than requested is a free win there since the caller must flush at least up to its record anyway. The walwriter's request is deliberately conservative in the other direction: the LogwrtRqst path backs off to the last completed page boundary to avoid rewriting the hot partial page, and WriteRqst.Flush is chosen by the wal_writer_delay / wal_writer_flush_after policy, including write-only cycles with Flush = 0. Unconditionally assigning the adjusted position to both would silently override those policies — raising Write into the current partial page and turning write-only cycles into fsync cycles. The fix only needs the safety direction, so it only ever lowers the targets: take the adjusted position when it is smaller than the request, and then cap Flush too, since Flush must not exceed Write. Comparing rather than assigning is what preserves the Flush = 0 write-only cycles. I'll add a comment spelling this out in the next version. > 3/ Do we need similar adjusted handling in AdvanceXLInsertBuffer()? I > don't think so because there the whole old page from the WAL buffer is > written anyway. Just want to clarify. Agreed, and for an additional reason: the request there is derived from the buffer page being evicted, which is always at or behind the current insert position, i.e. inside already-reserved WAL. So WaitXLogInsertionsToFinish() can never be asked for a position past the reserved end from that call site, and the adjusted return can't be smaller than the request. I'll post v3 with the "adjusted" wording, the comment above, and the natural-reproduction TAP test. Regards, Paul Kim
