Review of v2 (applyFlushedUpto) on master 2c10c2ce4d7 --enable-cassert --enable-debug --enable-tap-tests --enable-injection-points ===== recovery suite (make check in src/test/recovery, PROVE_FLAGS=-j6) ===== v2: Files=57, Tests=802, 62 wallclock secs ( 0.45 usr 0.07 sys + 20.70 cusr 41.80 csys = 63.02 CPU) Result: PASS master: Files=56, Tests=799, 67 wallclock secs ( 0.46 usr 0.08 sys + 21.34 cusr 42.92 csys = 64.80 CPU) Result: PASS ===== 058 alone, 20 runs with v2 ===== run 1: PASS in 6 s run 2: PASS in 4 s run 3: PASS in 5 s run 4: PASS in 7 s run 5: PASS in 4 s run 6: PASS in 6 s run 7: PASS in 6 s run 8: PASS in 6 s run 9: PASS in 7 s run 10: PASS in 5 s run 11: PASS in 4 s run 12: PASS in 4 s run 13: PASS in 4 s run 14: PASS in 4 s run 15: PASS in 4 s run 16: PASS in 5 s run 17: PASS in 5 s run 18: PASS in 4 s run 19: PASS in 5 s run 20: PASS in 5 s v2: 20 passed, 0 failed of 20 ===== 058 with the test but without the C changes ===== run 1: FAIL in 77 s # poll_query_until timed out executing this query: tonly: 0 passed, 1 failed of 1 standby log: 'incorrect prev-link 0/DEADBEEF' x 663, 'started streaming WAL' x 2 ===== delay.diff (review only: 3 s between RequestXLogStreaming() and the reset) ===== diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c index 061c7e1ff5b..318d2db8c26 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -3896,6 +3896,11 @@ WaitForWALToBecomeAvailable(XLogRecPtr RecPtr, bool randAccess, * apply pointer so replay is not stalled on WAL that * is already on disk. */ + /* REVIEW ONLY: widen the window between RequestXLogStreaming() + * and the reset below, to see what happens if the new + * walreceiver flushes before the reset. */ + if (resetApplyFlush) + pg_usleep(3000000L); if (resetApplyFlush) { XLogRecPtr sharedFlush; ===== reorder.diff (review only: reset moved before RequestXLogStreaming(), same 3 s sleep after it) ===== diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c index 061c7e1ff5b..8c4760b1a78 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -3880,11 +3880,6 @@ WaitForWALToBecomeAvailable(XLogRecPtr RecPtr, bool randAccess, } curFileTLI = tli; SetInstallXLogFileSegmentActive(); - RequestXLogStreaming(tli, ptr, PrimaryConnInfo, - PrimarySlotName, - wal_receiver_create_temp_slot); - flushedUpto = InvalidXLogRecPtr; - /* * RequestXLogStreaming() rounds ptr down to a segment * boundary and leaves flushedUpto unchanged on a @@ -3911,6 +3906,15 @@ WaitForWALToBecomeAvailable(XLogRecPtr RecPtr, bool randAccess, ResetWalRcvApplyFlushRecPtr(ptr); } } + RequestXLogStreaming(tli, ptr, PrimaryConnInfo, + PrimarySlotName, + wal_receiver_create_temp_slot); + flushedUpto = InvalidXLogRecPtr; + + /* REVIEW ONLY: same 3 s window as the v2delay build, now + * after the reset instead of before it. */ + if (resetApplyFlush) + pg_usleep(3000000L); } /* ===== t/058b_stream_repair_probe.pl (058 + primary at debug2 + PROBE note) ===== --- /home/manu/pgwal/src-v2/src/test/recovery/t/058_stream_repair.pl 2026-09-24 22:39:11.024531848 -0300 +++ /home/manu/pgwal/src-v2delay/src/test/recovery/t/058b_stream_repair_probe.pl 2026-09-24 22:46:25.933116755 -0300 @@ -21,6 +21,7 @@ 'postgresql.conf', qq( autovacuum = off wal_keep_size = 1GB +log_min_messages = debug2 )); $primary->start; @@ -145,6 +146,13 @@ "SELECT pg_last_wal_replay_lsn() >= '$target_lsn'") or die "standby did not replace corrupt WAL and catch up"; +# REVIEW PROBE: did the primary have to write WAL past the target for the +# standby to get there? +my $primary_now = $primary->lsn('insert'); +my $past = $primary->safe_psql('postgres', + "SELECT pg_wal_lsn_diff('$primary_now', '$target_lsn')"); +note "PROBE target_lsn=$target_lsn primary_insert_now=$primary_now bytes_past_target=$past"; + ok( $standby->log_contains( qr/record with incorrect prev-link 0\/DEADBEEF/), 'standby observed the injected corrupt record'); ===== probe with delay.diff ===== 2026-09-24 22:46:34.626 -03 checkpointer[912365] DEBUG: snapshot of 0+0 running transaction ids (lsn 0/02000088 oldest 2026-09-24 22:46:58.978 -03 background writer[912366] DEBUG: snapshot of 0+0 running transaction ids (lsn 0/050020D8 ol 2026-09-24 22:46:34.876 -03 walreceiver[912494] LOG: started streaming WAL from primary at 0/03000000 on timeline 1 2026-09-24 22:46:38.002 -03 walreceiver[913390] LOG: started streaming WAL from primary at 0/03000000 on timeline 1 2026-09-24 22:46:38.115 -03 startup[912493] LOG: record with incorrect prev-link 0/DEADBEEF at 0/04000028 2026-09-24 22:46:38.117 -03 walreceiver[913456] LOG: started streaming WAL from primary at 0/04000000 on timeline 1 2026-09-24 22:46:41.116 -03 startup[912493] LOG: restarting WAL streaming from 0/04000018; ignoring previously flushed WAL up to 0/050020A0 [22:46:38.009](4.490s) ok 1 - receive LSN does not move backward on walreceiver restart with apply lag [22:46:59.085](21.076s) # PROBE target_lsn=0/050020A0 primary_insert_now=0/050020D8 bytes_past_target=56 [22:46:59.087](0.002s) ok 2 - standby observed the injected corrupt record [22:46:59.087](0.000s) ok 3 - standby ignored stale flush pointer after the corrupt record ===== probe with reorder.diff ===== Files=1, Tests=3, 8 wallclock secs ( 0.01 usr 0.00 sys + 0.25 cusr 0.55 csys = 0.81 CPU) Result: PASS 2026-09-24 22:48:49.248 -03 startup[957343] LOG: record with incorrect prev-link 0/DEADBEEF at 0/04000028 2026-09-24 22:48:49.248 -03 startup[957343] LOG: restarting WAL streaming from 0/04000018; ignoring previously flushed WAL up to 0/050020A0 2026-09-24 22:48:49.250 -03 walreceiver[958288] LOG: started streaming WAL from primary at 0/04000000 on timeline 1 [22:48:49.124](4.254s) ok 1 - receive LSN does not move backward on walreceiver restart with apply lag [22:48:52.371](3.247s) # PROBE target_lsn=0/050020A0 primary_insert_now=0/050020A0 bytes_past_target=0 [22:48:52.372](0.000s) ok 2 - standby observed the injected corrupt record [22:48:52.372](0.000s) ok 3 - standby ignored stale flush pointer after the corrupt record ===== v2 + nocfbot-reset-before-request.diff.txt (no sleep) ===== v2fix built, warnings=0 v2fix: 20 passed, 0 failed of 20 recovery suite v2fix: rc=0 in 45 s; Files=57, Tests=802, 43 wallclock secs ( 0.36 usr 0.06 sys + 14.60 cusr 30.96 csys = 45.98 CPU) Result: PASS