Re: [PATCH v1 0/7] Wait event timing and tracing instrumentation

Hi Andrey,

Thank you very much for this review. The memory finding is correct
(more details on it below).
The hook direction is the right one. I have done tests you suggested
on a dedicated bare-metal host, and below are the numbers.
One decision I would like to invite objections to,
and a list of further v6 defects I found while preparing the experiments.

The short version:

* I built and measured two hook placements against unmodified
master: the transition placement you described (a hook call
inside every pgstat_report_wait_start()/end() transition), and a
timed-pair placement (a second pair of inline functions used only
at explicitly converted call sites, with the ordinary pair left
byte-identical to master).

* With no collector loaded they cost the same: about 2 ns per pair
on the already-set-latch path, and no statistically resolved
end-to-end difference on any workload.

* I propose the timed pair for v7, for reasons that are not
performance, and attach it as a small RFC patch.

* v6 has five confirmed source defects (yours is the first) and two
documentation/API mismatches. All are listed below with the v7
fix. v6 should not be reviewed further; with this mail the CF
entry carries only the two core patches below.

Test setup (Host, build, protocol)
=====================

Intel Xeon Platinum 8462Y+ (2 sockets, 1 TiB), Linux 5.14,
performance governor, otherwise idle. Server pinned to 8 physical
cores, pgbench to 8 other physical cores on the same NUMA node, no
SMT sibling shared between the two sets. GCC 11.5, -O2 -g0, autoconf,
assertions off. Master base fc9743420ded. Every configuration is a
separate installation, with a fresh server for every measured cell.

12 repetitions per cell, 10 s untimed warm-up, 30 s measured,
randomized complete Latin-square order so that every configuration
occupies every schedule position exactly once, paired Student t 95%
intervals, no outlier removal.

Gate before anything else: two independent builds of master (they
produced byte-identical binaries) run as separate installations
against each other on select-only pgbench, 16 clients:
+0.16% [-0.44, +0.76].

Configurations, your list plus controls, each for both placements:

master unmodified
v6-off v6 compiled in, wait_event_capture = off
NULL hooks present, no collector loaded (pointers NULL)
module-off collector preloaded, capture off
stats, trace collector enabled
control same source and object layout as NULL, with the hook
call sites compiled out

The layout control exists because an earlier round of this work found
a 3% TPC-B difference that was binary layout rather than code. Every
NULL comparison below is against its own control, not against master.

Isolated start/end pair (W1)
============================

A test-module function calls WaitLatch() on an already-set latch
10^8 times, with the whole loop timed. This is the path you named: it
reports a wait and returns without entering the kernel. Medians:

ns/iteration
master 9.24
v6-off 10.18
transition: control 9.16
NULL 11.30
module-off 16.68
stats 34.28
trace 36.12
timed pair: control 9.39
NULL 11.42
module-off 16.49
stats 34.29
trace 36.12

Paired differences over the 12 repetitions:

transition NULL - control +2.11 ns [+1.82, +2.40]
timed-pair NULL - control +1.97 ns [+1.64, +2.29]
timed-pair NULL - transition NULL -0.04 ns [-0.43, +0.35]

So the unplugged hook costs about 2 ns per pair on this path, with
an upper bound of 2.4 ns, and the same under both placements. One
note on provenance, since it is visible in the package: an earlier
run of the same test (+1.92 [+1.61, +2.22] and +1.87 [+1.62, +2.12])
stopped at a 2 ns continuation gate I had set for myself; I changed
that gate to report-only, reran the W0 and W1 stages under a new run
identifier, and continued to W2-W6 with no other change to the
protocol. Both runs are in the package. For reference, v6-off is
about 0.9 ns over master on this path, but that is a different
binary with no paired control.

The other W1 paths, NULL minus control:

transition timed pair
timeout-zero WaitLatch +0.43 [-0.21,+1.07] +0.32 [-0.01,+0.66]
cached FileReadV +0.08 [-1.06,+1.21] +2.52 [+0.58,+4.47]
pg_usleep(0) +0.71 [+0.56,+0.87] +0.02 [-0.03,+0.08]
bare report pair +0.18 [+0.17,+0.20] -0.01 [-0.03,+0.01]

Two comments. The FileReadV number for the timed pair is larger than
for the other placement and I cannot explain it: the FileReadV
instruction streams of the two NULL builds are identical, each has
exactly one hook pair, and the paired differences only turn positive
in the last five repetitions. I report it as measured. The last row
is the ordinary pgstat_report_wait_start()/end() pair on its own: the
transition hook makes it 0.18 ns slower than master's; under the
timed pair it is master's code. (pg_usleep(0) returns without a
syscall on Linux, so that row is another annotation-only path, not a
sleep.)

End-to-end, NULL hook minus layout control
==========================================

W2 select-only, 1 client, 4 GB shared_buffers
W3 8 clients on a deterministic short ProcArrayLock wait, 16 MB
W4 select-only, 16 clients, 4 GB
W5 TPC-B, 16 clients
W6a select-only, 16 clients, 32 MB
W6b TPC-B, 16 clients, 32 MB
W6c select-only, 32 clients, 32 MB
W6d one-hot-row update, 32 clients, 32 MB

