From 3aa9ee4a814cfb1c7efcd7cdbced7766ebf96c55 Mon Sep 17 00:00:00 2001 From: Ritesh Kumar Date: Sun, 8 Nov 2026 01:30:47 +0800 Subject: [PATCH v3 2/2] Test progress-reporting is unaffected by recovery conflicts MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add a section to `031_recovery_conflict.pl' that checks “redo in progress” is still logged after a lock or buffer pin recovery conflict. `ResolveRecoveryConflictWithLock()' and `ResolveRecoveryConflictWithBufferPin()' used to cancel every timeout of the startup process, including `STARTUP_PROGRESS_TIMEOUT'. The test logic waits for named events, and the names differ across branches: ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ Branch(es) Name Remarks ─────────────────────────────────────────────────────────────────── master, REL19 BufferCleanup - REL18, REL17 BufferPin - REL16, REL15 fns `wait_for_event', `advance_wal' inlined since they don’t exist ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ Table 1: Differences in test-logic across branches 031_recovery_conflict.pl tests are ALL skipped on REL16 and REL15 because it's unstable. Temporarily allowing them allows this TAP test addition to be useful for verification. Discussion: --- src/test/recovery/t/031_recovery_conflict.pl | 293 +++++++++++++++++++ src/test/recovery/t/restore_on_gate_open | 46 +++ 2 files changed, 339 insertions(+) create mode 100644 src/test/recovery/t/restore_on_gate_open diff --git a/src/test/recovery/t/031_recovery_conflict.pl b/src/test/recovery/t/031_recovery_conflict.pl index d3f4f591661..e6728862cdd 100644 --- a/src/test/recovery/t/031_recovery_conflict.pl +++ b/src/test/recovery/t/031_recovery_conflict.pl @@ -6,6 +6,7 @@ use strict; use warnings FATAL => 'all'; +use FindBin; use PostgreSQL::Test::Cluster; use PostgreSQL::Test::Utils; use Test::More; @@ -315,6 +316,298 @@ $node_standby->stop(); $node_primary->stop(); +## RECOVERY CONFLICT 7: Progress reporting survives conflicts +# +# The startup process logs "redo in progress" every +# log_startup_progress_interval. It must keep doing so after replay has +# waited out a recovery conflict. +# +# The resolvers for lock and buffer pin conflicts, +# ResolveRecoveryConflictWithLock() and ResolveRecoveryConflictWithBufferPin(), +# set up timeouts of their own and cancel them when the conflict is resolved. +# They must not also cancel STARTUP_PROGRESS_TIMEOUT. This section checks +# both resolvers' paths. +# +# The test doesn't depend on how fast replay runs. The restore_command, +# restore_on_gate_open, holds the startup process at two WAL segment boundaries +# until the test releases it: +# +# hold 1 -> [segment with the conflicting record] -> hold 2 -> [next segment] +# +# A held startup process can't log, but its progress timer keeps running and +# sets a flag once the interval has elapsed. The first record replayed after +# a hold then logs "redo in progress", if the timer is still armed. So: +# +# 1. At hold 1, a session takes the lock or pin that replay of the +# conflicting record needs. After the hold is released, progress is +# reported (the timer is armed), and replay then waits for the session. +# 2. The session ends its transaction. Replay resolves the conflict, which +# is where the timer used to be canceled, and reaches hold 2. +# 3. After hold 2 is released, progress is reported only if the timer +# survived the conflict. +# +# The nodes here do archive recovery (recovery.signal) with hot_standby on: +# redo progress is never reported in standby mode, so the streaming standby +# tests above can't show this. +$sect = "progress after conflict"; + +{ + my $table_lock = 'test_recovery_conflict_progress_lock'; + my $table_pin = 'test_recovery_conflict_progress_pin'; + my $backup_progress = 'backup_progress'; + + # Value of log_startup_progress_interval. + my $progress_interval_ms = 10; + + # How long to keep the startup process held, so that the progress interval + # has elapsed by the time it's released. This is not a race: the startup + # process can't move while it's held, and the progress timer is a kernel + # timer that fires during the hold whatever the load, so this only has to + # be longer than the interval. The margin covers timer slack. + my $hold_usec = 3 * $progress_interval_ms * 1000; + + # Our own primary, which archives its WAL and has none of the settings + # above (tablespaces, short standby delays). Without autovacuum, the only + # pruning is the one the test asks for. + my $node_wal = PostgreSQL::Test::Cluster->new('progress_primary'); + $node_wal->init(allows_streaming => 1, has_archiving => 1); + $node_wal->append_conf('postgresql.conf', 'autovacuum = off'); + $node_wal->start; + $node_wal->safe_psql('postgres', "CREATE DATABASE $test_db"); + + # Table for the lock conflict. + $node_wal->safe_psql($test_db, qq[CREATE TABLE $table_lock (a int)]); + + # Table for the buffer pin conflict: one page, with a dead row from an + # aborted insert for VACUUM to prune. Replaying the prune needs a cleanup + # lock on that page, which a pin held by a session blocks. As in section + # 1, these events happen before anything that the session's snapshot can see, + # so replay of the prune has no snapshot conflict with it, only the buffer + # pin conflict. + $node_wal->safe_psql( + $test_db, qq[ +CREATE TABLE $table_pin (a int, b int); +INSERT INTO $table_pin SELECT i, 0 FROM generate_series(1, 20) i; +BEGIN; +INSERT INTO $table_pin VALUES (21, 0); +ROLLBACK; +]); + + # The base backup is where recovery starts. Stopping a backup switches + # to a new WAL segment, so everything below is in segments that follow + # the end of the backup, and recovery is consistent before reaching them. + $node_wal->backup($backup_progress); + + # Run $sql, which writes the record that conflicts with replay, so that + # the record lands in a WAL segment of its own and some other record lands + # in the next segment. The startup process will be held at the start of + # each of the two segments. + # + # Returns a hash with: + # - conflict_lsn: the insert position before $sql ran. Replay must not + # have reached it when the session takes its lock or pin. + # - seg, seg_after: file names of the two segments, for their gates. + # - seg_start, seg_after_start: where the two segments start. Replay has + # reached hold 1 (or hold 2) when it has replayed WAL up to there. + # + # All of these are computed from one insert position taken after $sql + # ran, which is inside the first segment. pg_walfile_name() gives a + # different answer for a position exactly at a segment boundary on older + # branches, so it's only called on positions inside a segment. + my $write_conflict_segment = sub { + my $sql = shift; + + my $conflict_lsn = $node_wal->safe_psql($test_db, + 'SELECT pg_current_wal_insert_lsn()'); + $node_wal->safe_psql($test_db, $sql); + my ($seg, $seg_after, $seg_start, $seg_after_start) = split( + /\|/, + $node_wal->safe_psql( + $test_db, qq[ +SELECT pg_walfile_name(lsn), + pg_walfile_name(lsn + seg_size), + seg_start, + seg_start + seg_size +FROM pg_current_wal_insert_lsn() lsn, + LATERAL (SELECT setting::numeric AS seg_size + FROM pg_settings WHERE name = 'wal_segment_size') s, + LATERAL (SELECT lsn - ((lsn - '0/0') % seg_size) AS seg_start) b])); + # completes each segment, so that it gets archived + $node_wal->safe_psql($test_db, 'SELECT pg_switch_wal()'); + $node_wal->advance_wal(1); + + return { + conflict_lsn => $conflict_lsn, + seg => $seg, + seg_after => $seg_after, + seg_start => $seg_start, + seg_after_start => $seg_after_start, + }; + }; + + # Replaying a LOCK TABLE makes the startup process take + # AccessExclusiveLock on the table. + my $wal_lock = + $write_conflict_segment->(qq[BEGIN; LOCK TABLE $table_lock; COMMIT;]); + + # Replaying the prune record of this VACUUM makes the startup process + # take a cleanup lock on the table's page. + my $wal_pin = $write_conflict_segment->(qq[VACUUM FREEZE $table_pin;]); + + # A clean shutdown archives every completed segment before it finishes, + # so after this the archive holds all the WAL we wrote. The primary is + # not needed again. + $node_wal->stop; + + my $perlbin = $^X; + my $archive = $node_wal->archive_dir; + if ($windows_os) + { + $perlbin =~ s!\\!/!g; + $archive =~ s!\\!/!g; + } + my $restore_timeout = $PostgreSQL::Test::Utils::timeout_default; + + # Wait until the startup process is held at the gate of the segment + # starting at $seg_start: it has replayed everything before that segment, + # and is waiting in restore_command for it. The gate of that segment is + # closed, so it stays there. Returns the size of the server log then. + my $wait_for_hold = sub { + my ($node, $seg_start) = @_; + + $node->poll_query_until( + $test_db, qq[ +SELECT wait_event = 'RestoreCommand' + AND pg_last_wal_replay_lsn() >= '$seg_start' +FROM pg_stat_activity +WHERE backend_type = 'startup'] + ) or die "timed out waiting for the startup process to be held"; + + return -s $node->logfile; + }; + + # Restore a node from the backup and the archive, hold what replay of the + # conflicting record in $wal (from $write_conflict_segment) needs by + # running $hold_sql in a session, and check progress reporting around the + # resulting conflict. $wait_event is what the startup process is + # expected to wait on during the conflict, and $kind names the conflict. + my $check_progress_after_conflict = sub { + my ($name, $kind, $wal, $hold_sql, $wait_event) = @_; + my $what = "$sect ($kind)"; + + # Close the gates of both segments. + my $gates = PostgreSQL::Test::Utils::tempdir('gates'); + my $gate_conflict = "$gates/$wal->{seg}.gate"; + my $gate_after = "$gates/$wal->{seg_after}.gate"; + append_to_file($gate_conflict, ''); + append_to_file($gate_after, ''); + $gates =~ s!\\!/!g if $windows_os; + + # recovery.signal, not standby.signal: this is archive recovery, not + # standby mode, so redo progress is reported. + my $node_pitr = PostgreSQL::Test::Cluster->new($name); + $node_pitr->init_from_backup($node_wal, $backup_progress); + $node_pitr->set_recovery_mode; + + # The backup copied the primary's postgresql.conf. Later lines overwrite. + # - archive_mode = off: don't archive into the primary's archive + # after recovery ends. + # - recovery_prefetch = off: don't read WAL ahead of replay, which + # could ask for a held segment too early. + # - max_standby_archive_delay = -1: wait for the conflicting session + # instead of canceling it, so the test decides when it ends. + $node_pitr->append_conf( + 'postgresql.conf', qq[ +archive_mode = off +hot_standby = on +recovery_prefetch = off +restore_command = '"$perlbin" "$FindBin::RealBin/restore_on_gate_open" "$archive" "$gates" $restore_timeout "%f" "%p"' +log_startup_progress_interval = ${progress_interval_ms}ms +max_standby_archive_delay = -1 +]); + + # pg_ctl returns once the node accepts read-only connections, which + # happens at consistency. Replay then goes on until hold 1. + $node_pitr->start; + my $log_offset = $wait_for_hold->($node_pitr, $wal->{seg_start}); + + # Hold the lock or pin that replay of the conflicting record needs. + # The startup process can't have got there: it's held. + my $psql_pitr = $node_pitr->background_psql($test_db); + $psql_pitr->query_safe($hold_sql); + is( $node_pitr->safe_psql( + $test_db, + qq[SELECT pg_last_wal_replay_lsn() < '$wal->{conflict_lsn}']), + 't', + "$what: conflict set up before replay reached its record"); + + # Let the progress interval elapse while the startup process is held, + # and release it. It logs progress for the first record it replays, + # and then waits for our session. + Time::HiRes::usleep($hold_usec); + unlink($gate_conflict) or die "could not remove $gate_conflict: $!"; + $node_pitr->wait_for_event('startup', $wait_event); + + # Without progress before the conflict, the check after it would + # prove nothing. + like( + slurp_file($node_pitr->logfile, $log_offset), + qr/redo in progress/, + "$what: progress reported before the conflict"); + + # End our transaction, which releases the lock or pin. Replay + # resolves the conflict, finishes the segment, and reaches hold 2. + # + # Count progress from hold 2 on, not from the end of the conflict. + # The timer may have expired during the conflict, before the resolver + # canceled it, and the flag it set is still consumed by the next + # record: one "redo in progress" line can follow the conflict even + # without the fix. At least the XLOG_SWITCH record comes after the + # conflicting record in its segment, so that line is always logged + # before hold 2. + $psql_pitr->query_safe('COMMIT'); + $psql_pitr->quit; + $log_offset = $wait_for_hold->($node_pitr, $wal->{seg_after_start}); + + # Let the interval elapse again, and release the startup process for + # the rest of the archive. Recovery ends after the last segment in + # the archive. + Time::HiRes::usleep($hold_usec); + unlink($gate_after) or die "could not remove $gate_after: $!"; + $node_pitr->poll_query_until($test_db, + 'SELECT NOT pg_is_in_recovery()') + or die "timed out waiting for recovery to end"; + + # The actual check: fails if the conflict canceled the progress + # timeout. + my $n_after = () = + slurp_file($node_pitr->logfile, $log_offset) =~ /redo in progress/g; + cmp_ok($n_after, '>', 0, + "$what: progress reported after the conflict"); + + $node_pitr->stop; + }; + + # Lock conflict: ResolveRecoveryConflictWithLock(). Hold ACCESS SHARE on + # the table, which replay of the LOCK TABLE record has to wait for. The + # startup process waits for a relation lock. + $check_progress_after_conflict->( + 'progress_lock', 'lock', $wal_lock, + qq[BEGIN; LOCK TABLE $table_lock IN ACCESS SHARE MODE;], 'relation'); + + # Buffer pin conflict: ResolveRecoveryConflictWithBufferPin(). A cursor + # positioned on the table's only page keeps it pinned, and replay of + # VACUUM's prune record has to wait for the pin to go away. The startup + # process waits for a cleanup lock on the buffer. + $check_progress_after_conflict->( + 'progress_pin', 'buffer pin', $wal_pin, + qq[BEGIN; + DECLARE progress_cursor CURSOR FOR SELECT b FROM $table_pin; + FETCH FORWARD FROM progress_cursor;], + 'BufferCleanup'); +} + + done_testing(); sub check_conflict_log diff --git a/src/test/recovery/t/restore_on_gate_open b/src/test/recovery/t/restore_on_gate_open new file mode 100644 index 00000000000..4b2c458befb --- /dev/null +++ b/src/test/recovery/t/restore_on_gate_open @@ -0,0 +1,46 @@ +#!/usr/bin/perl + +# restore_command helper: restore a WAL file from an archive, like "cp", but +# only once its gate is open. +# +# The test closes the gate for a file by creating ".gate" in the gate +# directory, and opens it by removing that file. While the gate is closed +# this script waits, and with it the startup process that called it, so the +# test decides when replay may go past a given point in the WAL. +use strict; +use warnings FATAL => 'all'; +use File::Copy; +use Time::HiRes qw(time usleep); + +# This script accepts five arguments: +# - The archive directory to restore from. +# - The gate directory. +# - A timeout in seconds, defined by $PostgreSQL::Test::Utils::timeout_default. +# If a gate is still closed after this long, the script dies. Its exit +# status then makes recovery fail, instead of being taken as the end of the +# archive, which would make recovery end early. +# - The file to restore and the path to restore it to (%f and %p). +my ($archive_dir, $gate_dir, $timeout_sec, $file, $dest) = @ARGV; + +my $poll_interval_usec = 10_000; +my $gate = "$gate_dir/$file.gate"; + +if (-e $gate) +{ + print STDERR "restore_on_gate_open: waiting for gate of $file\n"; + my $deadline = time() + $timeout_sec; + while (-e $gate) + { + die "restore_on_gate_open: timed out waiting for gate of $file\n" + if time() > $deadline; + usleep($poll_interval_usec); + } +} + +# A file missing from the archive (the end of the WAL, a timeline history +# file that doesn't exist) is a plain failure, as with "cp". +exit 1 unless -e "$archive_dir/$file"; + +copy("$archive_dir/$file", $dest) + or die "restore_on_gate_open: could not copy $file: $!\n"; +exit 0; -- 2.54.0 (Apple Git-157)