From: Alexander Lakhin <exclusion@gmail.com>
To: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Cc: Michael Paquier <michael@paquier.xyz>
Cc: Yu Shi (Fujitsu) <shiy.fnst@fujitsu.com>
Cc: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Robert Haas <robertmhaas@gmail.com>
Cc: Andres Freund <andres@anarazel.de>
Cc: Thomas Munro <thomas.munro@gmail.com>
Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Subject: Re: Test slots invalidations in 035_standby_logical_decoding.pl only if dead rows are removed
Date: Thu, 11 Jan 2024 13:00:00 +0300
Message-ID: <5d0e5bec-67f9-9164-36cb-c4ff5f95d1ed@gmail.com> (raw)
In-Reply-To: <ZZ7GpII4bAYN+jT5@ip-10-97-1-34.eu-west-3.compute.internal>
References: <bf67e076-b163-9ba3-4ade-b9fc51a3a8f6@gmail.com>
<d40d015f-03a4-1cf2-6c1f-2b9aca860762@gmail.com>
<28fffded-7dc6-3518-7e0e-fc76b9221586@gmail.com>
<ZZ4cZkBLczQISHxq@paquier.xyz>
<7c025095-5763-17a6-8c80-899b35bd0459@gmail.com>
<ZZ7GpII4bAYN+jT5@ip-10-97-1-34.eu-west-3.compute.internal>
Hi Bertrand,
10.01.2024 19:32, Bertrand Drouvot wrote:
>
>> is an absent message 'obsolete replication slot "row_removal_activeslot"'
> Looking at recovery-15-vacuum_pg_class/i035_standby_logical_decoding_standby.log here:
>
> Yeah, the missing message has to come from InvalidatePossiblyObsoleteSlot().
>
> In case of an active slot we first call ReportSlotInvalidation with the second
> parameter set to true (to emit the "terminating" message), then SIGTERM the active
> process and then (later) we should call the other ReportSlotInvalidation()
> call with the second parameter set to false (to emit the message that we don't
> see here).
>
> So it means InvalidatePossiblyObsoleteSlot() did not trigger the second ReportSlotInvalidation()
> call.
I've found a way to reproduce the issue without slowing down a machine or
running multiple tests in parallel. It's enough for this to add a delay to
allow BackgroundWriterMain() to execute LogStandbySnapshot():
@@ -692,2 +690,3 @@
$node_primary->safe_psql('testdb', qq[UPDATE prun SET s = 'D';]);
+$node_primary->safe_psql('testdb', qq[SELECT pg_sleep(15);]);
$node_primary->safe_psql('testdb', qq[UPDATE prun SET s = 'E';]);
With this delay, I get the failure immediately:
$ PROVE_TESTS="t/035*" TEMP_CONFIG=/tmp/extra.config make check -s -C src/test/recovery
# +++ tap check in src/test/recovery +++
t/035_standby_logical_decoding.pl .. 47/?
# Failed test 'activeslot slot invalidation is logged with on-access pruning'
# at t/035_standby_logical_decoding.pl line 227.
_primary.log contains:
2024-01-11 09:37:01.731 UTC [67656] 035_standby_logical_decoding.pl STATEMENT: UPDATE prun SET s = 'D';
2024-01-11 09:37:01.738 UTC [67664] 035_standby_logical_decoding.pl LOG: statement: SELECT pg_sleep(15);
2024-01-11 09:37:01.738 UTC [67664] 035_standby_logical_decoding.pl LOG: xlog flush request 0/404D8F0; write 0/0; flush
0/0 at character 8
2024-01-11 09:37:01.738 UTC [67664] 035_standby_logical_decoding.pl CONTEXT: writing block 14 of relation base/16384/1247
2024-01-11 09:37:01.738 UTC [67664] 035_standby_logical_decoding.pl STATEMENT: SELECT pg_sleep(15);
2024-01-11 09:37:01.905 UTC [67204] LOG: xlog flush request 0/404DA58; write 0/404BB00; flush 0/404BB00
2024-01-11 09:37:01.905 UTC [67204] CONTEXT: writing block 4 of relation base/16384/2673
2024-01-11 09:37:12.514 UTC [67204] LOG: INSERT @ 0/4057768: - Standby/RUNNING_XACTS: nextXid 769 latestCompletedXid
768 oldestRunningXid 769
2024-01-11 09:37:12.514 UTC [67206] LOG: xlog bg flush request write 0/4057768; flush: 0/4057768, current is write
0/4057730; flush 0/4057730
2024-01-11 09:37:16.760 UTC [67712] 035_standby_logical_decoding.pl LOG: statement: UPDATE prun SET s = 'E';
2024-01-11 09:37:16.760 UTC [67712] 035_standby_logical_decoding.pl LOG: INSERT @ 0/40577A8: - Heap2/PRUNE:
snapshotConflictHorizon: 768,...
Note RUNNING_XACTS here...
_standby.log contains:
2024-01-11 09:37:16.842 UTC [67606] LOG: invalidating obsolete replication slot "pruning_inactiveslot"
2024-01-11 09:37:16.842 UTC [67606] DETAIL: The slot conflicted with xid horizon 768.
2024-01-11 09:37:16.842 UTC [67606] CONTEXT: WAL redo at 0/4057768 for Heap2/PRUNE: snapshotConflictHorizon: 768, ...
and no 'invalidating obsolete replication slot "pruning_activeslot"' below.
Debug logging added (see attached) gives more information:
2024-01-11 09:37:16.842 UTC [67606] LOG: invalidating obsolete replication slot "pruning_inactiveslot"
2024-01-11 09:37:16.842 UTC [67606] DETAIL: The slot conflicted with xid horizon 768.
...
2024-01-11 09:37:16.842 UTC [67606] LOG: !!!InvalidatePossiblyObsoleteSlot| RS_INVAL_HORIZON, s: 0x7f7985475c10,
s->effective_xmin: 0, s->effective_catalog_xmin: 769, snapshotConflictHorizon: 768
...
2024-01-11 09:37:16.842 UTC [67606] LOG: !!!InvalidatePossiblyObsoleteSlot| conflict: 0
so the condition TransactionIdPrecedesOrEquals(s->effective_catalog_xmin,
snapshotConflictHorizon) is not satisfied, hence conflict = 0 and it breaks
the loop in InvalidatePossiblyObsoleteSlot().
Several lines above in the log we can see:
2024-01-11 09:37:12.514 UTC [67606] LOG: REDO @ 0/4057730; LSN 0/4057768: prev 0/4057700; xid 0; len 24 -
Standby/RUNNING_XACTS: nextXid 769 latestCompletedXid 768 oldestRunningXid 769
2024-01-11 09:37:12.540 UTC [67643] 035_standby_logical_decoding.pl LOG: !!!LogicalConfirmReceivedLocation|
MyReplicationSlot: 0x7f7985475c10, MyReplicationSlot->effective_catalog_xmin: 769
and that's the first occurrence of xid 769 in the log.
The decoded stack trace for the LogicalConfirmReceivedLocation call is:
ogicalConfirmReceivedLocation at logical.c:1886:1
ProcessStandbyReplyMessage at walsender.c:2327:1
ProcessStandbyMessage at walsender.c:2188:1
ProcessRepliesIfAny at walsender.c:2121:5
WalSndWaitForWal at walsender.c:1735:7
logical_read_xlog_page at walsender.c:1068:13
ReadPageInternal at xlogreader.c:1062:12
XLogDecodeNextRecord at xlogreader.c:601:5
XLogReadAhead at xlogreader.c:976:5
XLogReadRecord at xlogreader.c:406:3
XLogSendLogical at walsender.c:3229:5
WalSndLoop at walsender.c:2658:7
StartLogicalReplication at walsender.c:1477:2
exec_replication_command at walsender.c:1985:6
PostgresMain at postgres.c:4649:10
Best regards,
Alexander
Attachments:adhoc-035-failure-debugging.patch (text/x-patch, 4.4K) downloaddiff --git a/src/backend/replication/logical/logical.c b/src/backend/replication/logical/logical.cindex ca09c683f1..098310b23e 100644--- a/src/backend/replication/logical/logical.c+++ b/src/backend/replication/logical/logical.c@@ -1883,6 +1883,7 @@ LogicalConfirmReceivedLocation(XLogRecPtr lsn)
{
SpinLockAcquire(&MyReplicationSlot->mutex);
MyReplicationSlot->effective_catalog_xmin = MyReplicationSlot->data.catalog_xmin;
+elog(LOG, "!!!LogicalConfirmReceivedLocation| MyReplicationSlot: %p, MyReplicationSlot->effective_catalog_xmin: %u", MyReplicationSlot, MyReplicationSlot->effective_catalog_xmin);
SpinLockRelease(&MyReplicationSlot->mutex);
ReplicationSlotsComputeRequiredXmin(false);
diff --git a/src/backend/replication/slot.c b/src/backend/replication/slot.cindex 52da694c79..b072873b74 100644--- a/src/backend/replication/slot.c+++ b/src/backend/replication/slot.c@@ -1380,6 +1380,7 @@ InvalidatePossiblyObsoleteSlot(ReplicationSlotInvalidationCause cause,
restart_lsn = s->data.restart_lsn;
+elog(LOG, "!!!InvalidatePossiblyObsoleteSlot| cause: %d, s->data.invalidated: %d", cause, s->data.invalidated);
/*
* If the slot is already invalid or is a non conflicting slot, we
* don't need to do anything.
@@ -1399,6 +1400,7 @@ InvalidatePossiblyObsoleteSlot(ReplicationSlotInvalidationCause cause,
/* invalid DB oid signals a shared relation */
if (dboid != InvalidOid && dboid != s->data.database)
break;
+elog(LOG, "!!!InvalidatePossiblyObsoleteSlot| RS_INVAL_HORIZON, s: %p, s->effective_xmin: %u, s->effective_catalog_xmin: %u, snapshotConflictHorizon: %u", s, s->effective_xmin, s->effective_catalog_xmin, snapshotConflictHorizon);
if (TransactionIdIsValid(s->effective_xmin) &&
TransactionIdPrecedesOrEquals(s->effective_xmin,
snapshotConflictHorizon))
@@ -1417,6 +1419,7 @@ InvalidatePossiblyObsoleteSlot(ReplicationSlotInvalidationCause cause,
}
}
+elog(LOG, "!!!InvalidatePossiblyObsoleteSlot| conflict: %d", conflict);
/* if there's no conflict, we're done */
if (conflict == RS_INVAL_NONE)
{
@@ -1487,6 +1490,7 @@ InvalidatePossiblyObsoleteSlot(ReplicationSlotInvalidationCause cause,
*/
if (last_signaled_pid != active_pid)
{
+elog(LOG, "!!!InvalidatePossiblyObsoleteSlot| before ReportSlotInvalidation(..., true, ...)");
ReportSlotInvalidation(conflict, true, active_pid,
slotname, restart_lsn,
oldestLSN, snapshotConflictHorizon);
@@ -1532,6 +1536,7 @@ InvalidatePossiblyObsoleteSlot(ReplicationSlotInvalidationCause cause,
ReplicationSlotRelease();
pgstat_drop_replslot(s);
+elog(LOG, "!!!InvalidatePossiblyObsoleteSlot| before ReportSlotInvalidation(..., false, ...)");
ReportSlotInvalidation(conflict, false, active_pid,
slotname, restart_lsn,
oldestLSN, snapshotConflictHorizon);
@@ -1575,6 +1580,7 @@ InvalidateObsoleteReplicationSlots(ReplicationSlotInvalidationCause cause,
if (max_replication_slots == 0)
return invalidated;
+elog(LOG, "!!!InvalidateObsoleteReplicationSlots");
XLogSegNoOffsetToRecPtr(oldestSegno, 0, wal_segment_size, oldestLSN);
restart:
@@ -1586,10 +1592,12 @@ restart:
if (!s->in_use)
continue;
+elog(LOG, "!!!InvalidateObsoleteReplicationSlots| before InvalidatePossiblyObsoleteSlot");
if (InvalidatePossiblyObsoleteSlot(cause, s, oldestLSN, dboid,
snapshotConflictHorizon,
&invalidated))
{
+elog(LOG, "!!!InvalidateObsoleteReplicationSlots| InvalidatePossiblyObsoleteSlot returned true, invalidated: %d", invalidated);
/* if the lock was released, start from scratch */
goto restart;
}
diff --git a/src/backend/storage/ipc/standby.c b/src/backend/storage/ipc/standby.cindex d8755a106d..c4cb24cc50 100644--- a/src/backend/storage/ipc/standby.c+++ b/src/backend/storage/ipc/standby.c@@ -500,9 +500,12 @@ ResolveRecoveryConflictWithSnapshot(TransactionId snapshotConflictHorizon,
* reached, e.g. due to using a physical replication slot.
*/
if (wal_level >= WAL_LEVEL_LOGICAL && isCatalogRel)
+{+//elog(LOG, "!!!ResolveRecoveryConflictWithSnapshot| RS_INVAL_HORIZON, snapshotConflictHorizon: %u, locator.dbOid: %d, locator.relNumber: %d", snapshotConflictHorizon, locator.dbOid, locator.relNumber);
InvalidateObsoleteReplicationSlots(RS_INVAL_HORIZON, 0, locator.dbOid,
snapshotConflictHorizon);
}
+}
/*
* Variant of ResolveRecoveryConflictWithSnapshot that works with
035-pruning-failure-logs.tar.gz (application/gzip, 149.0K) download
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: pgsql-hackers@postgresql.org
Cc: exclusion@gmail.com, bertranddrouvot.pg@gmail.com, michael@paquier.xyz, shiy.fnst@fujitsu.com, tgl@sss.pgh.pa.us, robertmhaas@gmail.com, andres@anarazel.de, thomas.munro@gmail.com, pgsql-hackers@lists.postgresql.org
Subject: Re: Test slots invalidations in 035_standby_logical_decoding.pl only if dead rows are removed
In-Reply-To: <5d0e5bec-67f9-9164-36cb-c4ff5f95d1ed@gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox