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

Hi hackers,

This is v11 of the timed-wait-event series, five patches. The number
jumps from v7 because three rounds in between were measured but
never posted: v8 was the first version with the contrib module. v9
and v10 tried small changes to the null-hook and attach paths, but
the changes were too small to measure. Everything they found is
folded into these five patches.

0001 and 0002 are the pair posted as v7, unchanged. 0003 is a new
test module for the hook contract. 0004 and 0005 are the collector,
contrib/pg_wait_event_tracing, statistics level and trace level.

Below: what changed since v7, one bare-metal run of numbers, what
v11 does about the review comments, what is left out on purpose,
and where the evidence is.

What changed since v7
======================

The collector is now contrib/pg_wait_event_tracing. Patch 0004 adds
the statistics level. Patch 0005 adds the trace level. The defects
found during the v6 review are fixed. Patch 0003 adds a new test
module for the hook contract.

The hook has two states: no consumer installed, or a consumer
installed. With no consumer, each side of the timed pair is one
branch, marked unlikely(). The work for an installed consumer, the
depth guard and the indirect call, lives in two separate functions,
marked cold, out of the main code path.

The branch hint is needed. GCC's branch predictor assumes a pointer
compared with NULL is not NULL. Without the hint, GCC puts the
consumer's code on the fast path and the no-consumer case on the
slow path, the wrong way round. I checked this with disassembly.
Across seven functions, on x86-64 with GCC 13, the code without the
hint adds 20 to 44 instructions per function over master. With the
hint, and the consumer's code moved out of line, that is 4 to 7
instructions. One function, pgaio_io_perform_synchronously, also had
4 extra stack references without the hint; with the hint, it has 0,
the same as master. In 10 of the 12 call sites checked, the
no-consumer path is a plain fall-through, with no jump at all.

The module now turns its hooks on only when needed. It installs them
the first time a process sets pg_wait_event_tracing.capture to
anything other than off, and never removes them. A process that
never turns capture on costs the same as a process with no collector
loaded.

The last change moves when the collector writes down a finished
wait.

Before this change, the collector did its accounting the moment
LWLockAcquire() returned control to the caller. That is inside the
lock's critical section: the backend already holds a lock other
backends are waiting for. In that moment, the collector read the
clock, found the right slot, and updated the counters. Every backend
waiting for that lock paid for this work, on top of its own wait.

Now, at wait_end, the collector only reads the clock and saves one
record, the event, the duration, and the timestamp, in a slot local
to the backend. The counters are updated later: at the next
wait_start, or at any point where order matters, such as a capture
change, a reset, a release, a process exit, or the backend reading
its own data.

The durations, the values, and the order are the same as before.
What changes is when another backend can see a finished wait (it
waits until the next such point), and that a crash can lose at most
one saved record, the one not yet written when the backend is
killed.

I measured this. On the same server, with the same kit, an earlier
run of this series, before this change, showed about 6.6% less TPS
with capture on than with the module loaded but off, on the
lock-storm workload. With the change, on the same workload, stats
versus module-off is -3.7% [-6.4%, -1.0%] in this run. The finding
and the decision are written up in DECISION-deferred-accounting.md,
which is in the evidence package. I decided to keep this change in
v11.

Measurements
============

Host: a two-socket Intel Xeon server, 32 physical cores per socket,
SMT off, turbo off, Rocky Linux 8, GCC 8.5. Server and pgbench each
pinned to disjoint physical cores of one NUMA node.

Protocol: seven configurations, master, master-aa, control,
hook-null, module-off, stats, trace. The layout control strips the
hook-test and slow-path call back out of the timed pair, leaving
only the volatile store. master-aa is a second, independently built
master run, its own installation: the A/A twin. All seven run
against five workloads, W1 the microbenchmark and W3/W4/W5/W6c
pgbench-driven, 16 repetitions in a randomized complete-block
schedule built from a 7x7 Latin square.

Every contrast gets two estimators, a paired Student t interval and
an exact Wilcoxon signed-rank Hodges-Lehmann interval. A contrast
counts as resolved only when both agree. I compute an A/A floor per
workload. A plateau probe picks the dataset/initdb variant before
the run starts (pinned spread 0.444%, unpinned spread 0.568%). Every
cell also carries its own mode proof, module presence, capture
level, hook-installed state, so a misconfigured cell fails closed
instead of silently contaminating a contrast.

One bare-metal run: 2026-09-23, tag wet-v11-run2, tip e26e6333322.

Overhead against vanilla master, positive means slower. W1 is ns per
timed pair on the already-set latch. The rest is percent of TPS,
paired means over 16 blocks. Intervals follow below:

A/A twin (noise floor) vs vanilla
W1 0.0 W3 +0.9 W4 +0.1 W5 -0.3 W6c -0.1

layout control vs vanilla
W1 -1.9 W3 -1.8 W4 0.0 W5 -1.0 W6c -0.6

hook-null (patch, no module) vs vanilla
W1 -0.2 W3 -2.6 W4 -0.2 W5 -0.6 W6c -0.5

