Hi,
While hacking on an improvement for the recovery prefetcher, I ran into
a pre-existing bug present since PG 15. The brief explanation is that
XLogPrefetcherBeginRead resets a bunch of stuff, but not the pointer
prefetcher->record. In some circumstances (full I/O queue, ...) that
happens to confuse XLogPrefetcherReadRecord, triggering failures:
- assert failures on development builds
Assert(lrq_completed(prefetcher->streaming_read) == 0);
- a bunch of weird/uncommon errors on regular builds
LOG: request to flush past end of generated WAL; request 0/030BBD90,
current position 0/030B9D48
ERROR: xlog flush request 0/030BBD90 is not satisfied --- flushed
only to 0/030B9D48
FATAL: checkpoint request failed
AFAICS it can happen only with reduced maintenance_io_concurrency, but
I'm not sure about that. Maybe there's a way to generate WAL records
with enough block images.
The attached patch fixes this by simply resetting the record to NULL in
XLogPrefetcherBeginRead. It also introduces a new TAP test triggering
this, using a SP-GiST index built etc.
I'm not sure if we want to add the TAP test, I'm attaching it more as a
way to reproduce the issue. Without the fix in XLogPrefetcherBeginRead,
it crashes with errors similar to the attached logs.
regards
--
Tomas Vondra
From 1d3c2796674af1cef3bf34e4e7ccb6c96f74ae76 Mon Sep 17 00:00:00 2001
From: Tomas Vondra <[email protected]>
Date: Sun, 25 Oct 2026 10:46:39 -0400
Subject: [PATCH] Forget the prefetcher's current record in
XLogPrefetcherBeginRead()
XLogPrefetcherBeginRead() discards the queue of records etc. It however
kept prefetcher->record, the record whose block references are examined
by XLogPrefetcherNextBlock().
That pointer is cleared once all block references have been examined, or
when XLogPrefetcherReadRecord() returns the record (see adb466150b4). A
record that was decoded and not returned yet survived the reset. The
next XLogPrefetcherReadRecord() call then continued with the remaining
block references of that stale record, and decoded the record at the new
read position only after those.
That matters in FinishWalRecovery(), which re-reads the last replayed
record after the redo loop to find out where WAL ends. When recovery
stops at a recovery target, the prefetcher may be part-way through a
later record. If the remaining block references of that record fill up
the new I/O queue (4 * maintenance_io_concurrency entries, or
maintenance_io_concurrency references that need I/O), no record is
decoded at all, and:
- Assert-enabled builds fail an assertion in XLogPrefetcherReadRecord()
that expects the I/O queue to be empty when no records are queued,
"lrq_completed(prefetcher->streaming_read) == 0" (or the
lrq_inflight() one, if some of the block references needed I/O).
- Other builds return NULL from ReadRecord() without an error, and
FinishWalRecovery() treats the start of the last replayed record as
the end of WAL. The history file of the new timeline is written with
that wrong switch point, and the end-of-recovery checkpoint then fails
with "xlog flush request ... is not satisfied" while writing a page
modified by the last replayed record, followed by "FATAL: checkpoint
request failed". The recovery signal file has already been removed
at that point, so simply restarting the server performs crash
recovery to the end of the WAL in pg_wal, past the recovery target.
XLOG_FPI records written by bulk index builds, CLUSTER and similar
operations carry up to XLR_MAX_BLOCK_ID block references that need no
I/O. The prefetcher has examined at least one of them, so the rest can
fill-up the I/O queue when maintenance_io_concurrency is set to 7 or
less, if the recovery target is shortly before such a record.
With higher settings, it needs a record with at least
maintenance_io_concurrency remaining block references that need I/O,
which is unusual.
Fix by forgetting the current record in XLogPrefetcherBeginRead(). The
other callers run before the redo loop, after reading a single record
without any readahead (see begin_ptr), so the prefetcher has no current
record at that point.
Add a TAP test that stops recovery before the record preceding the first
multi-block XLOG_FPI record of an SP-GiST index build, with
maintenance_io_concurrency = 1, so that the prefetcher is part-way
through the FPI record when recovery ends. The test uses SP-GiST rather
than B-tree, and compares LSNs as pg_lsn rather than as strings, so that
it works unchanged in the back branches: B-tree builds before 17 WAL-log
each page in a separate record, and the server log in 15-18 doesn't
zero-pad LSNs.
Backpatch-through: 15
---
src/backend/access/transam/xlogprefetcher.c | 8 ++
src/test/recovery/meson.build | 1 +
.../t/061_recovery_target_prefetch.pl | 94 +++++++++++++++++++
3 files changed, 103 insertions(+)
create mode 100644 src/test/recovery/t/061_recovery_target_prefetch.pl
diff --git a/src/backend/access/transam/xlogprefetcher.c b/src/backend/access/transam/xlogprefetcher.c
index dff57642ab4..5be2f34ef6f 100644
--- a/src/backend/access/transam/xlogprefetcher.c
+++ b/src/backend/access/transam/xlogprefetcher.c
@@ -975,6 +975,14 @@ XLogPrefetcherBeginRead(XLogPrefetcher *prefetcher, XLogRecPtr recPtr)
prefetcher->no_readahead_until = InvalidXLogRecPtr;
+ /*
+ * Forget the record we were examining, if any. It is about to be
+ * discarded along with the rest of the decoder's queue, and continuing
+ * with its remaining block references could fill up the new I/O queue
+ * before the record at recPtr is decoded.
+ */
+ prefetcher->record = NULL;
+
/* This will forget about any queued up records in the decoder. */
XLogBeginRead(prefetcher->reader, recPtr);
}
diff --git a/src/test/recovery/meson.build b/src/test/recovery/meson.build
index b6ac9dd07a7..cb3df6ed895 100644
--- a/src/test/recovery/meson.build
+++ b/src/test/recovery/meson.build
@@ -69,6 +69,7 @@ tests += {
't/058_shutdown_crash_restart.pl',
't/059_remote_apply_status_interval.pl',
't/060_multixact_crashed_updater.pl',
+ 't/061_recovery_target_prefetch.pl',
],
},
}
diff --git a/src/test/recovery/t/061_recovery_target_prefetch.pl b/src/test/recovery/t/061_recovery_target_prefetch.pl
new file mode 100644
index 00000000000..96f94d31b20
--- /dev/null
+++ b/src/test/recovery/t/061_recovery_target_prefetch.pl
@@ -0,0 +1,94 @@
+# Copyright (c) 2026, PostgreSQL Global Development Group
+
+# Test that recovery ends correctly when a recovery target is reached while
+# the WAL prefetcher is part-way through a later record with many block
+# references.
+
+use strict;
+use warnings FATAL => 'all';
+
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+my $node_primary = PostgreSQL::Test::Cluster->new('primary');
+$node_primary->init(has_archiving => 1, allows_streaming => 1);
+$node_primary->start;
+
+$node_primary->safe_psql(
+ 'postgres',
+ "CREATE TABLE t (i int, v text);
+ INSERT INTO t SELECT i, md5(i::text) FROM generate_series(1, 10000) i;"
+);
+$node_primary->backup('backup');
+
+# An SP-GiST build WAL-logs the new index with log_newpage_range(), in
+# XLOG_FPI records with up to XLR_MAX_BLOCK_ID block references each.
+my $start_lsn =
+ $node_primary->safe_psql('postgres', 'SELECT pg_current_wal_insert_lsn()');
+$node_primary->safe_psql('postgres',
+ 'CREATE INDEX t_v ON t USING spgist (v)');
+my $end_lsn =
+ $node_primary->safe_psql('postgres', 'SELECT pg_current_wal_insert_lsn()');
+my $walfile = $node_primary->safe_psql('postgres',
+ 'SELECT pg_walfile_name(pg_current_wal_lsn())');
+$node_primary->safe_psql('postgres', 'SELECT pg_switch_wal()');
+$node_primary->poll_query_until('postgres',
+ "SELECT last_archived_wal >= '$walfile' FROM pg_stat_archiver")
+ or die "timed out waiting for WAL to be archived";
+
+# Stop recovery before the record preceding the first FPI record with many
+# block references, rather than before the FPI record itself, because the
+# prefetcher forgets about a record once it has been read (even if it is not
+# replayed). With maintenance_io_concurrency = 1, the prefetcher only looks a
+# few block references ahead, so it is part-way through the FPI record when
+# recovery ends.
+my ($stdout, $stderr) = run_command(
+ [
+ 'pg_waldump',
+ '--path' => $node_primary->archive_dir,
+ '--start' => $start_lsn,
+ '--end' => $end_lsn,
+ ]);
+$stdout =~ /prev ([0-9A-F]+\/[0-9A-F]+), desc: FPI , .*blkref #8: /
+ or die "could not find an FPI record with many block references";
+my $target_lsn = $1;
+
+my $node_standby = PostgreSQL::Test::Cluster->new('standby');
+$node_standby->init_from_backup(
+ $node_primary, 'backup',
+ has_restoring => 1,
+ standby => 0);
+$node_standby->append_conf(
+ 'postgresql.conf', qq(
+maintenance_io_concurrency = 1
+recovery_target_lsn = '$target_lsn'
+recovery_target_inclusive = off
+recovery_target_action = 'promote'
+));
+$node_standby->start;
+$node_standby->poll_query_until('postgres', 'SELECT NOT pg_is_in_recovery()')
+ or die "timed out waiting for promotion";
+
+# Compare the LSNs as pg_lsn, so as not to depend on how they're formatted.
+my ($stop_lsn) =
+ slurp_file($node_standby->logfile) =~
+ /recovery stopping before WAL location \(LSN\) "([0-9A-F]+\/[0-9A-F]+)"/
+ or die "could not find where recovery stopped in the server log";
+is( $node_standby->safe_psql(
+ 'postgres', "SELECT '$stop_lsn'::pg_lsn = '$target_lsn'::pg_lsn"),
+ 't',
+ 'recovery stopped at the target');
+is( $node_standby->safe_psql(
+ 'postgres', "SELECT count(*), to_regclass('t_v') IS NULL FROM t"),
+ '10000|t',
+ 'data matches the recovery target');
+
+# Check that the WAL written on the new timeline can be replayed.
+$node_standby->safe_psql('postgres', 'INSERT INTO t VALUES (0)');
+$node_standby->stop('immediate');
+$node_standby->start;
+is($node_standby->safe_psql('postgres', 'SELECT count(*) FROM t'),
+ '10001', 'crash recovery after promotion');
+
+done_testing();
--
2.55.0
2026-10-25 20:51:57.687 CET postmaster[2029885] LOG: starting PostgreSQL 20devel on x86_64-pc-linux-gnu, compiled by clang version 21.1.8 (Fedora 21.1.8-6.fc43), 64-bit
2026-10-25 20:51:57.687 CET postmaster[2029885] LOG: listening on Unix socket "/tmp/Kdhey9VGHv/.s.PGSQL.14064"
2026-10-25 20:51:57.691 CET startup[2029890] LOG: database system was interrupted; last known up at 2026-10-25 20:51:57 CET
cp: cannot stat '/home/user/work/postgres/src/test/recovery/tmp_check/t_061_recovery_target_prefetch_primary_data/archives/00000002.history': No such file or directory
2026-10-25 20:51:57.694 CET startup[2029890] LOG: starting backup recovery with redo LSN 0/02000028, checkpoint LSN 0/02000088, on timeline ID 1
2026-10-25 20:51:57.698 CET startup[2029890] LOG: restored log file "000000010000000000000002" from archive
2026-10-25 20:51:57.709 CET startup[2029890] LOG: starting point-in-time recovery to WAL location (LSN) "0/030BBD90"
2026-10-25 20:51:57.710 CET startup[2029890] LOG: redo starts at 0/02000028
2026-10-25 20:51:57.716 CET startup[2029890] LOG: restored log file "000000010000000000000003" from archive
2026-10-25 20:51:57.716 CET startup[2029890] LOG: completed backup recovery with redo LSN 0/02000028 and end LSN 0/02000138
2026-10-25 20:51:57.716 CET startup[2029890] LOG: consistent recovery state reached at 0/02000138
2026-10-25 20:51:57.717 CET postmaster[2029885] LOG: database system is ready to accept read-only connections
2026-10-25 20:51:57.721 CET startup[2029890] LOG: recovery stopping before WAL location (LSN) "0/030BBD90"
2026-10-25 20:51:57.721 CET startup[2029890] LOG: redo done at 0/030BBD90 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s
TRAP: failed Assert("lrq_completed(prefetcher->streaming_read) == 0"), File: "xlogprefetcher.c", Line: 1050, PID: 2029890
postgres: standby: startup recovering 000000010000000000000003(__interceptor_backtrace+0x4a) [0x44b2aa]
postgres: standby: startup recovering 000000010000000000000003(ExceptionalCondition+0x1c1) [0x3882ca1]
postgres: standby: startup recovering 000000010000000000000003(XLogPrefetcherReadRecord+0x8c5) [0xbcc735]
postgres: standby: startup recovering 000000010000000000000003() [0xbfcf59]
postgres: standby: startup recovering 000000010000000000000003(FinishWalRecovery+0x25b) [0xbff72b]
postgres: standby: startup recovering 000000010000000000000003(StartupXLOG+0x2d98) [0xb89ce8]
postgres: standby: startup recovering 000000010000000000000003(StartupProcessMain+0x143) [0x262ff23]
postgres: standby: startup recovering 000000010000000000000003(postmaster_child_launch+0x8eb) [0x26138fb]
postgres: standby: startup recovering 000000010000000000000003() [0x2623556]
postgres: standby: startup recovering 000000010000000000000003(PostmasterMain+0x37e1) [0x26219f1]
postgres: standby: startup recovering 000000010000000000000003(main+0xebd) [0x1c1bb4d]
/lib64/libc.so.6(+0x35b5) [0x7340ffa115b5]
/lib64/libc.so.6(__libc_start_main+0x88) [0x7340ffa11668]
postgres: standby: startup recovering 000000010000000000000003(_start+0x25) [0x401275]
2026-10-25 20:51:57.725 CET postmaster[2029885] LOG: startup process (PID 2029890) was terminated by signal 6: Aborted
2026-10-25 20:51:57.725 CET postmaster[2029885] LOG: terminating any other active server processes
2026-10-25 20:51:57.727 CET postmaster[2029885] LOG: shutting down due to startup process failure
2026-10-25 20:51:57.728 CET postmaster[2029885] LOG: database system is shut down
2026-10-25 20:49:28.057 CET postmaster[2022545] LOG: starting PostgreSQL 20devel on x86_64-pc-linux-gnu, compiled by clang version 21.1.8 (Fedora 21.1.8-6.fc43), 64-bit
2026-10-25 20:49:28.057 CET postmaster[2022545] LOG: listening on Unix socket "/tmp/zxaWZD0jH2/.s.PGSQL.20889"
2026-10-25 20:49:28.061 CET startup[2022550] LOG: database system was interrupted; last known up at 2026-10-25 20:49:27 CET
cp: cannot stat '/home/user/work/postgres/src/test/recovery/tmp_check/t_061_recovery_target_prefetch_primary_data/archives/00000002.history': No such file or directory
2026-10-25 20:49:28.063 CET startup[2022550] LOG: starting backup recovery with redo LSN 0/02000028, checkpoint LSN 0/02000088, on timeline ID 1
2026-10-25 20:49:28.069 CET startup[2022550] LOG: restored log file "000000010000000000000002" from archive
2026-10-25 20:49:28.096 CET startup[2022550] LOG: starting point-in-time recovery to WAL location (LSN) "0/030BBD90"
2026-10-25 20:49:28.098 CET startup[2022550] LOG: redo starts at 0/02000028
2026-10-25 20:49:28.113 CET startup[2022550] LOG: restored log file "000000010000000000000003" from archive
2026-10-25 20:49:28.114 CET startup[2022550] LOG: completed backup recovery with redo LSN 0/02000028 and end LSN 0/02000138
2026-10-25 20:49:28.114 CET startup[2022550] LOG: consistent recovery state reached at 0/02000138
2026-10-25 20:49:28.114 CET postmaster[2022545] LOG: database system is ready to accept read-only connections
2026-10-25 20:49:28.119 CET startup[2022550] LOG: recovery stopping before WAL location (LSN) "0/030BBD90"
2026-10-25 20:49:28.119 CET startup[2022550] LOG: redo done at 0/030BBD90 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.02 s
cp: cannot stat '/home/user/work/postgres/src/test/recovery/tmp_check/t_061_recovery_target_prefetch_primary_data/archives/00000002.history': No such file or directory
2026-10-25 20:49:28.125 CET startup[2022550] LOG: selected new timeline ID: 2
cp: cannot stat '/home/user/work/postgres/src/test/recovery/tmp_check/t_061_recovery_target_prefetch_primary_data/archives/00000001.history': No such file or directory
2026-10-25 20:49:28.137 CET startup[2022550] LOG: archive recovery complete
2026-10-25 20:49:28.138 CET checkpointer[2022548] LOG: checkpoint starting: end-of-recovery fast wait
2026-10-25 20:49:28.142 CET checkpointer[2022548] LOG: request to flush past end of generated WAL; request 0/030BBD90, current position 0/030B9D48
2026-10-25 20:49:28.142 CET checkpointer[2022548] CONTEXT: writing block 82 of relation "base/5/16384"
2026-10-25 20:49:28.143 CET checkpointer[2022548] ERROR: xlog flush request 0/030BBD90 is not satisfied --- flushed only to 0/030B9D48
2026-10-25 20:49:28.143 CET checkpointer[2022548] CONTEXT: writing block 82 of relation "base/5/16384"
2026-10-25 20:49:28.143 CET startup[2022550] FATAL: checkpoint request failed
2026-10-25 20:49:28.143 CET startup[2022550] HINT: Consult recent messages in the server log for details.
2026-10-25 20:49:28.153 CET postmaster[2022545] LOG: startup process (PID 2022550) exited with exit code 1
2026-10-25 20:49:28.153 CET postmaster[2022545] LOG: terminating any other active server processes
2026-10-25 20:49:28.154 CET postmaster[2022545] LOG: shutting down due to startup process failure
2026-10-25 20:49:28.156 CET postmaster[2022545] LOG: database system is shut down
