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-05T12:53:10Z
Lists: pgsql-hackers 
On Fri, Apr 5, 2024 at 5:17 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> 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.
>

Thinking more on this, it doesn't seem related to
c9920a9068eac2e6c8fb34988d18c0b42b9bf811 as that commit doesn't change
any locking or something like that which impacts write positions. I
think what has happened here is that running_xact record written by
the background writer [1] is not written to the kernel or disk (see
LogStandbySnapshot()), before pg_current_wal_lsn() checks the
current_lsn to be compared with replayed LSN. Note that the reason why
walsender has picked the running_xact written by background writer is
because it has checked after pg_current_wal_lsn() query, see LOGs [2].
I think we can probably try to reproduce manually via debugger.

If this theory is correct then I think we will need to use injection
points to control the behavior of bgwriter or use the slots created
via SQL API for syncing in tests.

Thoughts?

[1] - 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)

[2] -
2024-04-05 04:37:05.134 UTC [3866413][client backend][1/4:0] LOG:
statement: SELECT pg_current_wal_lsn()
2024-04-05 04:37:05.144 UTC [3866413][client backend][:0] LOG:
disconnection: session time: 0:00:00.021 user=bf database=postgres
host=[local]
2024-04-05 04:37:05.144 UTC [3857385][walsender][25/0:0] DEBUG:
serializing snapshot to pg_logical/snapshots/0-3000060.snap

-- 
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).