TPS difference in percent, positive = the NULL build was faster:

transition timed pair timed - transition
W2 +0.17 [-0.67,+1.00] +0.48 [+0.18,+0.78] +0.02 [-0.34,+0.38]
W3 +1.26 [-1.64,+4.17] +0.09 [-2.55,+2.73] +0.01 [-2.37,+2.39]
W4 +1.06 [+0.61,+1.52] +1.13 [+0.79,+1.46] +0.13 [-0.18,+0.44]
W5 +0.49 [-0.19,+1.18] +0.31 [-0.55,+1.16] -0.43 [-1.06,+0.21]
W6a +0.47 [+0.17,+0.77] +0.80 [+0.48,+1.11] +0.28 [-0.03,+0.58]
W6b -0.38 [-2.02,+1.26] +0.04 [-0.71,+0.79] +1.25 [-0.80,+3.29]
W6c +0.47 [+0.20,+0.74] +0.68 [+0.35,+1.00] +0.08 [-0.17,+0.33]
W6d -0.15 [-0.39,+0.09] -0.05 [-0.28,+0.18] +0.57 [-0.31,+1.44]

No NULL build is resolvably slower than its control, and no workload
resolves a difference between the two placements. Several NULL builds
are resolvably faster than their controls (W4, W6a, W6c). That is not
the hook helping; it is the size of layout and code-generation effects
at this scale, and the reason the control is there.

Enabled cost
============

Relative to NULL, on the CPU-bound read workloads (W2, W3, W4, W6a,
W6c), stats cost about 0.5-1.1% and trace about 1.2-1.8%, for both
placements. W5, W6b and W6d are bottlenecked elsewhere and their
intervals include zero. Loading the collector with capture off adds
about 5.2 ns per pair on W1 (the indirect call plus the module's own
check); end-to-end that is generally below 0.5%, with a few cells
resolved at 0.2-0.4%.

Where the two placements do differ is with collection on. An ordinary
report that is not a timed site costs the transition collector about
25-27 ns more than module-off, because it observes every transition;
it costs the timed-pair collector nothing. At a timed site both cost
the same, about 18 ns (stats) and 19.5 ns (trace) over module-off.

Short waits (W3)
================

Qualified in a separate run with the same fixture, so the observer
query did not touch the TPS cells: about 607,000 LWLock waits/s, mean
5.15 us, p95 at or below 16.4 us, more than 99.9998% of recorded waits
being the target ProcArrayLock wait, 12 of 12 repetitions qualifying.
Enabled cost on W3 is in the same range as the other read workloads
(stats about 1.0%, trace 1.4-1.7%), so the short-wait case did not
show a disproportionate collector cost.

Register pressure
=================

Stack-memory operand counts from objdump of the retained binaries.
These count stack references, not proven spills; the 42 disassemblies
are in the package for anyone who wants to read them.

master v6-off transition timed pair
NULL ctrl NULL ctrl
WaitEventSetWait 40 40 40 40 40 40
FileReadV 0 0 0 0 0 0
LWLockAcquire 0 0 0 0 0 0
XLogWrite 36 40 40 36 40 36
SlruInternalWritePage 12 12 12 12 12 12
CopyReadLine 32 32 32 32 32 32
pgaio_io_perform_synchronously 0 0 0 0 0 0

The hook adds four stack references in XLogWrite, under both
placements, and the same four appear in v6-off; the other six
functions are unchanged. In this sample that is the one place where
Andres's spill concern is visible in the code, and it is the same
under all three designs.

The decision I am proposing
===========================

The two placements are indistinguishable in cost. I propose the timed
pair for v7, because:

1. pgstat_report_wait_start()/end() stay byte-identical to master;
the bare-pair row above is the direct measurement of that. My
understanding is that this is the property Andres was defending
when he wrote that he is "just about dead set adding even a
single cycle to wait events" [1]. The transition placement adds
the pointer test to that pair; the timed pair does not.

2. It is the explicitly opt-in, changed-over-per-call-site shape
Andres described for extended wait events [2]. The same message
asks that they count encounters as well as duration, which the
collector does, and that each converted site be justified by
reasoning or a careful experiment, which is what the tables
above are for. Andres, if that misreads you, please say so.

3. It converts every direct pgstat_report_wait_start() site the
backend executes, in one patch: 94 start sites and 111 end
calls (17 of them error-path cleanup calls) in 42 files, all of
src/backend plus the two control-file waits in src/common. So
present in-tree coverage equals the transition hook's, and
extension waits that go through core primitives (latches,
sockets, condition variables, LWLocks, file I/O) are covered
too, under the extension's own wait event name. What the timed
pair does not cover automatically is an extension's own
hand-annotated system call, the pattern in the custom-wait-event
example in xfunc.sgml: it stays visible in pg_stat_activity as
before, but is timed only once the extension switches those two
calls to the timed pair. To size that: of twenty widely used
extensions I checked, one uses that pattern (a storage engine
with its own files); the other nineteen and every in-tree
contrib module wait through core primitives and are covered
as is. The same applies to future core sites, where a site
that is not converted is one grep away. That is the coverage
the opt-in shape costs, and I would rather state it than hide
it.

