Re: test: avoid redundant standby catchup in 049_wait_for_lsn

On Tue, Sep 22, 2026 at 5:22 PM Xuneng Zhou <xunengzhou(at)gmail(dot)com> wrote:

>
>
> On Sun, Sep 20, 2026 at 10:16 AM Xuneng Zhou <xunengzhou(at)gmail(dot)com> wrote:
> >
> > Hi Alexander,
> >
> > On Mon, Apr 20, 2026 at 9:54 PM Xuneng Zhou <xunengzhou(at)gmail(dot)com>
> wrote:
> > >
> > > On Mon, Apr 20, 2026 at 6:21 PM Alexander Korotkov <
> aekorotkov(at)gmail(dot)com> wrote:
> > > >
> > > > On Sat, Apr 18, 2026 at 10:58 AM Alexander Korotkov
> > > > <aekorotkov(at)gmail(dot)com> wrote:
> > > > > On Sat, Apr 18, 2026 at 7:20 AM Xuneng Zhou <xunengzhou(at)gmail(dot)com>
> wrote:
> > > > > >> On Fri, Apr 17, 2026 at 08:25:35PM +0800, Xuneng Zhou wrote:
> > > > > >> > The change preserves the same coverage while removing one
> redundant
> > > > > >> > replay catch-up on the delayed standby. It appears to reduce
> the test
> > > > > >> > runtime by about 7 seconds, though I have looked into why
> much of the
> > > > > >> > improvement comes from this change alone.
> > > > > >>
> > > > > >> Alexander may think differently and remove that, but I
> disagree. The
> > > > > >> test is clearly written so as we want two wait checks to
> happen, for
> > > > > >> for CREATE FUNCTION, and one for CREATE PROCEDURE. Removing
> the first
> > > > > >> check to keep only the second one removes its meaning. In
> short, I
> > > > > >> see nothing wrong to deal with here.
> > > > > >
> > > > > >
> > > > > > Thank you for the review. I agree that the two wait checks serve
> distinct purposes and are not redundant. The main motivation for this patch
> was efficiency. In my testing, the new test added approximately 7 seconds
> to the runtime, while the creation of the procedure and function completed
> quickly. I suspect the latency stems from the wait-for-catch-up step. When
> I removed it, the test runtime dropped by about 7 seconds.I haven't yet
> investigated why the wait is so costly in this case. I should probably look
> into that before proposing this change.
> > > > >
> > > > > On my laptop the time needed to run t/049_wait_for_lsn.pl also
> drops
> > > > > from 20 secs to 12 secs. The influence to the runtime of the whole
> > > > > test suite in parallel would be not that big as CPU time only drops
> > > > > from 2.16 sec to 2.07 sec. But anyway that's pretty significant.
> > > > > I've revised comment message a bit and surrounding comments. I'm
> > > > > going to push this if no objections.
> > > >
> > > > Pushed.
> > > >
> > >
> > > Thanks for pushing it. I haven't had time to investigate the latency
> > > yet, but will do it later.
> >
> > While working on other things, I revisited the thread and looked into
> > the issue. The delayed investigation has exposed an unexpected
> > fragility. I'll post some findings soon.
>
> ===== The cause of the delay
> In 23cbadeeb47, we combined the creation of two wrappers into a single
> session and used one wait_for_catchup for synchronization. After this
> commit, the 8s delay has disappeared, which is strange, since the saved
> wait_for_catchup shouldn't be that costly. In a timed run on a build before
> 23cbadeeb47, the two DDL catch-ups took 0.987s and 0.985s (matched the
> configured one-second replay delay), which means the time for saving the
> catchup is less than 1s. The rest of saving time has gone somewhere else.
>
> [09:49:21.319](0.012s) # TIMING 0.006 standby
> ALTER SYSTEM SET primary_conninfo = '...'; SELECT pg_reload_conf();
>
> [09:49:29.901](8.582s) # TIMING 0.016 standby
> SELECT pg_lsn_cmp(...);
> [09:49:29.901](0.000s) ok 31 - mixed mode waiters: all modes completed and
> reached target LSN
>
> In the timed runs on the same historical build, there's a consistent ~8s
> gap between resuming the wal receiver and the lsn check in test 7d. This
> means that it tooks ~8s for the 6 waiters to reach their target LSN, which
> is unexpected since there's no additional delay settings.
>
> These are the fetched LSN for the waiting:
>
> Wait target: 0/0301A018
> Primary insertion: 0/0301A018
>
> Primary write/flush: 0/0301A000
> Standby write/flush/replay: 0/0301A000
>
> Blocked waiters: 6
>
> We cans see that the primary and standby's progressing LSNs had all
> reached '0/0301A000'. But the target LSN returned by
> pg_current_wal_insert_lsn() was '0/0301A018' -- 24 bytes ahead.
>
> That gap corresponds exactly to a WAL page header. '0/0301A000' lies on an
> 8kb page boundary Consistently, pg_waldump showed a 34-byte COMMIT record
> starting at 0/03019FD8; after alignment, it occupies 40 bytes and ends
> exactly at that boundary.
>
> At this boundary, pg_current_wal_insert_lsn() returns the next insertion
> address, which is after the header gap. The test thus waited for a position
> beyond the existing WAL, requiring another WAL record to make progress. The
> unrelated progression comes from the primary's background writer who
> generated a RUNNING_XACTS record, advancing WAL to 0/0301A050, and then
> notified the waiters.
>
> There are similar cases reported and fixed before[1] [2].
>
> ===== The accidental removal of the delay
> In a small experiment to differentiate the time saved by removing one
> catch-up and combining two creations into one sessions, the results shows
> as follows:
>
> Variant Sessions Catch-ups Result
> Before 2 2 Boundary stall;
> 20.072s
> After 1 1 No boundary
> stall; 11.297s
> Control 2 1 Boundary stall
> returns; 19.012s
>
> the combination of creations contributed the majority of time saving. That
> change also introduced the initial divergence and subsequent changes of the
> layout of WAL records in before-and-after commit runs:
>
> --- The WAL layout before the commit 23cbadeeb47
>
> Section / operation XID Aligned COMMIT end Offset
> within 8 KiB WAL page
>
> 5: wrapper function DDL 698 0/0300CFC0 0x0FC0
> 5: procedure DDL 699 0/0300F5B8 0x15B8
>
> ...
>
> 7d: mixed waiters 717 0/0301A000 0x0000
>
> --- The WAL layout after the commit
>
> 5: wrapper function DDL 698 0/0300CFC0 0x0FC0
> 5: procedure DDL 699 0/0300F888 0x1888
>
> ...
>
> 7d: mixed waiters 717 0/030143F0 0x03F0
>
> We can see that the first divergence occurred in 5: procedure DDL and
> section 7d's COMMIT end shifted away from the boundary 0/0301A000 to
> 0/030143F0. Therefore, the getter pg_current_wal_insert_lsn would just
> return the current insert LSN as the target LSN without adding the header
> gap. It won't exceed the LSN being replayed and flushed, hence avoiding the
> stall of waiting future unrelated WAL records.
>
> Where did the WAL reduction from 0/0301A000 to 0/030143F0 between two runs
> comes from? An analysis with pg_waldump shows that combining the
> definitions of function and procedure in 5d into one backend session
> preserves its cached insertion target, so the procedure creation can reuse
> the catalog page modified by the preceding function, thus avoiding another
> full-page image. That different placement also changes subsequent FSM
> searches and page occupancy, allowing later helpers definitions to
> genenerate smaller or fewer page images.
>
>
> ===== Fix it once for all
>
> As the investigation indicates, the root cause of the delay is
> pg_current_wal_insert_lsn can return a position beyond the end of existing
> WAL: when the last record ends exactly at a page boundary, the returned
> position skips the next page’s header. In practice, this seems not a
> serious problem as long as the WAL reception and replay is normal --
> unrelated WAL records would eventually unleash the waiters. In some edge
> cases, however, it would be more concerning since future wake-up is could
> be unguaranteed. Other getters like pg_current_wal_lsn(),
> pg_current_wal_flush_lsn() do not skip page headers and can work well for
> synchronous commit. But COMMIT could return before its WAL is written or
> flushed in asynchronous settings. I am wondering whether we would expose
> GetXLogInsertEndRecPtr() introduced in b1f14c96720 as sql function and let
> the command make use of it.
>
> [1]
> https://www.postgresql.org/message-id/E1w1B0a-0002Si-0M%40gemulon.postgresql.org
> [2]
> https://www.postgresql.org/message-id/flat/vf4hbwrotvhbgcnknrqmfbqlu75oyjkmausvy66ic7x7vuhafx%40e4rvwavtjswo
>

Here are the attachments of timing scripts, timestamped logs and the dumped
wal files.

On a second thought, GetXLogInsertEndRecPtr() still returns the globally
reserved insertion pointer rather than the specific ptr for session or txn,
so fetched target LSN could be an unrelated record generated by other
backends concurrently, which means that the user could also wait for
unnecessary wal progress to achieve read-after-your write consistency. We
could somehow expose the local commit record ptr, but it would narrow the
command use cases from waiting for wal progress to waiting for a commit
record, since some operations like non-transactional logical messages won't
emit a commit record.

--
Regards,
Xuneng Zhou
HighGo Software Co., Ltd.