| From: | Thom Brown <thom(at)linux(dot)com> |
|---|---|
| To: | Nick Ivanov <nick(dot)ivanov(at)enterprisedb(dot)com> |
| Cc: | Fabrice Chapuis <fabrice636861(at)gmail(dot)com>, Robert Haas <robertmhaas(at)gmail(dot)com>, PostgreSQL Hackers <pgsql-hackers(at)lists(dot)postgresql(dot)org> |
| Subject: | Re: incremental backup issue |
| Date: | 2026-07-13 18:14:07 |
| Message-ID: | CAA-aLv4pnNVRK=-se_n6b=+eqACJ8s9s7vFokjf1J_o173dXoQ@mail.gmail.com |
| Views: | Whole Thread | Raw Message | Download mbox | Resend email |
| Thread: | |
| Lists: | pgsql-hackers |
On Mon, 13 Jul 2026 at 17:26, Nick Ivanov <nick(dot)ivanov(at)enterprisedb(dot)com> wrote:
>
> Hello Fabrice,
>
> I'm wondering if you had a chance to reproduce the problem. I'm seeing something similar, but not exactly, so I'm curious if this may be another manifestation of the error I get.
I threw this at Claude which managed to reproduce the issue, identify
the cause, and has produced a fix.
Here's the report:
A user running 17.7 reported that the walsummarizer process on a standby
logged this, over and over, every 10 seconds, and never made progress:
ERROR: could not read WAL from timeline 6 at 698/460000A0: invalid
record length at 698/460000A0: expected at least 24, got 0
698/460000A0 was the switch point from timeline 6 to timeline 7 (per the
history file); on disk, timeline 6 ends there with a shutdown checkpoint
followed by zeroes. The summarizer on the primary was fine. Restarting it
"fixed" things only in the sense that it jumped forward to the current
timeline and silently left a gap in the summaries, breaking the incremental
backup chain across that range.
I looked into it and believe there are two related problems, both in
src/backend/postmaster/walsummarizer.c.
Root cause
----------
SummarizeWAL() reads WAL up to a horizon, private_data->read_upto. On a
standby that comes from GetLatestLSN(), i.e. the greater of the WAL
receiver's flush position and the replay position. That value can sit
past the last *complete* record on the timeline being read: the flush
pointer can be a little ahead of the last good record, and a timeline
that ends at a switch point is followed by zeroed WAL space.
When the summarizer then reads into that zeroed space, XLogReadRecord()
returns the usual end-of-WAL marker (xl_tot_len == 0), reported as
"invalid record length ... got 0". SummarizeWAL() treats that as a fatal
error rather than as end of WAL, so it errors out, sleeps 10 s, and
retries from GetOldestUnsummarizedLSN() -- which returns the same place,
because nothing advanced. And because unsummarized WAL is pinned on disk
(KeepLogSeg() keeps everything >= GetOldestUnsummarizedLSN()), the
offending segment is retained forever, so the condition cannot clear on
its own. That's the 10-second loop.
The primary never hits this because there GetLatestLSN() is
GetFlushRecPtr(), which is always the end of a complete record on the
current timeline.
Separately, and contributing to the above: when SummarizeWAL() is reading
a *historic* timeline, it still sets read_upto = maximum_lsn (the latest
position on the current timeline), which can be far past where the
historic timeline ended. summarizer_read_local_xlog_page() already clamps
read_upto to the switch point when it *discovers* mid-read that a timeline
has gone historic (that's the case cf8a4898360 dealt with), and the
SummarizeWAL() header comment says maximum_lsn "should be the switch point
when reading a historic timeline" -- but the initial setup doesn't
actually clamp it.
Reproduction
------------
The attached TAP test reproduces it deterministically: stream a standby,
promote it at a chosen LSN to fork a new timeline, then overwrite the tail
of the old timeline with zeroes ahead of its switch point, and turn on
summarize_wal. Without the fix the summarizer loops on the error above and
never advances; with it, the summarizer stops cleanly at the end of valid
WAL. (The zeroing stands in for "the timeline's on-disk WAL ends, in
zeroes, before read_upto" -- which is what happens on the reporter's box,
just arrived at through the standby's position reporting rather than by
hand.)
Proposed fix
------------
0001 clamps read_upto to the switch point when reading a historic
timeline, matching the page-read callback and the documented contract.
0002 makes SummarizeWAL() recognise a zeroed record (xl_tot_len == 0, the
canonical end-of-WAL marker) as end of WAL instead of a hard error: it
ends the current summary there and waits, with backoff, for the situation
to change (more WAL, or a timeline switch that the main loop then
follows). This mirrors how recovery treats the same condition on a
standby. Other invalid records (bad CRC, bad rmid, ...) are still reported
as errors, so genuine corruption isn't masked. 0002 also carries the TAP
test.
Both patches pass the existing pg_walsummary and pg_combinebackup suites
(including 008_promote, incremental backup across a promotion).
Open question
-------------
0002 is really hardening the summarizer against a read horizon that points
past valid WAL. The deeper question -- why a standby's reported flush/
replay position ends up past the real end of a timeline in the first place
-- may deserve a separate look on the recovery side. But the summarizer
should not melt down regardless, and today it does, so I think the
hardening is worthwhile on its own.
</claude>
Patches attached.
Regards
Thom
| Attachment | Content-Type | Size |
|---|---|---|
| 0001-clamp-read-horizon.diff | text/x-patch | 1.2 KB |
| 0002-end-of-wal.diff | text/x-patch | 9.8 KB |
| From | Date | Subject | |
|---|---|---|---|
| Next Message | Tomas Vondra | 2026-07-13 18:17:27 | Re: PGLZ Compression Optimization |
| Previous Message | Bharath Rupireddy | 2026-07-13 18:07:00 | Re: Vacuum statistics |