The transition numbers are in every table above so that the choice is
visibly not made on performance. If you or Andres prefer the
transition placement after seeing them, the core part becomes a
smaller patch, not a different design, and I will switch.

Attached, against master at 412ef97d925c:

v7-0001 the two hook pointers, the recursion depth guard, and
pgstat_report_wait_start_timed()/end_timed() in
wait_event.h; 63 lines, nothing else in core changes.
v7-0002 the call-name conversions, 205 lines changed, no other
edits. The remaining rows of the series will follow as
v8 on this thread.

The hook contract is your list as written: void (*)(uint32
wait_event_info) for begin and for end; only preallocated
backend-local state; no waits, allocations, locks or errors; a
per-backend depth counter in core so that a wait inside a hook is
never re-entered. The collector chains by calling the previous begin
hook before its own and its own end hook before the previous end, and
both preload orders passed smoke tests, so a second consumer such as
EXPLAIN WAITS can stack on the same hook. One narrow question: is
wait_event_info alone, on both begin and end, enough for the
consumers you have in mind? I deliberately pass no timestamp, so each
consumer reads its own clock only when it is enabled.

v6 defects
==========

Reviewing v6 for this experiment found five source defects and two
documentation/API mismatches. They were established by source tracing;
none is exercised by the benchmark, which ran v6 with capture off.
All seven are in the collector, so the attached 0001/0002 touch none
of them; the fixes come with the contrib module.

1. Dense allocation on first use (your finding). v7: one sparse
slot per collecting backend, allocated at a safe point, never
inside the hook.

2. After ProcNumber reuse, a successor backend with capture off can
be shown with its predecessor's counters under its own PID and
role: the slot is zeroed only on lazy attach, and the reader
checks only that the current backend entry is live. v7: owner
identity recorded at attach and checked by every reader.

3. Under EXEC_BACKEND the trace orphan cleanup runs before the
trace control pointer is attached, returns early, and the later
attach skips the still-orphaned slot, so tracing is silently
disabled on ordinary ProcNumber reuse. v7: cleanup runs after
shared memory is attached.

4. Cross-backend reset checks only pg_signal_backend membership.
Unlike pg_signal_backend() it does not protect superuser or
role-less targets and it accepts auxiliary PIDs. v7: the same
rules as pg_signal_backend().

5. Reset resolves the PID to a ProcNumber under ProcArrayLock,
releases the lock, then bumps that slot's generation; a
successor that attached in between consumes the reset. v7: the
reset carries the target's identity and the consumer verifies
it.

6. Query markers are query-ID transitions, not the matched
Parse/Bind/Execute brackets the documentation describes. v7:
documentation and behaviour reconciled.

7. The documented direct reader for extensions references
WaitEventTraceCtl, which is file-static. v7: a supported
accessor is exported.

What v7 will contain
====================

0001/0002 above; the collector as contrib/pg_wait_event_timing (a
contrib module ships with every release and is available on managed
services the way pg_stat_statements is; if the preference is an
external extension, the core part is unchanged); sparse memory; the
seven fixes and tests for them. The collector used in this benchmark
is a port of the v6 hot path with sparse state, histograms, rings,
markers, snapshots and chaining, but without ACL, reset, post-mortem
retention or error nesting, so I will re-measure the enabled numbers
once on the real module before citing them in the cover letter.
I aim to post it before this commitfest closes at the end of
September, and in any case before the November one.

EXPLAIN WAITS: agreed that they are not competitors. Thank you for the
pointer to Ilmar's thread, which I had not connected to this one; if a
hook of this shape lands I am happy to align on one API so that his
collector can attach for the requested statement only.

Package
=======

The 2,040 raw result rows (matching the predeclared schedules), the
scripts, the exact commits, the 42 disassemblies, and a VERIFY.sh that
regenerates every report from the raw JSON:

https://github.com/DmitryNFomin/pg-wait-event-hook-benchmark/releases/download/v2026-09-09/wait-hook-peer-review-20260909-REDACTED.tar.gz

(69,367,758 bytes, SHA-256
83b01bc010f3dc330d8e04b2bad9fa1d54d1298757f5cc84bb78ff8accc286b7;
the repository README lists the contents.)

Host names, user names and workspace paths in it are replaced by
neutral tokens and its hash manifests were regenerated for the copy;
the numbers are untouched and VERIFY.sh passes on it. One caveat
recorded in it: the run finished all workloads and the post-processing
step then exited with 141 (an early-exit awk sending SIGPIPE to
objdump under pipefail). The disassembly step was rerun; no workload
was; the original exit status is preserved.

Thanks again.

[1] https://www.postgresql.org/message-id/uah2s5tppv3onn7bsf2uelyexfrxwrmye6qqyrbbsjepxny7l5@guymflaarnsr
[2] https://www.postgresql.org/message-id/sofkrmi3skg3ekc3y23uwxscbviy5lcbukincoyauypg4ylfdg@6lwzhi6uagc7

Regards,
Dmitry Fomin