Subject: Re: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman

From: Thomas Munro <[email-masked]>
Date: Mon, 11 Apr 2022 18:48:58 +1200

On Sat, Apr 9, 2022 at 12:59 PM Andres Freund <[email-masked]> wrote:
> On 2022-04-08 17:55:51 -0400, Tom Lane wrote:
> > I tried adjusting the patch so it does guarantee that (as attached),
> > and in two out of two tries it got past the archive_cleanup_command
> > failure but then hung up waiting for standby2 to promote.
>
> Adding
>
> $node_standby->safe_psql('postgres', "SELECT pg_switch_wal()");
> just after
> $node_standby2->start;
>
> makes the tests pass here.

Sorry for the delay... I got a bit confused about the different things
going on in this thread but I hope I've got it now:

1.  This test had some pre-existing bugs/races, which hadn't failed
before due to scheduling, even under Valgrind.  The above changes
appear to fix those problems.  To Michael for comment.

> What is that second test really testing?
>
> # Check the presence of temporary files specifically generated during
> # archive recovery.  To ensure the presence of the temporary history
> # file, switch to a timeline large enough to allow a standby to recover
> # a history file from an archive.  As this requires at least two timeline
> # switches, promote the existing standby first.  Then create a second
> # standby based on the promoted one.  Finally, the second standby is
> # promoted.
>
> Note "Then create a second standby based on the promoted one." - but that's
> not actually what's happening:

2.  There may also be other problems with the test but those aren't
relevant to skink's failure, which starts on the 5th test.  To Michael
for comment.

> But I think there's also something funky in the prefetching logic. I think it
> may attempt restoring during prefetching somehow, even though there's code
> that appears to try to prevent that?