module-off (loaded, capture off) vs vanilla
W1 -0.3 W3 -0.4 W4 -0.1 W5 -0.6 W6c -0.4

stats (capture on) vs vanilla
W1 +36.6 W3 +3.3 W4 -0.1 W5 -0.2 W6c +0.4

trace (capture on) vs vanilla
W1 +38.1 W3 +3.1 W4 +1.0 W5 +0.3 W6c +0.5

The exact contrasts behind that table, with intervals, follow.
Disabled modes first: hook-null versus its layout control, and
module-off (collector loaded, capture off) versus hook-null. Paired
95%:

W1, already-set latch, ns per pair:
hook-null vs control: +1.63 [+1.48, +1.77]
module-off vs hook-null: -0.05 [-0.17, +0.06]

W3, deterministic short ProcArrayLock wait, 8 clients, percent TPS:
A/A floor (master-aa vs vanilla): 2.3
hook-null vs control: +0.8 [-0.4, +2.0]
module-off vs hook-null: -2.2 [-4.7, +0.2]

W4, select-only, 16 clients, percent TPS:
A/A floor (master-aa vs vanilla): 0.51
hook-null vs control: +0.26 [-0.31, +0.83]
module-off vs hook-null: -0.07 [-0.57, +0.43]

W5, TPC-B, 16 clients, percent TPS:
A/A floor (master-aa vs vanilla): 0.29
hook-null vs control: -0.40 [-0.72, -0.07]
module-off vs hook-null: -0.06 [-0.53, +0.41]

W6c, select-only, 32 clients, eviction layout, percent TPS:
A/A floor (master-aa vs vanilla): 0.24
hook-null vs control: -0.07 [-0.50, +0.36]
module-off vs hook-null: -0.10 [-0.48, +0.27]

The deferral touches neither of these paths.

Now the enabled modes, stats versus module-off and trace versus
module-off, where the collector's cost shows. Paired 95%:

W1, ns per pair:
stats vs module-off: +36.85 [+36.75, +36.94]
trace vs module-off: +38.35 [+38.26, +38.44]

W3, percent TPS:
stats vs module-off: -3.7 [-6.4, -1.0]
trace vs module-off: -3.5 [-5.7, -1.2]
lock-wait rate: 406k/s, about 5 per transaction

W4, percent TPS:
stats vs module-off: -0.05 [-0.58, +0.47]
trace vs module-off: -1.1 [-1.7, -0.6]

W5, percent TPS:
stats vs module-off: -0.31 [-0.64, +0.02]
trace vs module-off: -0.88 [-1.31, -0.44]

W6c, percent TPS:
stats vs module-off: -0.79 [-1.18, -0.40]
trace vs module-off: -0.98 [-1.31, -0.65]

The W6c persistent-backend crossover: 16 sessions, patched
installation only, no build pairing, capture toggled by reload
within each session. stats vs off -0.54 [-0.66, -0.41], trace vs off
-1.03 [-1.16, -0.90], off versus off placebo (both sides
uninstrumented, a null check) -0.14 [-0.33, +0.05]. The suitability
gate passed.

W3 is the worst case here, both for stats versus module-off and for
trace versus module-off.

What v11 does about the review comments
========================================

Thank you to Andrey, Andres and Michael for their comments on this
and the earlier threads. Below is what v11 does about each point.
Whether this is enough is for the reviewers to judge.

1. Andrey asked, on 2026-09-05, for five configurations: master,
compiled in but off, a null hook, the module preloaded with
capture off, and capture on. There is no compile-time switch in
v11: no configure flag, the hook is always compiled in.
hook-null is the closest match to the compiled-in-but-off
configuration. I also added a layout control and a second,
independent master build (master-aa), both in the table above.

2. Andrey also asked about extra instructions or register spills at
the hot call sites. I looked at the x86-64 GCC 13 disassembly of
seven functions. Without the branch hint, the code adds 20 to 44
instructions per function over master, and one function,
pgaio_io_perform_synchronously, gets 4 extra stack references.
With the hint, and the consumer's code moved out of line, that is
4 to 7 instructions, and the stack references go back to
master's count. The kit repeats the same disassembly on the
benchmark host, with GCC 8.5, and it is in the evidence package.

3. Andrey pointed at the already-set-latch path, where
WaitEventSetWait reports the wait before it checks the latch.
W1's latch_set test is that path. hook-null minus control there
is +1.63 ns [+1.48, +1.77].

4. Andrey set out the hook contract: only preallocated backend-local
state, no waits, no allocations, no locks, no errors, and a
recursion guard in core. That contract is written in 0001's
header comment. The depth guard enforces it in core, and 0003's
tests cover the chaining order, the depth guard, a NULL hook, and
the error path.

5. Andrey asked how this would sit next to EXPLAIN WAITS. The
chaining order is fixed: the previous begin hook runs before a
new consumer's own begin, and the new consumer's own end runs
before the previous end. 0003 tests this with two consumers, in
both installation orders. Thank you for pointing at Ilmar's
thread [0]. I am happy to align on one API with that thread.

