On 14/02/2022 22:43, Heikki Linnakangas wrote:
On 14/02/2022 16:41, Tom Lane wrote:
Heikki Linnakangas <heikki.linnakan...@iki.fi> writes:
Add test case for an archive recovery corner case.
hoverfly seems not to like this:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hoverfly&dt=2022-02-14%2012%3A36%3A12
Hmm, only hoverfly - and even that succeeded on next run. Some kind of a
flakyness I guess. I'll try to run the test in a loop and see if I can
reproduce it.
That was interesting: the order that WAL segments are archived when a
standby is promoted is not fully deterministic. The test polled
pg_stat_archiver.last_archived_wal to wait until a particular WAL
segment was archived, but it could happen that a lower-numbered WAL
segment was archived *after* the waited-for segment, and
pg_stat_archiver.last_archived_wal therefore displayed the
lower-numbered WAL segment. So the test incorrectly thought that the
higher-numbered segment that it waits for hadn't been archived yet.
I realized that this test doesn't really need to wait for the segment to
be archived, because it will stop the standby server immediately after
that, and stopping a server implicitly waits for all the WAL to be
archived before the archiver process exits. So I just removed it.
During normal operations the WAL segments are archived in order. But I'm
not sure if there are some other corner cases, aside from promoting a
standby server, when this could happen. After crash restart, maybe, if
some .ready/done files are lost.
I find it a bit surprising that pg_stat_archiver.last_archived_wal is
not necessarily the highest-numbered segment that was archived. I
propose that we mention that in the docs, as in the attached patch.
I'll commit this soon, to silence the occasional failures on the
buildfarm, but let me know if you have any better suggestions or thoughts.
- Heikki
From 271d4ec8caec018186ab0314295ee761e2882488 Mon Sep 17 00:00:00 2001
From: Heikki Linnakangas <heikki.linnakan...@iki.fi>
Date: Tue, 15 Feb 2022 23:14:59 +0200
Subject: [PATCH 1/1] Fix race condition in 028_pitr_timelines.pl test, add
note to docs.
The 028_pitr_timelines.pl test would sometimes hang, waiting for a WAL
segment that was just filled up to be archived. It was because the
test used 'pg_stat_archiver.last_archived_wal' to check if a file was
archived, but the order that WAL files are archived when a standby is
promoted is not fully deterministic, and 'last_archived_wal' tracks
the last segment that was archived, not the highest-numbered WAL
segment. Because of that, if the archiver archived segment 3, and then
2, 'last_archived_wal' say 2, and the test query would think that 3
has not been archived yet.
Normally, WAL files are marked ready for archival in order, and the
archiver process will process them in order, so that issue doesn't
arise. We have used the same query on 'last_archived_wal' in a few
other tests with no problem. But when a standby is promoted, things
are a bit chaotic. After promotion, the server will try to archive all
the WAL segments from the old timeline that are in pg_wal, as well as
the history file and any new WAL segments on the new timeline. The
end-of-recovery checkpoint will create the .ready files for all the
WAL files on the old timeline, but at the same time, the new timeline
is opened up for business. A file from the new timeline can therefore
be archived before the files from the old timeline have been marked as
ready for archival.
It turns out that we don't really need to wait for the archival in
this particular test, because the standby server is about to be
stopped, and stopping a server will wait for the end-of-recovery
checkpoint and all WAL archivals to finish, anyway. So we can just
remove it from the test.
Add a note to the docs on 'pg_stat_archiver' view that files can be
archived out of order.
Discussion: https://www.postgresql.org/message-id/2842251.1644849...@sss.pgh.pa.us
---
doc/src/sgml/monitoring.sgml | 9 +++++++++
src/test/recovery/t/028_pitr_timelines.pl | 13 ++-----------
2 files changed, 11 insertions(+), 11 deletions(-)
diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml
index 62f2a3332b..44e08225a8 100644
--- a/doc/src/sgml/monitoring.sgml
+++ b/doc/src/sgml/monitoring.sgml
@@ -3474,6 +3474,15 @@ SELECT pid, wait_event_type, wait_event FROM pg_stat_activity WHERE wait_event i
</tgroup>
</table>
+ <para>
+ Normally, WAL files are archived in order, oldest to newest, but that is
+ not guaranteed, and does not hold under special circumstances like when
+ promoting a standby or after crash recovery. Therefore it is not safe to
+ assume that all files older than
+ <structfield>last_archived_wal</structfield> have also been successfully
+ archived.
+ </para>
+
</sect2>
<sect2 id="monitoring-pg-stat-bgwriter-view">
diff --git a/src/test/recovery/t/028_pitr_timelines.pl b/src/test/recovery/t/028_pitr_timelines.pl
index c0b76fe37b..a8b12d9af6 100644
--- a/src/test/recovery/t/028_pitr_timelines.pl
+++ b/src/test/recovery/t/028_pitr_timelines.pl
@@ -36,7 +36,6 @@ use File::Compare;
# Initialize and start primary node with WAL archiving
my $node_primary = PostgreSQL::Test::Cluster->new('primary');
$node_primary->init(has_archiving => 1, allows_streaming => 1);
-$node_primary->append_conf('postgresql.conf', 'log_min_messages=debug1');
$node_primary->start;
# Take a backup.
@@ -70,7 +69,6 @@ $node_standby->init_from_backup(
has_archiving => 1,
has_restoring => 0);
$node_standby->append_conf('postgresql.conf', 'archive_mode = always');
-$node_standby->append_conf('postgresql.conf', 'log_min_messages=debug1');
$node_standby->start;
$node_primary->wait_for_catchup($node_standby);
@@ -93,15 +91,8 @@ my $walfile_to_be_archived = $node_standby->safe_psql('postgres',
# Make WAL segment eligible for archival
$node_standby->safe_psql('postgres', 'SELECT pg_switch_wal()');
-# Wait until the WAL segment has been archived.
-my $archive_wait_query =
- "SELECT '$walfile_to_be_archived' <= last_archived_wal FROM pg_stat_archiver;";
-$node_standby->poll_query_until('postgres', $archive_wait_query)
- or die "Timed out while waiting for WAL segment to be archived";
-my $last_archived_wal_file = $walfile_to_be_archived;
-
-# Ok, the standby has now archived the WAL on timeline 2. We don't
-# need the standby anymore.
+# We don't need the standby anymore, request shutdown. The server will
+# finish archiving all the WAL on timeline 2 before it exits.
$node_standby->stop;
# Contents of the WAL archive at this point:
--
2.30.2
