Re: Fix slot synchronization with two_phase decoding enabled

On Wed, Apr 30, 2025 at 2:38 AM Zhijie Hou (Fujitsu)
<houzj(dot)fnst(at)fujitsu(dot)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(dot)mshk(at)gmail(dot)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