Re: Be strict when request to flush past end of WAL in WaitXLogInsertionsToFinish

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