Re: test: avoid redundant standby catchup in 049_wait_for_lsn

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

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