On Sun, Sep 20, 2026 at 10:16 AM Xuneng Zhou <[email protected]> wrote: > > Hi Alexander, > > On Mon, Apr 20, 2026 at 9:54 PM Xuneng Zhou <[email protected]> wrote: > > > > On Mon, Apr 20, 2026 at 6:21 PM Alexander Korotkov <[email protected]> wrote: > > > > > > On Sat, Apr 18, 2026 at 10:58 AM Alexander Korotkov > > > <[email protected]> wrote: > > > > On Sat, Apr 18, 2026 at 7:20 AM Xuneng Zhou <[email protected]> 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.
v1-0002-Use-WAL-insertion-end-positions-in-WAIT-examples-.patch
Description: Binary data
v1-0001-Expose-the-WAL-insertion-end-position-to-SQL.patch
Description: Binary data
