On Wed, Apr 30, 2025 at 2:38 AM Zhijie Hou (Fujitsu) <houzj.f...@fujitsu.com> wrote: > > On Tue, Apr 29, 2025 at 6:57 PM Amit Kapila wrote: > > > > On Tue, Apr 29, 2025 at 3:01 AM Masahiko Sawada > > <sawada.m...@gmail.com> wrote: > > > > > > Your fix looks good to me. Is it worth considering putting an > > > assertion to verify if new two_phase_at is equal to or greater than > > > confirmed_lsn (or at least it doesn't go backward), when syncing > > > two_phase_at? > > > > > > > Yeah, it makes sense. But the condition should be reverse (two_phase_at > > should be less than or equal to confirmed_flush). I have done that, changed > > a > > few comments, and committed the patch. > > I noticed a BF failure[1] related to the fix, where the recently added > assertion > Assert(slot->data.two_phase_at <= slot->data.confirmed_flush) was broken. > After > examining the logs and code, I couldn't identify any functionality issues.
Yeah, that's weird. > AFAICS, the last slotsync cycle should have retrieved the latest > confirmed_flush and > two_phase_at from the source slot, both expected to be 0/6005150. Here are > some details: > > The standby's log[1] shows the source slot's two_phase_at as 0/6005150. > Meanwhile, the publisher's log reveals that the source slot's confirmed_flush > was already 0/6005150 before the last slotsync. Therefore, the last slotsync > cycle should have fetched confirmed_flush: 0/6005150, two_phase_at: 0/6005150. > > If we assume remote_slot->confirmed_lsn during the last sync cycle is > 0/6005150, then either the local slot's confirmed_lsn had already been updated > to this value in a prior sync, leading it to skip the update in the last cycle > (in which case, the assertion shouldn't be broken), or it should enter the > slot > update branch to set the synced slot to 0/6005150 (see > update_local_synced_slot() for details). Thus, theoretically, the assertion > wouldn't fail. Agreed with your analysis. After enabling the subscription with two_phase=true, the primary server has the following logs that indicate that logical decoding started from 0/6005150, not 0/6004FC8. Given that the slot's two_phase was enabled at this time, the slot's confirmed_flush and two_phase_at were 0/6005150. 2025-04-29 09:18:05.487 UTC [1022913][walsender][29/0:0] LOG: received replication command: START_REPLICATION SLOT "lsub1_slot" LOGICAL 0/6004FC8 (proto_version '4', streaming 'parallel', two_phase 'on', origin 'any', publication_names '"regress_mypub"') 2025-04-29 09:18:05.487 UTC [1022913][walsender][29/0:0] STATEMENT: START_REPLICATION SLOT "lsub1_slot" LOGICAL 0/6004FC8 (proto_version '4', streaming 'parallel', two_phase 'on', origin 'any', publication_names '"regress_mypub"') 2025-04-29 09:18:05.487 UTC [1022913][walsender][29/0:0] LOG: acquired logical replication slot "lsub1_slot" 2025-04-29 09:18:05.487 UTC [1022913][walsender][29/0:0] STATEMENT: START_REPLICATION SLOT "lsub1_slot" LOGICAL 0/6004FC8 (proto_version '4', streaming 'parallel', two_phase 'on', origin 'any', publication_names '"regress_mypub"') 2025-04-29 09:18:05.487 UTC [1022913][walsender][29/0:0] LOG: 0/6004FC8 has been already streamed, forwarding to 0/6005150 2025-04-29 09:18:05.487 UTC [1022913][walsender][29/0:0] STATEMENT: START_REPLICATION SLOT "lsub1_slot" LOGICAL 0/6004FC8 (proto_version '4', streaming 'parallel', two_phase 'on', origin 'any', publication_names '"regress_mypub"') 2025-04-29 09:18:05.516 UTC [1022913][walsender][29/0:0] LOG: starting logical decoding for slot "lsub1_slot" 2025-04-29 09:18:05.516 UTC [1022913][walsender][29/0:0] DETAIL: Streaming transactions committing after 0/6005150, reading WAL from 0/6004A00. 2025-04-29 09:18:05.516 UTC [1022913][walsender][29/0:0] STATEMENT: START_REPLICATION SLOT "lsub1_slot" LOGICAL 0/6004FC8 (proto_version '4', streaming 'parallel', two_phase 'on', origin 'any', publication_names '"regress_mypub"') > > Beyond functionality problems, another possibility might be the CPU reordered > memory access, causing the assertion to execute before updating > confirmed_flush. Not sure CPU reordered memory access could matter in this case but I don't have other ideas of possible causes. > However, we lack the information needed to verify this, so one > idea is to add some DEBUG message in update_local_synced_slot() to facilitate > tracking if the issue recurs. That would be a good idea. Also, it's unrelated to this issue but probably we are better off doing this assertion check only when enabling two_phase. The assertion is currently checked even when disabling the two_phase, which seems not to make sense, and we don't clear two_phase_at value when disabling two_phase by ReplicationSlotAlter(). Regards, -- Masahiko Sawada Amazon Web Services: https://aws.amazon.com