6. Andrey asked about the memory cost of the earlier design. In
v11, one small control entry sits in shared memory per possible
ProcNumber, 56 bytes on x86-64, all the time. The larger payload,
about 200 KiB (212,664 bytes at the default 192 LWLock tranches),
is allocated only for a backend that turns capture on, at a safe
point, and released when capture turns off or the backend exits.

7. Andrey asked where this should live. It is a contrib module, so
it ships with core and is available on managed services the same
way pg_stat_statements is. There is no configure-time flag.

8. Andres wrote [1] that he was against adding even a single cycle
to wait events. pgstat_report_wait_start() and
pgstat_report_wait_end(), the plain pair, are byte-identical to
master in every build here. Two of the W1 rows, report_only and
usleep0, use only that plain pair. Across every configuration, in
this run, they show a 0.00 ns difference from master.

9. Andres also wrote [2] that a hook like this should be opt-in per
call site, should count encounters as well as duration, and that
each converted site should be justified. The timed pair is that
opt-in shape. The collector records count, total, max, and a
log2 histogram per event. Each site pays the same one predicted
branch: measured alone, that is +1.63 ns per pair, and it does
not show up as a real difference against the layout control on
any pgbench workload here.

10. Andres also raised sampling as an alternative. As Andrey said in
the same thread, sampling (EXPLAIN WAITS) and exact per-wait
timing answer different questions, and both can use the same
hook. Nothing here rules out a sampling collector.

11. Michael raised [3] that new wait events could get harder to add.
A new site that uses the plain pair is unaffected. A site that
wants timing uses the timed pair, and pays one branch when no
consumer is installed. This is written up in xfunc.sgml.

What is left out of v11 on purpose
==================================

Three things stay out. All were noted since v8, and I have not
reconsidered them here.

- No end-of-message marker for the pipelined extended protocol.
Nothing in postgres.c fires when one queued Bind/Execute ends
and the next begins, so a queued statement's boundary is
inferred from the next statement's own QueryStart.
- No trace rings for a server-side process before a reload. The
always-on reserved region covers per-class statistics only,
about 10 MiB at default settings. A ring per such process would
be roughly 4 MB each. That is why crash-recovery tracing
specifically is still a gap.
- No C-level reader API. SQL functions are the only supported
interface. This also closes v6 defect 7.

The deferral changes two things, each bounded.

Visibility latency: a completed wait becomes visible to a reader at
the next flush point, not immediately. In practice that is
microseconds away, and at the latest the end of the current
statement, because going idle is itself a timed wait. For a
server-side process that blocks without a timeout, such as a
caught-up standby's startup process waiting for WAL, the most recent
completed wait becomes visible only when that process's next wait
begins. This is documented in the module page.

Crash loss: if a backend is killed, not exited, between a wait
ending and the next flush, that one pending record is lost.
Statistics are released at exit regardless, so this only matters for
a post-mortem trace ring. Only the crashed backend's single most
recent wait can be missing. If someone has a consumer in mind for
which this visibility rule is a problem, I would like to hear about
it.

Where the evidence is
======================

The tip I measured, e26e6333322, and the tip I posted,
382f87e07f8, differ only in two TAP tests and one documentation
sentence. No C code changed between them.

The run is published, sanitized, on branch v11-evidence-20260923
(raw archives, matrix and crossover analysis, host check,
disassembly, early A/A gate log):

https://github.com/DmitryNFomin/postgres/tree/v11-evidence-20260923

The kit itself (scripts, workloads, the analyzer, the runbook) is on
branch v11-notes:

https://github.com/DmitryNFomin/postgres/tree/v11-notes

The raw archive, the analysis, the disassembly, the kit, and the
patches are also together in one downloadable package:

https://github.com/DmitryNFomin/postgres/releases/tag/v11-evidence-20260924
(wait-event-v11-evidence-20260924.tar.gz, 3,736,151 bytes, SHA-256
fe46d50a67d01583bc8b92e333366a1b40450fa5add4b6c04ec6b58004a5c667)

The five patches are also up as a pull request:

https://github.com/DmitryNFomin/postgres/pull/2

Every number above comes from the raw archive, through the kit's own
analyzer.

Attachments
===========

v11-0001 begin/end hook pair, wait_event.h/.c
v11-0002 call-site conversion to the timed pair
v11-0003 test_wait_hook, the hook-contract test module
v11-0004 pg_wait_event_tracing, statistics level
v11-0005 pg_wait_event_tracing, trace level

Nothing else attached, for cfbot.

[0] https://www.postgresql.org/message-id/cover.1778280923.git.tanswis42@gmail.com
[1] https://www.postgresql.org/message-id/uah2s5tppv3onn7bsf2uelyexfrxwrmye6qqyrbbsjepxny7l5@guymflaarnsr
[2] https://www.postgresql.org/message-id/sofkrmi3skg3ekc3y23uwxscbviy5lcbukincoyauypg4ylfdg@6lwzhi6uagc7
[3] https://www.postgresql.org/message-id/alQ60-N2n8NzVw5g@paquier.xyz

Regards,
Dmitry Fomin