Horton

RE: Synchronizing slots from primary to standby

Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>

View thread View on postgr.es
From: "Zhijie Hou (Fujitsu)" <houzj.fnst@fujitsu.com>
To: Amit Kapila <amit.kapila16@gmail.com>, Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Cc: shveta malik <shveta.malik@gmail.com>, Bharath Rupireddy <bharath.rupireddyforpostgres@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-08T06:48:57Z
Lists: pgsql-hackers

Attachments

On Saturday, April 6, 2024 12:43 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> On Fri, Apr 5, 2024 at 8:05 PM Bertrand Drouvot
> <bertranddrouvot.pg@gmail.com> wrote:
> >
> > On Fri, Apr 05, 2024 at 06:23:10PM +0530, Amit Kapila wrote:
> > > On Fri, Apr 5, 2024 at 5:17 PM Amit Kapila <amit.kapila16@gmail.com>
> wrote:
> > > 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.
> >
> > Agree.
> >
> > > 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.
> >
> > Agree, I think it's not visible through pg_current_wal_lsn() yet.
> >
> > Also I think that the DEBUG message in LogCurrentRunningXacts()
> >
> > "
> >         elog(DEBUG2,
> >              "snapshot of %d+%d running transaction ids (lsn %X/%X oldest
> xid %u latest complete %u next xid %u)",
> >              CurrRunningXacts->xcnt, CurrRunningXacts->subxcnt,
> >              LSN_FORMAT_ARGS(recptr),
> >              CurrRunningXacts->oldestRunningXid,
> >              CurrRunningXacts->latestCompletedXid,
> >              CurrRunningXacts->nextXid); "
> >
> > should be located after the XLogSetAsyncXactLSN() call. Indeed, the
> > new LSN is visible after the spinlock (XLogCtl->info_lck) in
> > XLogSetAsyncXactLSN() is released,
> >
> 
> I think the new LSN can be visible only when the corresponding WAL is written
> by XLogWrite(). I don't know what in XLogSetAsyncXactLSN() can make it
> visible. In your experiment below, isn't it possible that in the meantime WAL
> writer has written that WAL due to which you are seeing an updated location?
> 
> >see:
> >
> > \watch on Session 1 provides:
> >
> >  pg_current_wal_lsn
> > --------------------
> >  0/87D110
> > (1 row)
> >
> > Until:
> >
> > Breakpoint 2, XLogSetAsyncXactLSN (asyncXactLSN=8900936) at
> xlog.c:2579
> > 2579            XLogRecPtr      WriteRqstPtr = asyncXactLSN;
> > (gdb) n
> > 2581            bool            wakeup = false;
> > (gdb)
> > 2584            SpinLockAcquire(&XLogCtl->info_lck);
> > (gdb)
> > 2585            RefreshXLogWriteResult(LogwrtResult);
> > (gdb)
> > 2586            sleeping = XLogCtl->WalWriterSleeping;
> > (gdb)
> > 2587            prevAsyncXactLSN = XLogCtl->asyncXactLSN;
> > (gdb)
> > 2588            if (XLogCtl->asyncXactLSN < asyncXactLSN)
> > (gdb)
> > 2589                    XLogCtl->asyncXactLSN = asyncXactLSN;
> > (gdb)
> > 2590            SpinLockRelease(&XLogCtl->info_lck);
> > (gdb) p p/x (uint32) XLogCtl->asyncXactLSN
> > $1 = 0x87d148
> >
> > Then session 1 provides:
> >
> >  pg_current_wal_lsn
> > --------------------
> >  0/87D148
> > (1 row)
> >
> > So, when we see in the log:
> >
> > 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)
> > 2024-04-05 04:37:05.197 UTC [3866475][client backend][2/4:0] LOG:
> statement: SELECT '0/3000060' <= replay_lsn AND state = 'streaming'
> >
> > It's indeed possible that the new LSN was not visible yet (spinlock
> > not released?) before the query began (because we can not rely on the
> > time the DEBUG message has been emitted).
> >
> > > 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
> >
> > It think it is.
> >
> > > 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?
> >
> > I think that maybe as a first step we should move the "elog(DEBUG2,"
> > message as proposed above to help debugging (that could help to confirm
> the above theory).
> >
> 
> I think I am missing how exactly moving DEBUG2 can confirm the above theory.
> 
> > If the theory is proven then I'm not sure we need the extra complexity
> > of injection point here, maybe just relying on the slots created via
> > SQL API could be enough.
> >
> 
> Yeah, that could be the first step. We can probably add an injection point to
> control the bgwrite behavior and then add tests involving walsender
> performing the decoding. But I think it is important to have sufficient tests in
> this area as I see they are quite helpful in uncovering the issues.

Here is the patch to drop the subscription in the beginning so that the
restart_lsn of the lsub1_slot won't be advanced due to concurrent
xl_running_xacts from bgwriter. The subscription will be re-created after all
the slots are sync-ready. I think maybe we can use this to stabilize the test
as a first step and then think about how to make use of injection point to add
more tests if it's worth it.

Best Regards,
Hou zj

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