3.  Urghl.  Yeah.  There is indeed code to report XLREAD_WOULDBLOCK
for the lastSourceFailed case, but we don't really want to do that
more often than every 5 seconds.  So I think I need to make that
"sticky", so that we don't attempt to prefetch again (ie to read from
the next segment, which invokes restore_command) until we've replayed
all the records we already have, then hit the end and go to sleep.
The attached patch does that, and makes the offending test pass under
Valgrind for me, even without the other changes already mentioned.  If
I understand correctly, this is due to a timing race in the tests
(though I didn't check where exactly), because all those extra
fork/exec calls are extremely slow under Valgrind.

> And interestingly I'm not seeing the
> "switched WAL source from stream to archive after failure"
> lines I'd expect.

I see them now.  It's because it gives up when it's reading ahead
(nonblocking), which may not be strictly necessary but I found it
simpler to think about.  Then when it tries again in 5 seconds it's in
blocking mode so it doesn't give up so easily.

2022-04-11 18:15:08.220 NZST [524796] DEBUG:  switched WAL source from
stream to archive after failure
cp: cannot stat '/tmp/archive/000000010000000000000017': No such file
or directory
2022-04-11 18:15:08.226 NZST [524796] DEBUG:  could not restore file
"000000010000000000000017" from archive: child process exited with
exit code 1
2022-04-11 18:15:08.226 NZST [524796] DEBUG:  could not open file
"pg_wal/000000010000000000000017": No such file or directory
2022-04-11 18:15:08.226 NZST [524796] DEBUG:  switched WAL source from
archive to stream after failure
From e488e20f7c364ba1adaae8d1f6ea92a7f5d0bda6 Mon Sep 17 00:00:00 2001
From: Thomas Munro <[email-masked]>
Date: Mon, 11 Apr 2022 17:16:24 +1200
Subject: [PATCH] Don't retry restore_command while reading ahead.

Suppress further attempts to read ahead in the WAL if we run out of
data, until records already decoded have been replayed.  When replaying
from archives, this avoids repeatedly retrying the restore_command until
after we've slept for 5 seconds.

When replaying from a network stream, this makes us less aggressive in
theory, but we probably can't benefit from being more aggressive yet
anyway as the flushedUpto variable doesn't advance until we run out of
data (though we could improve that in future).

While here, fix a potential off-by one confusion with the
no_readahead_until mechanism: we suppress readahead until after the
record that begins at that LSN has been replayed (ie we are replaying a
higher LSN), so change < to <=.

Defect in commit 5dc0418f.

Reported-by: Andres Freund <[email-masked]>
Discussion: https://postgr.es/m/20220409005910.alw46xqmmgny2sgr%40alap3.anarazel.de
---
 src/backend/access/transam/xlogprefetcher.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

diff --git a/src/backend/access/transam/xlogprefetcher.c b/src/backend/access/transam/xlogprefetcher.c
index f3428888d2..43e82b65c2 100644
--- a/src/backend/access/transam/xlogprefetcher.c
+++ b/src/backend/access/transam/xlogprefetcher.c
@@ -487,8 +487,8 @@ XLogPrefetcherNextBlock(uintptr_t pgsr_private, XLogRecPtr *lsn)
 			 */
 			nonblocking = XLogReaderHasQueuedRecordOrError(reader);
 
-			/* Certain records act as barriers for all readahead. */
-			if (nonblocking && replaying_lsn < prefetcher->no_readahead_until)
+			/* Readahead is disabled until we replay past a certain point. */
+			if (nonblocking && replaying_lsn <= prefetcher->no_readahead_until)
 				return LRQ_NEXT_AGAIN;
 
 			record = XLogReadAhead(prefetcher->reader, nonblocking);
@@ -496,8 +496,13 @@ XLogPrefetcherNextBlock(uintptr_t pgsr_private, XLogRecPtr *lsn)
 			{
 				/*
 				 * We can't read any more, due to an error or lack of data in
-				 * nonblocking mode.
+				 * nonblocking mode.  Don't try to read ahead again until we've
+				 * replayed everything already decoded.
 				 */
+				if (nonblocking && prefetcher->reader->decode_queue_tail)
+					prefetcher->no_readahead_until =
+						prefetcher->reader->decode_queue_tail->lsn;
+
 				return LRQ_NEXT_AGAIN;
 			}
 
-- 
2.30.2

---

From: Michael Paquier <[email-masked]>
Date: Mon, 11 Apr 2022 16:43:26 +0900

> appear to fix those problems.  To Michael for comment.

I have seen the thread, and there is a lot in it.  I will try to look
tomorrow at the parts I got involved in.
--
Michael

---

From: Michael Paquier <[email-masked]>
Date: Tue, 12 Apr 2022 12:49:48 +0900

> appear to fix those problems.  To Michael for comment.

Yeah, there are two problems here.  From what I can see, ensuring the
execution of archive_cleanup_command on the standby needs the
checkpoint on the primary and the restart point on the standby.  So
pg_current_wal_lsn() should be located after the primary's checkpoint 
and not before it so as we are sure that the checkpoint records finds
its way to the standby.  That's what Tom mentioned upthread.

The second problem is to make sure that $standby2 sees the promotion
of $standby and its history file, but we also want to recover
00000002.history from some archives to create a RECOVERYHISTORY at
recovery for the purpose of the test.  Switching to a new segment as
proposed by Andres does not seem completely right to me because we are
not 100% sure of the ordering an archive is going to happen, no?  I
think that the logic to create $standby2 from the initial backup of
the primary is right, because there is no 00000002.history in it, but
we also need to be sure that 00000002.history has been archived once
the promotion of $standby is done.  This can be validated thanks to
the logs, actually.

> relevant to skink's failure, which starts on the 5th test.  To Michael

This comes from df86e52, where we want to recovery a history file that
would be created as RECOVERYHISTORY and make sure that the file gets
removed at the end of recovery.  So $standby2 should choose a new
timeline different from the one of chosen by $standby.  Looking back
at what has been done, it seems to me that the comment is the
incorrect part:
https://www.postgresql.org/message-id/[email-masked]

All that stuff leads me to the attached.  Thoughts?
--
Michael
diff --git a/src/test/recovery/t/002_archiving.pl b/src/test/recovery/t/002_archiving.pl
index c8f5ffbaf0..45aafcb35c 100644
--- a/src/test/recovery/t/002_archiving.pl
+++ b/src/test/recovery/t/002_archiving.pl
@@ -24,6 +24,8 @@ $node_primary->backup($backup_name);
 
 # Initialize standby node from backup, fetching WAL from archives
 my $node_standby = PostgreSQL::Test::Cluster->new('standby');
+# Note that this makes the standby archive its contents on the archives
+# of the primary.
 $node_standby->init_from_backup($node_primary, $backup_name,
 	has_restoring => 1);
 $node_standby->append_conf('postgresql.conf',
@@ -44,13 +46,16 @@ $node_standby->start;
 # Create some content on primary
 $node_primary->safe_psql('postgres',
 	"CREATE TABLE tab_int AS SELECT generate_series(1,1000) AS a");
-my $current_lsn =
-  $node_primary->safe_psql('postgres', "SELECT pg_current_wal_lsn();");
 
 # Note the presence of this checkpoint for the archive_cleanup_command
 # check done below, before switching to a new segment.
 $node_primary->safe_psql('postgres', "CHECKPOINT");
 
+# Done after the checkpoint to ensure that the checkpoint gets replayed
+# on the standby.
+my $current_lsn =
+  $node_primary->safe_psql('postgres', "SELECT pg_current_wal_lsn();");
+
 # Force archiving of WAL file to make it present on primary
 $node_primary->safe_psql('postgres', "SELECT pg_switch_wal()");
 
@@ -81,10 +86,34 @@ ok( !-f "$data_dir/$recovery_end_command_file",
 # file, switch to a timeline large enough to allow a standby to recover
 # a history file from an archive.  As this requires at least two timeline
 # switches, promote the existing standby first.  Then create a second
-# standby based on the promoted one.  Finally, the second standby is
-# promoted.
+# standby based on the primary, using its archives.  Finally, the second
+# standby is promoted.
 $node_standby->promote;
 
+# Wait until the history file has been archived on the archives of the
+# primary once the promotion of the standby completes.
+my $primary_archive = $node_primary->archive_dir;
+my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
+my $attempts     = 0;
+while ($attempts < $max_attempts)
+{
+	last if (-e "$primary_archive/00000002.history");
+
+	# Wait 0.1 second before retrying.
+	usleep(100_000);
+
+	$attempts++;
+}
+
+if ($attempts >= $max_attempts)
+{
+	die "timed out waiting for 00000002.history\n";
+}
+else
+{
+	note "found 00000002.history after $attempts attempts\n"
+}
+
 # recovery_end_command should have been triggered on promotion.
 ok( -f "$data_dir/$recovery_end_command_file",
 	'recovery_end_command executed after promotion');
@@ -108,14 +137,19 @@ my $log_location = -s $node_standby2->logfile;
 # Now promote standby2, and check that temporary files specifically
 # generated during archive recovery are removed by the end of recovery.
 $node_standby2->promote;
+
+# Check the logs of the standby to see that the commands have failed.
+my $log_contents = slurp_file($node_standby2->logfile, $log_location);
 my $node_standby2_data = $node_standby2->data_dir;
+
+like(
+	$log_contents,
+	qr/restored log file "00000002.history" from archive/s,
+	"00000002.history retrieved from the archives");
 ok( !-f "$node_standby2_data/pg_wal/RECOVERYHISTORY",
 	"RECOVERYHISTORY removed after promotion");
 ok( !-f "$node_standby2_data/pg_wal/RECOVERYXLOG",
 	"RECOVERYXLOG removed after promotion");
-
-# Check the logs of the standby to see that the commands have failed.
-my $log_contents = slurp_file($node_standby2->logfile, $log_location);
 like(
 	$log_contents,
 	qr/WARNING:.*recovery_end_command/s,

---

From: Thomas Munro <[email-masked]>
Date: Sun, 17 Apr 2022 08:56:33 +1200

> All that stuff leads me to the attached.  Thoughts?

Under valgrind I got "Undefined subroutine &main::usleep called at
t/002_archiving.pl line 103" so I added "use Time::HiRes qw(usleep);",
and now I get past the first 4 tests with your patch, but then
promotion times out, not sure why:

+++ tap check in src/test/recovery +++
t/002_archiving.pl ..
ok 1 - check content from archives
ok 2 - archive_cleanup_command executed on checkpoint
ok 3 - recovery_end_command not executed yet
# found 00000002.history after 14 attempts
ok 4 - recovery_end_command executed after promotion
Bailout called.  Further testing stopped:  command "pg_ctl -D
/home/tmunro/projects/postgresql/src/test/recovery/tmp_check/t_002_archiving_standby2_data/pgdata
-l /home/tmunro/projects/postgresql/src/test/recovery/tmp_check/log/002_archiving_standby2.log
promote" exited with value 1

Since it's quite painful to run TAP tests under valgrind, I found a
place to stick a plain old sleep to repro these problems:

--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -1035,7 +1035,7 @@ sub enable_restoring
        my $copy_command =
          $PostgreSQL::Test::Utils::windows_os
          ? qq{copy "$path\\\\%f" "%p"}
-         : qq{cp "$path/%f" "%p"};
+         : qq{sleep 1 && cp "$path/%f" "%p"};

Soon I'll push the fix to the slowness that xlogprefetcher.c
accidentally introduced to continuous archive recovery, ie the problem
of calling a failing restore_command repeatedly as we approach the end
of a WAL segment instead of just once every 5 seconds after we run out
of data, and after that you'll probably need to revert that fix
locally to repro this.

---

From: Michael Paquier <[email-masked]>
Date: Sun, 17 Apr 2022 13:17:32 +0900

> promote" exited with value 1

Hmm.  As far as I can see, aren't you just hitting the 60s timeout of 
pg_ctl here due to the slowness of valgrind?

> place to stick a plain old sleep to repro these problems:

Actually, I am wondering how you are patching Cluster.pm to do that.

> of data, and after that you'll probably need to revert that fix

Okay.  Thanks.  Anyway, I'll do something about that tomorrow (no
room to look at the buildfarm today), and I was thinking about
replacing the while loop I had in the last version of the patch with a
poll_query_until that does a pg_stat_file() with an absolute path to
the history file to avoid the dependency to usleep() in the test,
splitting the fix into two commits as there is more than one problem,
each applying to different branches.
--
Michael

---

From: Andrew Dunstan <[email-masked]>
Date: Sun, 17 Apr 2022 10:56:08 -0400

> Actually, I am wondering how you are patching Cluster.pm to do that.

I don't really think it's Cluster.pm's business to deal with that. It
takes an install path as given either explicitly or implicitly.

It shouldn't be too hard to get Makefile.global to install valgrind
wrappers into the tmp_install/bin directory.

cheers

andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

---

From: Michael Paquier <[email-masked]>
Date: Mon, 18 Apr 2022 08:49:17 +0900

> wrappers into the tmp_install/bin directory.

Or what gets used in just a wrapper of the contents of bin/ that get
enforced to be first in PATH?
--
Michael

---

From: Michael Paquier <[email-masked]>
Date: Mon, 18 Apr 2022 13:55:13 +0900

> https://www.postgresql.org/message-id/[email-masked]

acf1dd42 has taken care of the failures of this test with skink, and I
have just taken care of the two races in the tests with e61efaf and
1a8b110.  I have left e61efaf out of REL_10_STABLE as the idea of
relying on a poll_query_until() with pg_stat_file() and an absolute
path would not work there, and the branch will be EOL'd soon while
there were no complains with this test for two years.
--
Michael

---

From: Andrew Dunstan <[email-masked]>
Date: Mon, 18 Apr 2022 13:32:33 -0400

> enforced to be first in PATH?

That seems likely to be difficult. For example pg_ctl might find its
colocated postgres rather than the valgrind wrapper. Ditto initdb.

cheers

andrew

---

From: Thomas Munro <[email-masked]>
Date: Tue, 19 Apr 2022 09:45:11 +1200

> enforced to be first in PATH?

Delayed response to the question on how I did that, because it was a 4
day weekend down here and I got distracted by sunshine...

A horrible slow way to do it is to build with -DUSE_VALGRIND and then
just run the whole process tree (eg make, perl, psql, ... and all)
under valgrind with --trace-children=yes:

tmunro@x1:~/projects/postgresql$ valgrind --quiet
--suppressions=`pwd`/src/tools/valgrind.supp --trace-children=yes
--track-origins=yes --run-libc-freeres=no --vgdb=no
--error-markers=VALGRINDERROR-BEGIN,VALGRINDERROR-END make -C
src/test/recovery/ check PROVE_TESTS=t/002_* PROVE_FLAGS=-v

I think that sort of thing actually worked when I tried it on a
beefier workstation, but it sent my Thinkpad that "only" has a 16GB of
RAM into some kind of death spiral.  The way I succeeded was indeed
using a wrapper script, based on a suggestion from Andres, my
kludgy-hardcoded-path-assuming implementation of which looked like:

=== install-postgres-valgrind, to be run once after building ===
#!/bin/sh

SRC=$HOME/projects/postgresql

# move the real binary out of the way
mv $SRC/src/backend/postgres $SRC/src/backend/postgres.real

# install the wrapper, in the location it'll be copied from for tmp_install
cp postgres.valgrind $SRC/src/backend/postgres
===

=== postgres.valgrind wrapper script ===
#!/bin/sh
exec /usr/bin/valgrind \
    --quiet \
    --error-exitcode=128 \
    --suppressions=$HOME/projects/postgresql/src/tools/valgrind.supp \
    --trace-children=yes --track-origins=yes --read-var-info=no \
    --leak-check=no \
    --run-libc-freeres=no \
    --vgdb=no \
    --error-markers=VALGRINDERROR-BEGIN,VALGRINDERROR-END \
    $HOME/projects/postgresql/src/backend/postgres.real \
    "$@"
===

Then just:

make -C src/test/recovery/ check PROVE_TESTS=t/002_* PROVE_FLAGS=-v

Yeah, it might be quite neat to find a tool-supported way to do that.

Tangentially, I'd also like to look into making
PostgreSQL-under-Valgrind work on FreeBSD and macOS, which didn't work
last time I tried it for reasons that might, I hope, have been fixed
on the Valgrind side by now.

---

From: Michael Paquier <[email-masked]>
Date: Tue, 19 Apr 2022 11:33:25 +0900

> day weekend down here and I got distracted by sunshine...

Happy Easter.

> Yeah, it might be quite neat to find a tool-supported way to do that.

Thanks for the details.  I feared that it was something like that for
the backend.  At least that's better than having valgrind spawn all
the processes kicked by the make command.  :/

> on the Valgrind side by now.

Okay.

As a side note, skink has cooled down since acf1dd4, and did not
complain either after the additions of e61efaf and 1a8b110.
--
Michael