Horton

Re: Synchronizing slots from primary to standby

Amit Kapila <amit.kapila16@gmail.com>

View thread View on postgr.es
From: Amit Kapila <amit.kapila16@gmail.com>
To: shveta malik <shveta.malik@gmail.com>
Cc: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>, "Zhijie Hou (Fujitsu)" <houzj.fnst@fujitsu.com>, Bertrand Drouvot <bertranddrouvot.pg@gmail.com>, Ajin Cherian <itsajin@gmail.com>, Peter Smith <smithpb2250@gmail.com>, Masahiko Sawada <sawada.mshk@gmail.com>, Dilip Kumar <dilipbalaut@gmail.com>, Nisha Moond <nisha.moond412@gmail.com>, "Hayato Kuroda (Fujitsu)" <kuroda.hayato@fujitsu.com>, Peter Eisentraut <peter.eisentraut@enterprisedb.com>, Bruce Momjian <bruce@momjian.us>, Ashutosh Sharma <ashu.coek88@gmail.com>, Andres Freund <andres@anarazel.de>, pgsql-hackers <pgsql-hackers@postgresql.org>, Alvaro Herrera <alvherre@alvh.no-ip.org>
Date: 2024-04-05T11:47:17Z
Lists: pgsql-hackers 
On Thu, Apr 4, 2024 at 2:59 PM shveta malik <shveta.malik@gmail.com> wrote:
>
> There is an intermittent BF failure observed at [1] after this commit (2ec005b).
>

Thanks for analyzing and providing the patch. I'll look into it. There
is another BF failure [1] which I have analyzed. The main reason for
failure is the following test:

#   Failed test 'logical slots have synced as true on standby'
#   at /home/bf/bf-build/serinus/HEAD/pgsql/src/test/recovery/t/040_standby_failover_slots_sync.pl
line 198.
#          got: 'f'
#     expected: 't'

Here, we are expecting that the two logical slots (lsub1_slot, and
lsub2_slot), one created via subscription and another one via API
pg_create_logical_replication_slot() are synced. The standby LOGs
which are as follows show that the one created by API 'lsub2_slot' is
synced but the other one 'lsub1_slot':

LOG for lsub1_slot:
================
2024-04-05 04:37:07.421 UTC [3867682][client backend][0/2:0] DETAIL:
Streaming transactions committing after 0/0, reading WAL from
0/3000060.
2024-04-05 04:37:07.421 UTC [3867682][client backend][0/2:0]
STATEMENT:  SELECT pg_sync_replication_slots();
2024-04-05 04:37:07.422 UTC [3867682][client backend][0/2:0] DEBUG:
xmin required by slots: data 0, catalog 740
2024-04-05 04:37:07.422 UTC [3867682][client backend][0/2:0] LOG:
could not sync slot "lsub1_slot"

LOG for lsub2_slot:
================
2024-04-05 04:37:08.518 UTC [3867682][client backend][0/2:0] DEBUG:
xmin required by slots: data 0, catalog 740
2024-04-05 04:37:08.769 UTC [3867682][client backend][0/2:0] LOG:
newly created slot "lsub2_slot" is sync-ready now
2024-04-05 04:37:08.769 UTC [3867682][client backend][0/2:0]
STATEMENT:  SELECT pg_sync_replication_slots();

We can see from the log of lsub1_slot that its restart_lsn is
0/3000060 which means it will start reading from the WAL from that
location. Now, if we check the publisher log, we have running_xacts
record at that location. See following LOGs:

2024-04-05 04:36:57.830 UTC [3860839][client backend][8/2:0] LOG:
statement: SELECT pg_create_logical_replication_slot('lsub2_slot',
'test_decoding', false, false, true);
2024-04-05 04:36:58.718 UTC [3860839][client backend][8/2:0] DEBUG:
snapshot of 0+0 running transaction ids (lsn 0/3000060 oldest xid 740
latest complete 739 next xid 740)
....
....
2024-04-05 04:37:05.074 UTC [3854278][background writer][:0] DEBUG:
snapshot of 0+0 running transaction ids (lsn 0/3000098 oldest xid 740
latest complete 739 next xid 740)

The first running_xact record ends at 3000060 and the second one at
3000098. So, the start location of the second running_xact is 3000060,
the same can be confirmed by the following LOG line of walsender:

