Re: test: avoid redundant standby catchup in 049_wait_for_lsn - Mailing list pgsql-hackers

On Sun, Sep 20, 2026 at 10:16 AM Xuneng Zhou <xunengzhou@gmail.com> wrote:
>
> Hi Alexander,
>
> On Mon, Apr 20, 2026 at 9:54 PM Xuneng Zhou <xunengzhou@gmail.com> wrote:
> >
> > On Mon, Apr 20, 2026 at 6:21 PM Alexander Korotkov <aekorotkov@gmail.com> wrote:
> > >
> > > On Sat, Apr 18, 2026 at 10:58 AM Alexander Korotkov
> > > <aekorotkov@gmail.com> wrote:
> > > > On Sat, Apr 18, 2026 at 7:20 AM Xuneng Zhou <xunengzhou@gmail.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.