MIME-Version: 1.0
References: 
 <CAHGQGwF6zG9Z8ws1yb3hY1VqV-WT7hR0qyXCn2HdbjvZQKufDw@mail.gmail.com>
 <CAA4eK1KLk+TWyNPJ=z6SzQQXySc-N9Gs3eR-QKfV+MX7vfJWiw@mail.gmail.com>
 <CAHGQGwG1br8SQQnBieyJeRAmnMejEtJrVmurfTPxNouLHSW=jA@mail.gmail.com>
 <CAA4eK1KB6geysORVyOh-dJ+9U57CBC30K2XD3fQ6SKZc0Hsi3Q@mail.gmail.com>
 <TYRPR01MB14195ED854BE834AFDC815E9494592@TYRPR01MB14195.jpnprd01.prod.outlook.com>
In-Reply-To: 
 <TYRPR01MB14195ED854BE834AFDC815E9494592@TYRPR01MB14195.jpnprd01.prod.outlook.com>
From: Amit Kapila <amit.kapila16@gmail.com>
Date: Fri, 10 Apr 2026 15:22:34 +0530
Message-ID: 
 <CAA4eK1++dGmvReJ4pRw09qdrUED=iUfyiEM-fN03D2VVK1de1A@mail.gmail.com>
Subject: Re: Fix slotsync worker busy loop causing repeated log messages
To: "Zhijie Hou (Fujitsu)" <houzj.fnst@fujitsu.com>
Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>,
 Fujii Masao <masao.fujii@gmail.com>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Archived-At: 
 <https://www.postgresql.org/message-id/CAA4eK1%2B%2BdGmvReJ4pRw09qdrUED%3DiUfyiEM-fN03D2VVK1de1A%40mail.gmail.com>
Precedence: bulk

On Fri, Apr 10, 2026 at 8:28=E2=80=AFAM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> On Sunday, March 22, 2026 1:47 AM Amit Kapila <amit.kapila16@gmail.com> w=
rote:
> > On Thu, Mar 19, 2026 at 7:08=E2=80=AFPM Fujii Masao <masao.fujii@gmail.=
com>
> > wrote:
> > >
> > > On Sat, Feb 28, 2026 at 2:03=E2=80=AFPM Amit Kapila <amit.kapila16@gm=
ail.com>
> > wrote:
> > > >
> > > > On Fri, Feb 27, 2026 at 8:34=E2=80=AFPM Fujii Masao <masao.fujii@gm=
ail.com>
> > wrote:
> > > > >
> > > > > Normally, the slotsync worker updates the standby slot using the
> > > > > primary's slot state. However, when confirmed_flush_lsn matches
> > > > > but restart_lsn does not, the worker does not actually update the
> > > > > standby slot. Despite that, the current code of
> > > > > update_local_synced_slot() appears to treat this situation as if
> > > > > an update occurred. As a result, the worker sleeps only for the
> > > > > minimum interval (200 ms) before retrying. In the next cycle, it
> > > > > again assumes an update happened, and continues looping with the
> > > > > short sleep interval, causing the repeated logical decoding log m=
essages.
> > Based on a quick analysis, this seems to be the root cause.
> > > > >
> > > > > I think update_local_synced_slot() should return false (i.e., no
> > > > > update
> > > > > happened) when confirmed_flush_lsn is equal but restart_lsn
> > > > > differs between primary and standby.
> > > > >
> > > >
> > > > We expect that in such a case update_local_synced_slot() should
> > > > advance local_slot's 'restart_lsn' via
> > > > LogicalSlotAdvanceAndCheckSnapState(), otherwise, it won't go in th=
e
> > > > cheap code path next time. Normally, restart_lsn advancement should
> > > > happen when we process XLOG_RUNNING_XACTS and call
> > > > SnapBuildProcessRunningXacts(). In this particular case as both
> > > > restart_lsn and confirmed_flush_lsn are the same (0/03000140), the
> > > > machinery may not be processing XLOG_RUNNING_XACTS record. I have
> > > > not debugged the exact case yet but you can try by emitting some
> > > > more records on publisher, it should let the standby advance the
> > > > slot. It is possible that we can do something like you are proposin=
g
> > > > to silence the LOG messages but we should know what is going on her=
e.
> > >
> > > I agree it's important to investigate why restart_lsn doesn't advance
> > > in that case and fix that issue.
> > >
> > > Separately, I think mistreating the slot as updated is another proble=
m:
> > > the local slot is treated as updated even when it isn't, which causes
> > > the slotsync worker to use the minimum sleep interval. We should
> > > address this independently.
> > >
> > > LogicalSlotAdvanceAndCheckSnapState() doesn't always update the local
> > > slot, but update_local_synced_slot() currently assumes it does. That
> > > seems to be the root cause. The attached 0001 patch makes
> > > LogicalSlotAdvanceAndCheckSnapState() return whether the slot was
> > > actually updated, and updates update_local_synced_slot() to act based=
 on
> > that result.
> > >
> > > I've also attached 0002, which reduces the log level of some logical
> > > decoding messages (e.g., "logical decoding found consistent point")
> > > from LOG to DEBUG1. These are low-level, developer-oriented messages
> > > and can be noisy when they occur regularly. This is the same issue I
> > reported earlier at [1].
> > >
> > > How about applying these patches while we continue working on the
> > > restart_lsn issue?
> > >
> >
> > *
> > @@ -2174,7 +2193,10 @@
> > LogicalSlotAdvanceAndCheckSnapState(XLogRecPtr moveto,
> >
> >   if (XLogRecPtrIsValid(ctx->reader->EndRecPtr))
> >   {
> > - LogicalConfirmReceivedLocation(moveto);
> > + bool slot_updated =3D LogicalConfirmReceivedLocation(moveto);
> > +
> > + if (updated_xmin_or_lsn)
> > + *updated_xmin_or_lsn =3D slot_updated;
> >
> > BTW, LogicalSlotAdvanceAndCheckSnapState() could also advance slot whil=
e
> > processing running_xact record, so not sure we can rely only on the exp=
licit
> > call LogicalConfirmReceivedLocation() above to ascertain the same.
>
> Perhaps we could simply compare the slot's old and new LSN/xmin to determ=
ine
> whether updated_xmin_or_lsn needs to be set.
>

The patch works for me. Can we change the comment to as follows: "It
is possible that the slot's xmin or LSNs are not updated, when the
synced slot has reached consistent snapshot state or cannot build the
one at all."?

--=20
With Regards,
Amit Kapila.