2024-04-05 04:37:05.144 UTC [3857385][walsender][25/0:0] DEBUG:
serializing snapshot to pg_logical/snapshots/0-3000060.snap

This shows that while processing running_xact at location 3000060, we
have serialized the snapshot. As there is no running transaction in
WAL at 3000060 so ideally we should have reached a consistent state
after processing that record on standby. But the reason standby didn't
process that LOG is that the confirmed_flush LSN is also at the same
location so the function LogicalSlotAdvanceAndCheckSnapState() exits
without reading the WAL at that location. Now, this can be confirmed
by the below walsender-specific LOG in publisher:

2024-04-05 04:36:59.155 UTC [3857385][walsender][25/0:0] DEBUG: write
0/3000060 flush 0/3000060 apply 0/3000060 reply_time 2024-04-05
04:36:59.155181+00

We update the confirmed_flush location with the flush location after
receiving the above feedback. You can notice that we didn't receive
the feedback for the 3000098 location and hence both the
confirmed_flush and restart_lsn are at the same location 0/3000060.
Now, the test is waiting for the subscriber to send feedback of the
last WAL write location by
$primary->wait_for_catchup('regress_mysub1'); As noticed from the
publisher LOGs, the query we used for wait is:

SELECT '0/3000060' <= replay_lsn AND state = 'streaming'
        FROM pg_catalog.pg_stat_replication
        WHERE application_name IN ('regress_mysub1', 'walreceiver')

Here, instead of '0/3000060' it should have used ''0/3000098' which is
the last write location. This position we get via function
pg_current_wal_lsn()->GetXLogWriteRecPtr()->LogwrtResult.Write. And
this variable seems to be touched by commit
c9920a9068eac2e6c8fb34988d18c0b42b9bf811. Though unlikely could
c9920a9068eac2e6c8fb34988d18c0b42b9bf811 be a reason for failure? At
this stage, I am not sure so just sharing with others to see if what I
am saying sounds logical. I'll think more about this.


[1] - https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=serinus&dt=2024-04-05%2004%3A34%3A27

-- 
With Regards,
Amit Kapila.

Commits

  1. Doc: Add the new section "Logical Replication Failover".

  2. Fix the review comments and a bug in the slot sync code.

  3. Fix a test in failover slots regression test.

  4. Fix the intermittent buildfarm failures in 040_standby_failover_slots_sync.

  5. Split XLogCtl->LogwrtResult into separate struct members

  6. Ensure that the sync slots reach a consistent state after promotion without losing data.

  7. Introduce a new GUC 'standby_slot_names'.

  8. Fix BF failure introduced by commit b3f6b14cf4.

  9. Fixups for commit 93db6cbda0.

  10. Fix BF failure in commit 93db6cbda0.

  11. Add a new slot sync worker to synchronize logical slots.

  12. Improve ERROR/LOG messages added by commits ddd5f4f54a and 7a424ece48.

  13. Disable autovacuum on primary in 040_standby_failover_slots_sync test.

  14. Fix the incorrect format specifier used in commit 7a424ece48.

  15. Change the LOG level in 040_standby_failover_slots_sync.pl to DEBUG2.

  16. Add more LOG and DEBUG messages for slot synchronization.

  17. Another try to fix BF failure introduced in commit ddd5f4f54a.

  18. Fix BF introduced in commit ddd5f4f54a.

  19. Add a slot synchronization function.

  20. Clean-ups for 776621a5e4 and 7329240437.

  21. Enhance libpqrcv APIs to support slot synchronization.

  22. Add a failover option to subscriptions.

  23. Allow setting failover property in the replication command.

  24. Allow to enable failover property for replication slots via SQL API.

  25. Add macros for looping through a List without a ListCell.

  26. Track conflict_reason in pg_replication_slots.

  27. Allow upgrades to preserve the full subscription's state.

  28. Add support for incremental backup.

  29. Simplify some logic in CreateReplicationSlot()

  30. Fix uninitialized access to InitialRunningXacts during decoding after ERROR.

  31. Flexible options for CREATE_REPLICATION_SLOT.

  32. Empty search_path in logical replication apply worker and walsender.

  33. Fix oldest xmin and LSN computation across repslots after advancing

  34. Require C99 (and thus MSCV 2013 upwards).