public inbox for [email protected]
help / color / mirror / Atom feedFrom: Hayato Kuroda (Fujitsu) <[email protected]>
To: 'Alexander Lakhin' <[email protected]>
To: Peter Eisentraut <[email protected]>
To: Euler Taveira <[email protected]>
To: Amit Kapila <[email protected]>
To: Shlok Kyal <[email protected]>
Cc: Tomas Vondra <[email protected]>
Cc: Bharath Rupireddy <[email protected]>
Cc: [email protected] <[email protected]>
Cc: Michael Paquier <[email protected]>
Cc: Andres Freund <[email protected]>
Cc: Ashutosh Bapat <[email protected]>
Cc: FabrÃzio de Royes Mello <[email protected]>
Cc: vignesh C <[email protected]>
Subject: RE: speed up a logical replica setup
Date: Wed, 3 Jul 2024 05:12:25 +0000
Message-ID: <OSBPR01MB25528300C71FDD83EA1DCA12F5DD2@OSBPR01MB2552.jpnprd01.prod.outlook.com> (raw)
In-Reply-To: <[email protected]>
References: <[email protected]>
<[email protected]>
<TYCPR01MB12077907C052EC329C45AE198F5362@TYCPR01MB12077.jpnprd01.prod.outlook.com>
<[email protected]>
<[email protected]>
<[email protected]>
<CAA4eK1KPoLUUGzjw9eEQd56LUAf2QQj8BqMcsoSe6vycB5CYUQ@mail.gmail.com>
<[email protected]>
<CAA4eK1JJq_ER6Kq_H=jKHR75QPRd8y9_D=RtYw=aPYKMfqLi9A@mail.gmail.com>
<CAA4eK1KdCb+5sjYu6qCMXXdCX1y_ihr8kFzMozq0=P=auYxgog@mail.gmail.com>
<CANhcyEV6q1Vhd37i1axUeScLi0UAGVxta1LDa0BV0Eh--TcPMg@mail.gmail.com>
<CAA4eK1JaQcAZ=n513-4VDW4ujE9T9f007fczNCpVDbg1smhT4g@mail.gmail.com>
<[email protected]>
<[email protected]>
<[email protected]>
<[email protected]>
Dear Alexander and other hackers,
> As a recent buildfarm failure [1] shows, that test addition introduced
> new instability:
> ### Starting node "node_s"
> # Running: pg_ctl -w -D
> /home/bf/bf-build/piculet/HEAD/pgsql.build/testrun/pg_basebackup/040_pg_c
> reatesubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata
> -l
> /home/bf/bf-build/piculet/HEAD/pgsql.build/testrun/pg_basebackup/040_pg_c
> reatesubscriber/log/040_pg_createsubscriber_node_s.log
> -o --cluster-name=node_s start
> waiting for server to start.... done
> server started
> # Postmaster PID for node "node_s" is 416482
> error running SQL: 'psql:<stdin>:1: ERROR: skipping slot synchronization as the
> received slot sync LSN 0/30047F0 for
> slot "failover_slot" is ahead of the standby position 0/3004708'
> while running 'psql -XAtq -d port=51506 host=/tmp/pqWohdD5Qj
> dbname='postgres' -f - -v ON_ERROR_STOP=1' with sql 'SELECT
> pg_sync_replication_slots()' at
> /home/bf/bf-build/piculet/HEAD/pgsql/src/test/perl/PostgreSQL/Test/Cluster
> .pm line 2126.
>
> I could reproduce this failure with:
> --- a/src/backend/replication/walreceiver.c
> +++ b/src/backend/replication/walreceiver.c
> @@ -517,6 +517,7 @@ WalReceiverMain(char *startup_data, size_t
> startup_data_len)
> * let the startup process and primary server know
> about
> * them.
> */
> +pg_usleep(300000);
> XLogWalRcvFlush(false, startpointTLI);
>
> make -s check -C src/bin/pg_basebackup/ PROVE_TESTS="t/040*"
>
> # +++ tap check in src/bin/pg_basebackup +++
> t/040_pg_createsubscriber.pl .. 22/? # Tests were run but no plan was declared
> and done_testing() was not seen.
> # Looks like your test exited with 29 just after 23.
> t/040_pg_createsubscriber.pl .. Dubious, test returned 29 (wstat 7424, 0x1d00)
> All 23 subtests passed
>
> Test Summary Report
> -------------------
> t/040_pg_createsubscriber.pl (Wstat: 7424 Tests: 23 Failed: 0)
> Non-zero exit status: 29
> Parse errors: No plan found in TAP output
> Files=1, Tests=23, 4 wallclock secs ( 0.01 usr 0.01 sys + 0.49 cusr 0.44
> csys = 0.95 CPU)
I thought it was not related with the feature of pg_createsubscriber. It was
related with the slotsync function. In the first place, the error message was
output with the below backtrace.
```
synchronize_one_slot
synchronize_slots
pg_sync_replication_slots
```
And I found the error could be reproduced by the attached script with the source
modification by Alexander [1]. According to my analysis, this could be caused when
1) a replication slot is created with failover = true and XLOG_RUNNING_XACT record is generated, and
2) pg_sync_replication_slots() is called *before* the record is flushed on the
standby. To stabilize the test, we can call wait_for_replay_catchup() after the slot
creation on the primary.
> Moreover, this test may suffer from autovacuum:
> echo "
> autovacuum_naptime = 1
> autovacuum_analyze_threshold = 1
> " > /tmp/temp.config
> TEMP_CONFIG=/tmp/temp.config make -s check -C src/bin/pg_basebackup/
> PROVE_TESTS="t/040*"
>
> # +++ tap check in src/bin/pg_basebackup +++
> t/040_pg_createsubscriber.pl .. 24/?
> # Failed test 'failover slot is synced'
> # at t/040_pg_createsubscriber.pl line 273.
> # got: ''
> # expected: 'failover_slot'
> t/040_pg_createsubscriber.pl .. 28/? # Looks like you failed 1 test of 33.
> t/040_pg_createsubscriber.pl .. Dubious, test returned 1 (wstat 256, 0x100)
> Failed 1/33 subtests
Thanks for reporting. I could reproduce the failure, and some BF animals said NG.
According to them, the root cause seemed that slot synchronization was failed.
```
LOG: statement: SELECT pg_sync_replication_slots()
LOG: could not sync slot "failover_slot" as remote slot precedes local slot
DETAIL: Remote slot has LSN 0/3006890 and catalog xmin 743, but local slot has LSN 0/3006890 and catalog xmin 744.
```
Based on that, I considered a scenario why the slot could not be synchronized.
I felt this was not caused by the pg_createsubscriber.
1. At initial stage, the xmin of the physical slot is 743, and nextXid of the
primary is also 743.
2. Autovacuum worker starts a new transaction. nextXid is incremented to 744.
3. Tries to creates a logical replication slot with failover=true *before the
transaction at step2 is replicated to the standby*.
4. While creating the slot, the catalog_xmin must be determined.
The initial candidate is nextXid (= 744), but the oldest xmin of replication
slots (=743) is used if it is older than nextXid. So 743 is chosen in this case.
This operaion is done in CreateInitDecodingContext()->GetOldestSafeDecodingContext().
5. After that, the transaction at step2 is reached to the standby node and it
updates the nextXid.
6. Finally runs pg pg_sync_replication_slots() on the standby. It finds a failover
slot on the primary and tries to create on the standby. However, the
catalog_xmin on the primary (743) is older than the nextXid of the standby (744)
so that it skips to create a slot.
To avoid the issue, we can disable the autovacuuming while testing.
# Descriptions for attached files
An attached script can be used to reproduce the first failure without pg_createsubscriber.
It requires to modify the code like [1].
0001 patch can reduce the wait time of test. See [3]. I know the approach is bit hacky but
it worked.
0002 patch waits until the WAL record is replicated. This fixes a first failure.
0003 patch disables autovacuum for node_p and node_s. I think node_p is enough, but did
like that just in case. This fixes a second failure.
[1]: https://www.postgresql.org/message-id/0dffca12-bf17-4a7a-334d-225569de5e6e%40gmail.com
[2]: https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=adder&dt=2024-07-02%2008%3A45%3A39
[3]: https://www.postgresql.org/message-id/OSBPR01MB25521B15BF950D2523BBE143F5D32%40OSBPR01MB2552.jpnprd0...
Best Regards,
Hayato Kuroda
FUJITSU LIMITED
https://www.fujitsu.com/
Attachments:
[application/octet-stream] v2-0001-emit-dummy-message-while-setting-up-the-publisher.patch (1.6K, ../OSBPR01MB25528300C71FDD83EA1DCA12F5DD2@OSBPR01MB2552.jpnprd01.prod.outlook.com/2-v2-0001-emit-dummy-message-while-setting-up-the-publisher.patch)
download | inline diff:
From e66878760f87687c072a3ff902cba3bfed298b15 Mon Sep 17 00:00:00 2001
From: Hayato Kuroda <[email protected]>
Date: Wed, 3 Jul 2024 04:53:26 +0000
Subject: [PATCH v2 1/3] emit dummy message while setting up the publisher
---
src/bin/pg_basebackup/pg_createsubscriber.c | 26 +++++++++++++++++++++
1 file changed, 26 insertions(+)
diff --git a/src/bin/pg_basebackup/pg_createsubscriber.c b/src/bin/pg_basebackup/pg_createsubscriber.c
index 21dd50f808..499f26cf38 100644
--- a/src/bin/pg_basebackup/pg_createsubscriber.c
+++ b/src/bin/pg_basebackup/pg_createsubscriber.c
@@ -781,6 +781,32 @@ setup_publisher(struct LogicalRepInfo *dbinfo)
disconnect_database(conn, false);
}
+ /*
+ * pg_create_logical_replication_slot () returns the end of the
+ * RUNNING_XACT record. If we use the returned value as recovery_target_lsn
+ * as-is, however, we must wait for additional WAL generation because the
+ * parameter requires that the replicated WAL overtake a certain point.
+ * Insert a dummy WAL record to avoid unnecessary waits.
+ */
+ if (!dry_run)
+ {
+ PGconn *conn;
+ PGresult *res = NULL;
+
+ conn = connect_database(dbinfo[0].pubconninfo, true);
+
+ /* Insert dummy data to WAL to move forward the WAL record */
+ res = PQexec(conn,
+ "SELECT pg_catalog.pg_logical_emit_message(true, 'pg_createsubscriber', 'dummy data', true);");
+
+ if (PQresultStatus(res) != PGRES_TUPLES_OK)
+ {
+ pg_log_error("could not run CHECKPOINT: %s",
+ PQresultErrorMessage(res));
+ disconnect_database(conn, true);
+ }
+ }
+
return lsn;
}
--
2.43.0
[application/octet-stream] v2-0002-wait-until-RUNNING_XACT-is-replicated.patch (1018B, ../OSBPR01MB25528300C71FDD83EA1DCA12F5DD2@OSBPR01MB2552.jpnprd01.prod.outlook.com/3-v2-0002-wait-until-RUNNING_XACT-is-replicated.patch)
download | inline diff:
From 87129dad670100482d8a514dd4a502cade544ac7 Mon Sep 17 00:00:00 2001
From: Hayato Kuroda <[email protected]>
Date: Wed, 3 Jul 2024 05:03:11 +0000
Subject: [PATCH v2 2/3] wait until RUNNING_XACT is replicated
---
src/bin/pg_basebackup/t/040_pg_createsubscriber.pl | 1 +
1 file changed, 1 insertion(+)
diff --git a/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl b/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl
index 80002c5a17..ed5ccf2bd7 100644
--- a/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl
+++ b/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl
@@ -293,6 +293,7 @@ $node_p->safe_psql($db1,
"SELECT pg_create_logical_replication_slot('$fslotname', 'pgoutput', false, false, true)"
);
$node_s->start;
+$node_p->wait_for_replay_catchup($node_s);
$node_s->safe_psql('postgres', "SELECT pg_sync_replication_slots()");
my $result = $node_s->safe_psql('postgres',
"SELECT slot_name FROM pg_replication_slots WHERE slot_name = '$fslotname' AND synced AND NOT temporary"
--
2.43.0
[application/octet-stream] v2-0003-disable-autovacuum-while-testing.patch (1.1K, ../OSBPR01MB25528300C71FDD83EA1DCA12F5DD2@OSBPR01MB2552.jpnprd01.prod.outlook.com/4-v2-0003-disable-autovacuum-while-testing.patch)
download | inline diff:
From 5f4fe7b85f54823094aa0b7c72bac83d31f54c8f Mon Sep 17 00:00:00 2001
From: Hayato Kuroda <[email protected]>
Date: Wed, 3 Jul 2024 05:07:18 +0000
Subject: [PATCH v2 3/3] disable autovacuum while testing
---
src/bin/pg_basebackup/t/040_pg_createsubscriber.pl | 2 ++
1 file changed, 2 insertions(+)
diff --git a/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl b/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl
index ed5ccf2bd7..877a540d7a 100644
--- a/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl
+++ b/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl
@@ -116,6 +116,7 @@ command_fails(
my $node_p = PostgreSQL::Test::Cluster->new('node_p');
my $pconnstr = $node_p->connstr;
$node_p->init(allows_streaming => 'logical');
+$node_p->append_conf('postgresql.conf', 'autovacuum = off');
$node_p->start;
# Set up node F as about-to-fail node
@@ -149,6 +150,7 @@ $node_s->append_conf(
primary_slot_name = '$slotname'
primary_conninfo = '$pconnstr dbname=postgres'
hot_standby_feedback = on
+autovacuum = off
]);
$node_s->set_standby_mode();
$node_s->start;
--
2.43.0
[application/octet-stream] repro_skipping_slot_sync.sh (767B, ../OSBPR01MB25528300C71FDD83EA1DCA12F5DD2@OSBPR01MB2552.jpnprd01.prod.outlook.com/5-repro_skipping_slot_sync.sh)
download
view thread (107+ messages) latest in thread
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected]
Subject: RE: speed up a logical replica setup
In-Reply-To: <OSBPR01MB25528300C71FDD83EA1DCA12F5DD2@OSBPR01MB2552.jpnprd01.prod.outlook.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox