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

Hi hackers,

As promised in the cover letter, here are the overhead numbers and the
methodology behind them.

Hardware and setup
------------------

Dedicated Hetzner CCX43 (16 dedicated AMD EPYC Milan vCPUs, 64 GB RAM),
Linux, gcc 13, -O2 (meson debugoptimized), no other load. Four builds:

BASELINE unpatched master
WET/off patched, --enable-wait-event-timing, wait_event_capture=off
WET/stats same build, wait_event_capture=stats
WET/trace same build, wait_event_capture=trace (4 MB rings)

pgbench scale 100, shared_buffers = 4 GB unless noted, 16 clients /
8 threads / 30 s, 5 runs per cell, means reported. Run-to-run spread
on this machine is roughly +/- 1-2 %, so single-digit deltas below
should be read against that floor.

The numbers were taken on the pre-split development tip of this work.
The v1 series is a reorganization of that same code into reviewable
pieces; the recording hot paths are unchanged. The off- and stats-mode
results were additionally re-validated on the series itself (same
machine, same protocol) with matching results.

1. pgbench -S (read-only)
-------------------------

mean TPS vs BASELINE
BASELINE 164,859 --
WET/off 166,840 +1.20 %
WET/stats 164,126 -0.44 %
WET/trace 165,687 +0.50 %

All three modes are within run-to-run noise of vanilla. (Yes, "off"
came out faster than baseline here -- see the layout note below for
why we do not read anything into that.)

2. pgbench TPC-B
----------------

mean TPS vs BASELINE
BASELINE 17,569 --
WET/off 17,487 -0.46 %
WET/stats 17,240 -1.87 %
WET/trace 17,314 -1.45 %

3. Wait-saturated worst case (eviction stress)
----------------------------------------------

To probe the per-transition cost directly, shared_buffers = 32 MB
against a ~1.5 GB working set forces ~98 % buffer misses; every miss
produces a BufferIO/DataFileRead wait. This drives the instrumented
path at the highest rate we could construct:

scenario mode TPS vs off
W1 -S, 16 clients off 116,487 --
stats 116,625 +0.1 %
trace 114,844 -1.4 %
W2 TPC-B, 16 clients off 16,813 --
stats 16,766 -0.3 %
trace 16,698 -0.7 %
W3 -S, 32 clients (2x oversub) off 162,845 --
stats 158,880 -2.4 %
trace 159,141 -2.3 %
W4 hot-row UPDATE, 32 clients off 8,138 --
stats 7,772 -4.5 %
trace 7,814 -4.0 %

W4 is the deliberate pathological case: every transaction contends on
the same row, so each transaction goes through many lock-wait
transitions. The ~4.5 % there is the honest ceiling we could produce
for the recording cost; it is bounded and proportional to the
wait-transition rate, which is exactly the workload where you would
want this data. Typical stats-mode cost elsewhere is <= ~0.5 % vs off.

A sample of what trace mode captured under W1, as a sanity check that
the instrumented path was actually exercised:

IO / DataFileRead (dominant), IO / WalWrite, IO / AioIoCompletion,
Activity / BgwriterMain, Activity / WalWriterMain,
LWLock / WaitEventTraceDSA

4. A methodological caution: binary layout
------------------------------------------

While validating the off-mode gate we hit an apparent -3 % TPC-B
regression that survived re-runs within one session -- and then
reversed sign in a fresh session with the identical binary (-3.00 %,
then +0.18 %). A control build with the gate #ifdef'd out entirely
(same patch, no live code in the hot path) measured -2.39 %, while
re-adding the gate measured +2.64 % -- a slowdown from removing an
instruction and a speedup from adding one, which is impossible as an
instruction cost. This is the well-known code-layout effect
(Mytkowicz et al., "Producing Wrong Data Without Doing Anything
Obviously Wrong", ASPLOS 2009): TPC-B on this machine is sensitive to
where unrelated code lands in the binary at the +/- 2-3 % level.

Consequently: (a) we report off-mode as "within noise" rather than
quoting a signed per-mille number, and (b) the earlier unlikely()
annotation on the gate was dropped after objdump showed gcc 13 -O2
emits byte-identical code with and without it (the measured "effect"
of the annotation was pure layout). The gate itself is one global
load and a predicted branch; arithmetic puts it around 10^-5 of a
TPC-B transaction, far below anything measurable here.

5. Stability under the same workloads
-------------------------------------

Not performance, but run on the same box and worth one paragraph: the
full check-world passes on the instrumented and stub builds; an
ASAN-instrumented build ran the pgbench matrix, a connect storm, a
SELECT FOR UPDATE pile-up and a pg_terminate_backend storm with no
findings; stress runs covered immediate-shutdown recovery, rapid mode
flips under load, 150 concurrent cross-backend trace readers against a
live writer, 8 KB and 32 MB rings, an orphan-sweep of 50 short-lived
backends, and a primary + hot-standby pair with trace enabled on both.
No crashes or sanitizer reports in any of it.

Happy to re-run any of this with different parameters, or publish the
driver scripts if that is useful.

Regards,
Dmitry Fomin

Show quoted text

On Fri, Jul 3, 2026 at 10:22 PM Dmitry Fomin <fomin.list@gmail.com> wrote:

Hi hackers,

This series adds opt-in instrumentation that captures the duration of
every wait event reported through pgstat_report_wait_start()/_end(),
behind a configure-time flag (--enable-wait-event-timing) and a runtime
GUC (wait_event_capture = off | stats | trace, default off).

PostgreSQL exposes a rich taxonomy of wait events in pg_stat_activity,
but only as instantaneous snapshots: there is no in-core way to ask
"how long do my backends actually spend in each wait?", or "what was
the wait sequence of this session's last N events?". External tools
either sample at coarse resolution (pg_wait_sampling, default 10 ms) or
pay ~200-300 ns per transition via hardware watchpoints.

This is a reworked submission of an earlier 8k-line single patch,
following Andrey Borodin's advice to split it into independently
committable pieces with the DSA machinery deferred. The series has
three groups; each patch builds and passes check-world on its own:

Group 1 -- stats level (patches 1-4, committable on their own):

0001 adds the configure flag and the wait_event_capture GUC; pure
scaffolding, no behavior.
0002 records per-(backend, event) statistics -- count, total/max
duration, and a 32-bucket log2 histogram -- in eagerly-allocated
shared memory, with a single load+branch gate in the inline
wait_start/wait_end fast path and the recording bodies
out-of-line. Exposed via pg_stat_wait_event_timing. No DSA.
0003 exposes the overflow counters and adds reset functions (own
backend synchronous; cross-backend via a lock-free
request/response on an atomic generation counter).
0004 enables the flag on one CI task, so both the instrumented and
the stub build paths are exercised on every run.

Group 2 -- storage refactor:

0005 converts the per-backend array from eager shared memory to a
lazily-created DSA, so a build with the feature compiled in but
never enabled pays no per-backend memory. Pure refactor: the
SQL surface is unchanged and 0002/0003's tests pass as-is. This
is the riskiest patch -- it adds the lazy-attach guards
(critical sections, LWLock wait queues, re-entrancy) and the
proc_exit teardown gate -- which is exactly why it is isolated.

Group 3 -- trace level:

0006 adds wait_event_capture = trace: a per-session DSA ring buffer
of individual waits, readable from the owning session and
cross-backend (including post-mortem reads of rings whose
backend has exited). Cross-backend reads are protected by a
position-encoded identity seqlock; a TAP test drives an
injection point inside the writer to prove it rejects
stale-cycle reads that a parity-only seqlock would accept.
0007 interleaves query-attribution markers (executor and protocol
boundaries) into the ring, so a reader can tell which query
each wait belongs to.

Off-mode overhead: pgbench -S and TPC-B on a dedicated 16-vCPU box
show the compiled-in-but-off configuration within run-to-run noise of
an unpatched build (the inline gate is one global load and a predicted
branch; an earlier unlikely() annotation was dropped after measurement
showed byte-identical codegen without it). stats mode costs <= ~0.5%
vs off across read-only, TPC-B, and a wait-saturated
32MB-shared_buffers workload. I will post the full numbers and
methodology in a follow-up message.

Open questions:

* Whether the configure flag should eventually be dropped in favor of
always-compiled (the off-mode cost is one predicted branch).
* Defaults worth litigating: 32 histogram buckets,
wait_event_timing_max_tranches = 192, and
wait_event_trace_ring_size = 4MB.
* The trace level's orphan-ring retention tradeoff (post-mortem reads
vs bounded memory), documented on WaitEventTraceControl.

The patches deliberately contain no catversion bump; one is needed at
commit time for 0002, 0003 and 0006.

Thanks to Andrey Borodin for the first review of the earlier
single-patch version -- his advice to break it into independently
committable pieces shaped this series -- and to Nikolay Samokhvalov and
Kirk Wolak for discussion and independent testing of the overhead and
the orphaned-ring lifecycle.

Regards,
Dmitry Fomin

Dmitry Fomin (7):
wait_event_timing: add --enable-wait-event-timing flag and
wait_event_capture GUC
wait_event_timing: record per-backend wait event statistics (stats level)
wait_event_timing: expose overflow counters and add reset functions
ci: build one task with --enable-wait-event-timing
wait_event_timing: allocate the per-backend array lazily in DSA
wait_event_timing: add trace level with a per-session ring buffer
wait_event_timing: add query-attribution markers to the trace ring

.github/workflows/pg-ci.yml | 7 +
configure | 32 +
configure.ac | 8 +
doc/src/sgml/config.sgml | 106 +
doc/src/sgml/monitoring.sgml | 783 +++++
meson.build | 1 +
meson_options.txt | 3 +
src/backend/catalog/system_views.sql | 103 +
src/backend/executor/execMain.c | 5 +
src/backend/postmaster/auxprocess.c | 11 +
src/backend/storage/lmgr/proc.c | 5 +
src/backend/tcop/postgres.c | 39 +
src/backend/utils/.gitignore | 1 +
src/backend/utils/Makefile | 9 +-
src/backend/utils/activity/Makefile | 4 +-
src/backend/utils/activity/backend_status.c | 13 +
.../activity/generate-wait_event_types.pl | 179 +
src/backend/utils/activity/meson.build | 1 +
src/backend/utils/activity/wait_event.c | 3 +-
.../utils/activity/wait_event_names.txt | 2 +
.../utils/activity/wait_event_timing.c | 3111 +++++++++++++++++
src/backend/utils/init/postinit.c | 11 +
src/backend/utils/misc/guc_parameters.dat | 29 +
src/backend/utils/misc/guc_tables.c | 1 +
src/backend/utils/misc/postgresql.conf.sample | 5 +
src/include/catalog/pg_proc.dat | 59 +
src/include/pg_config.h.in | 3 +
src/include/storage/lwlocklist.h | 2 +
src/include/storage/subsystemlist.h | 2 +
src/include/utils/.gitignore | 1 +
src/include/utils/guc.h | 1 +
src/include/utils/guc_hooks.h | 3 +
src/include/utils/meson.build | 4 +-
src/include/utils/wait_classes.h | 9 +
src/include/utils/wait_event.h | 49 +
src/include/utils/wait_event_timing.h | 374 ++
src/test/modules/test_misc/meson.build | 1 +
.../t/015_wait_event_trace_seqlock.pl | 122 +
src/test/regress/expected/rules.out | 30 +
.../regress/expected/wait_event_timing.out | 188 +
.../regress/expected/wait_event_timing_1.out | 181 +
src/test/regress/parallel_schedule | 4 +
src/test/regress/sql/wait_event_timing.sql | 113 +
src/tools/pgindent/typedefs.list | 12 +
44 files changed, 5621 insertions(+), 9 deletions(-)
create mode 100644 src/backend/utils/activity/wait_event_timing.c
create mode 100644 src/include/utils/wait_event_timing.h
create mode 100644 src/test/modules/test_misc/t/015_wait_event_trace_seqlock.pl
create mode 100644 src/test/regress/expected/wait_event_timing.out
create mode 100644 src/test/regress/expected/wait_event_timing_1.out
create mode 100644 src/test/regress/sql/wait_event_timing.sql

Hi hackers,

This series adds opt-in instrumentation that captures the duration of
every wait event reported through pgstat_report_wait_start()/_end(),
behind a configure-time flag (--enable-wait-event-timing) and a runtime
GUC (wait_event_capture = off | stats | trace, default off).

PostgreSQL exposes a rich taxonomy of wait events in pg_stat_activity,
but only as instantaneous snapshots: there is no in-core way to ask
"how long do my backends actually spend in each wait?", or "what was
the wait sequence of this session's last N events?". External tools
either sample at coarse resolution (pg_wait_sampling, default 10 ms) or
pay ~200-300 ns per transition via hardware watchpoints.

This is a reworked submission of an earlier 8k-line single patch,
following Andrey Borodin's advice to split it into independently
committable pieces with the DSA machinery deferred. The series has
three groups; each patch builds and passes check-world on its own:

Group 1 -- stats level (patches 1-4, committable on their own):

0001 adds the configure flag and the wait_event_capture GUC; pure
scaffolding, no behavior.
0002 records per-(backend, event) statistics -- count, total/max
duration, and a 32-bucket log2 histogram -- in eagerly-allocated
shared memory, with a single load+branch gate in the inline
wait_start/wait_end fast path and the recording bodies
out-of-line. Exposed via pg_stat_wait_event_timing. No DSA.
0003 exposes the overflow counters and adds reset functions (own
backend synchronous; cross-backend via a lock-free
request/response on an atomic generation counter).
0004 enables the flag on one CI task, so both the instrumented and
the stub build paths are exercised on every run.

Group 2 -- storage refactor:

0005 converts the per-backend array from eager shared memory to a
lazily-created DSA, so a build with the feature compiled in but
never enabled pays no per-backend memory. Pure refactor: the
SQL surface is unchanged and 0002/0003's tests pass as-is. This
is the riskiest patch -- it adds the lazy-attach guards
(critical sections, LWLock wait queues, re-entrancy) and the
proc_exit teardown gate -- which is exactly why it is isolated.

Group 3 -- trace level:

0006 adds wait_event_capture = trace: a per-session DSA ring buffer
of individual waits, readable from the owning session and
cross-backend (including post-mortem reads of rings whose
backend has exited). Cross-backend reads are protected by a
position-encoded identity seqlock; a TAP test drives an
injection point inside the writer to prove it rejects
stale-cycle reads that a parity-only seqlock would accept.
0007 interleaves query-attribution markers (executor and protocol
boundaries) into the ring, so a reader can tell which query
each wait belongs to.

Off-mode overhead: pgbench -S and TPC-B on a dedicated 16-vCPU box
show the compiled-in-but-off configuration within run-to-run noise of
an unpatched build (the inline gate is one global load and a predicted
branch; an earlier unlikely() annotation was dropped after measurement
showed byte-identical codegen without it). stats mode costs <= ~0.5%
vs off across read-only, TPC-B, and a wait-saturated
32MB-shared_buffers workload. I will post the full numbers and
methodology in a follow-up message.

Open questions:

* Whether the configure flag should eventually be dropped in favor of
always-compiled (the off-mode cost is one predicted branch).
* Defaults worth litigating: 32 histogram buckets,
wait_event_timing_max_tranches = 192, and
wait_event_trace_ring_size = 4MB.
* The trace level's orphan-ring retention tradeoff (post-mortem reads
vs bounded memory), documented on WaitEventTraceControl.

The patches deliberately contain no catversion bump; one is needed at
commit time for 0002, 0003 and 0006.

Changes in v2 (both found by cfbot on day one -- thanks, cfbot):

* Fixed a Windows/MSVC build failure (C2370): the ShmemCallbacks
registry symbols were redeclared with PGDLLIMPORT in
wait_event_timing.h, clashing with the plain extern declarations
that storage/subsystems.h generates for every registry entry. The
header declarations are gone; the defining file now includes
storage/subsystems.h like the other shmem subsystems.

* Fixed the CompilerWarnings task: the generated
wait_event_timing_data.h is a single-inclusion data header (its
arrays are sized by macros from wait_event_types.h), so it is now
excluded from headerscheck, next to nodetags.h and friends.

No functional changes.

Thanks to Andrey Borodin for the first review of the earlier
single-patch version -- his advice to break it into independently
committable pieces shaped this series -- and to Nikolay Samokhvalov and
Kirk Wolak for discussion and independent testing of the overhead and
the orphaned-ring lifecycle.

Regards,
Dmitry Fomin

Dmitry Fomin (7):
wait_event_timing: add --enable-wait-event-timing flag and
wait_event_capture GUC
wait_event_timing: record per-backend wait event statistics (stats
level)
wait_event_timing: expose overflow counters and add reset functions
ci: build one task with --enable-wait-event-timing
wait_event_timing: allocate the per-backend array lazily in DSA
wait_event_timing: add trace level with a per-session ring buffer
wait_event_timing: add query-attribution markers to the trace ring

.github/workflows/pg-ci.yml | 7 +
configure | 32 +
configure.ac | 8 +
doc/src/sgml/config.sgml | 106 +
doc/src/sgml/monitoring.sgml | 783 +++++
meson.build | 1 +
meson_options.txt | 3 +
src/backend/catalog/system_views.sql | 103 +
src/backend/executor/execMain.c | 5 +
src/backend/postmaster/auxprocess.c | 11 +
src/backend/storage/lmgr/proc.c | 5 +
src/backend/tcop/postgres.c | 39 +
src/backend/utils/.gitignore | 1 +
src/backend/utils/Makefile | 9 +-
src/backend/utils/activity/Makefile | 4 +-
src/backend/utils/activity/backend_status.c | 13 +
.../activity/generate-wait_event_types.pl | 179 +
src/backend/utils/activity/meson.build | 1 +
src/backend/utils/activity/wait_event.c | 3 +-
.../utils/activity/wait_event_names.txt | 2 +
.../utils/activity/wait_event_timing.c | 3112 +++++++++++++++++
src/backend/utils/init/postinit.c | 11 +
src/backend/utils/misc/guc_parameters.dat | 29 +
src/backend/utils/misc/guc_tables.c | 1 +
src/backend/utils/misc/postgresql.conf.sample | 5 +
src/include/catalog/pg_proc.dat | 59 +
src/include/pg_config.h.in | 3 +
src/include/storage/lwlocklist.h | 2 +
src/include/storage/subsystemlist.h | 2 +
src/include/utils/.gitignore | 1 +
src/include/utils/guc.h | 1 +
src/include/utils/guc_hooks.h | 3 +
src/include/utils/meson.build | 4 +-
src/include/utils/wait_classes.h | 9 +
src/include/utils/wait_event.h | 49 +
src/include/utils/wait_event_timing.h | 360 ++
src/test/modules/test_misc/meson.build | 1 +
.../t/015_wait_event_trace_seqlock.pl | 122 +
src/test/regress/expected/rules.out | 30 +
.../regress/expected/wait_event_timing.out | 188 +
.../regress/expected/wait_event_timing_1.out | 181 +
src/test/regress/parallel_schedule | 4 +
src/test/regress/sql/wait_event_timing.sql | 113 +
src/tools/pginclude/headerscheck | 2 +
src/tools/pgindent/typedefs.list | 12 +
45 files changed, 5610 insertions(+), 9 deletions(-)
create mode 100644 src/backend/utils/activity/wait_event_timing.c
create mode 100644 src/include/utils/wait_event_timing.h
create mode 100644 src/test/modules/test_misc/t/015_wait_event_trace_seqlock.pl
create mode 100644 src/test/regress/expected/wait_event_timing.out
create mode 100644 src/test/regress/expected/wait_event_timing_1.out
create mode 100644 src/test/regress/sql/wait_event_timing.sql

Hi hackers,

Hi hackers,

v3 is v2 rebased over current master (5f14f82280d); cfbot flagged the
set as needing a rebase after typedefs.list drifted. No code changes.

Regards,
Dmitry Fomin

Dmitry Fomin (7):
wait_event_timing: add --enable-wait-event-timing flag and
wait_event_capture GUC
wait_event_timing: record per-backend wait event statistics (stats
level)
wait_event_timing: expose overflow counters and add reset functions
ci: build one task with --enable-wait-event-timing
wait_event_timing: allocate the per-backend array lazily in DSA
wait_event_timing: add trace level with a per-session ring buffer
wait_event_timing: add query-attribution markers to the trace ring

.github/workflows/pg-ci.yml | 7 +
configure | 32 +
configure.ac | 8 +
doc/src/sgml/config.sgml | 106 +
doc/src/sgml/monitoring.sgml | 783 +++++
meson.build | 1 +
meson_options.txt | 3 +
src/backend/catalog/system_views.sql | 103 +
src/backend/executor/execMain.c | 5 +
src/backend/postmaster/auxprocess.c | 11 +
src/backend/storage/lmgr/proc.c | 5 +
src/backend/tcop/postgres.c | 39 +
src/backend/utils/.gitignore | 1 +
src/backend/utils/Makefile | 9 +-
src/backend/utils/activity/Makefile | 4 +-
src/backend/utils/activity/backend_status.c | 13 +
.../activity/generate-wait_event_types.pl | 179 +
src/backend/utils/activity/meson.build | 1 +
src/backend/utils/activity/wait_event.c | 3 +-
.../utils/activity/wait_event_names.txt | 2 +
.../utils/activity/wait_event_timing.c | 3112 +++++++++++++++++
src/backend/utils/init/postinit.c | 11 +
src/backend/utils/misc/guc_parameters.dat | 29 +
src/backend/utils/misc/guc_tables.c | 1 +
src/backend/utils/misc/postgresql.conf.sample | 5 +
src/include/catalog/pg_proc.dat | 59 +
src/include/pg_config.h.in | 3 +
src/include/storage/lwlocklist.h | 2 +
src/include/storage/subsystemlist.h | 2 +
src/include/utils/.gitignore | 1 +
src/include/utils/guc.h | 1 +
src/include/utils/guc_hooks.h | 3 +
src/include/utils/meson.build | 4 +-
src/include/utils/wait_classes.h | 9 +
src/include/utils/wait_event.h | 49 +
src/include/utils/wait_event_timing.h | 360 ++
src/test/modules/test_misc/meson.build | 1 +
.../t/015_wait_event_trace_seqlock.pl | 122 +
src/test/regress/expected/rules.out | 30 +
.../regress/expected/wait_event_timing.out | 188 +
.../regress/expected/wait_event_timing_1.out | 181 +
src/test/regress/parallel_schedule | 4 +
src/test/regress/sql/wait_event_timing.sql | 113 +
src/tools/pginclude/headerscheck | 2 +
src/tools/pgindent/typedefs.list | 12 +
45 files changed, 5610 insertions(+), 9 deletions(-)
create mode 100644 src/backend/utils/activity/wait_event_timing.c
create mode 100644 src/include/utils/wait_event_timing.h
create mode 100644 src/test/modules/test_misc/t/015_wait_event_trace_seqlock.pl
create mode 100644 src/test/regress/expected/wait_event_timing.out
create mode 100644 src/test/regress/expected/wait_event_timing_1.out
create mode 100644 src/test/regress/sql/wait_event_timing.sql

--
Dmitry

Hi,

On 11/07/2026 20:42, Dmitry Fomin wrote:

Hi hackers,

Hi hackers,

v3 is v2 rebased over current master (5f14f82280d); cfbot flagged the
set as needing a rebase after typedefs.list drifted. No code changes.

Just a quick note to say I'm very interested in these patches. I've
tried them and I'm quite enthusiastic with it. For example, it's nice to
see wait events wrt the checkpointer:

select wait_event_type, wait_event, calls, total_time_ms
from pg_stat_wait_event_timing
where pid=984861
order by total_time_ms desc;

┌─────────────────┬──────────────────────┬───────┬───────────────┐
│ wait_event_type │ wait_event │ calls │ total_time_ms │
├─────────────────┼──────────────────────┼───────┼───────────────┤
│ Activity │ CheckpointerMain │ 3 │ 300109.767515 │
│ Timeout │ CheckpointWriteDelay │ 1056 │ 105928.938476 │
│ IO │ DataFileWrite │ 1751 │ 61.356984 │
│ IO │ DataFileFlush │ 77 │ 7.395531 │
│ IO │ SlruWrite │ 3 │ 0.095615 │
└─────────────────┴──────────────────────┴───────┴───────────────┘
(5 rows)

That's definitely something I was waiting for.

Anyway, it was just a quick look. The patches apply to HEAD, they
compile, and it was easy to do some quick tests. I'll try to find some
time to work more on this, but I'd be very interested to see this
landing in v20.

Kudos for the great work, Dmitry!

Regards.

Regards,
Dmitry Fomin

Dmitry Fomin (7):
wait_event_timing: add --enable-wait-event-timing flag and
wait_event_capture GUC
wait_event_timing: record per-backend wait event statistics (stats
level)
wait_event_timing: expose overflow counters and add reset functions
ci: build one task with --enable-wait-event-timing
wait_event_timing: allocate the per-backend array lazily in DSA
wait_event_timing: add trace level with a per-session ring buffer
wait_event_timing: add query-attribution markers to the trace ring

.github/workflows/pg-ci.yml | 7 +
configure | 32 +
configure.ac | 8 +
doc/src/sgml/config.sgml | 106 +
doc/src/sgml/monitoring.sgml | 783 +++++
meson.build | 1 +
meson_options.txt | 3 +
src/backend/catalog/system_views.sql | 103 +
src/backend/executor/execMain.c | 5 +
src/backend/postmaster/auxprocess.c | 11 +
src/backend/storage/lmgr/proc.c | 5 +
src/backend/tcop/postgres.c | 39 +
src/backend/utils/.gitignore | 1 +
src/backend/utils/Makefile | 9 +-
src/backend/utils/activity/Makefile | 4 +-
src/backend/utils/activity/backend_status.c | 13 +
.../activity/generate-wait_event_types.pl | 179 +
src/backend/utils/activity/meson.build | 1 +
src/backend/utils/activity/wait_event.c | 3 +-
.../utils/activity/wait_event_names.txt | 2 +
.../utils/activity/wait_event_timing.c | 3112 +++++++++++++++++
src/backend/utils/init/postinit.c | 11 +
src/backend/utils/misc/guc_parameters.dat | 29 +
src/backend/utils/misc/guc_tables.c | 1 +
src/backend/utils/misc/postgresql.conf.sample | 5 +
src/include/catalog/pg_proc.dat | 59 +
src/include/pg_config.h.in | 3 +
src/include/storage/lwlocklist.h | 2 +
src/include/storage/subsystemlist.h | 2 +
src/include/utils/.gitignore | 1 +
src/include/utils/guc.h | 1 +
src/include/utils/guc_hooks.h | 3 +
src/include/utils/meson.build | 4 +-
src/include/utils/wait_classes.h | 9 +
src/include/utils/wait_event.h | 49 +
src/include/utils/wait_event_timing.h | 360 ++
src/test/modules/test_misc/meson.build | 1 +
.../t/015_wait_event_trace_seqlock.pl | 122 +
src/test/regress/expected/rules.out | 30 +
.../regress/expected/wait_event_timing.out | 188 +
.../regress/expected/wait_event_timing_1.out | 181 +
src/test/regress/parallel_schedule | 4 +
src/test/regress/sql/wait_event_timing.sql | 113 +
src/tools/pginclude/headerscheck | 2 +
src/tools/pgindent/typedefs.list | 12 +
45 files changed, 5610 insertions(+), 9 deletions(-)
create mode 100644 src/backend/utils/activity/wait_event_timing.c
create mode 100644 src/include/utils/wait_event_timing.h
create mode 100644 src/test/modules/test_misc/t/015_wait_event_trace_seqlock.pl
create mode 100644 src/test/regress/expected/wait_event_timing.out
create mode 100644 src/test/regress/expected/wait_event_timing_1.out
create mode 100644 src/test/regress/sql/wait_event_timing.sql

--
Dmitry

--
Guillaume Lelarge
Consultant
https://dalibo.com

On Fri, Jul 03, 2026 at 10:22:58PM +0200, Dmitry Fomin wrote:

PostgreSQL exposes a rich taxonomy of wait events in pg_stat_activity,
but only as instantaneous snapshots: there is no in-core way to ask
"how long do my backends actually spend in each wait?", or "what was
the wait sequence of this session's last N events?". External tools
either sample at coarse resolution (pg_wait_sampling, default 10 ms) or
pay ~200-300 ns per transition via hardware watchpoints.

This is a reworked submission of an earlier 8k-line single patch,
following Andrey Borodin's advice to split it into independently
committable pieces with the DSA machinery deferred. The series has
three groups; each patch builds and passes check-world on its own:

Please also see this thread, particularly the second message (posted
one year + 4 days ago):
/messages/by-id/aGKSzFlpQWSh/+2w@ip-10-97-1-34.eu-west-3.compute.internal
/messages/by-id/xuynb44ql3hhggvqtme7axbliww7gwuy6pbaohxc4ngu3ynbsi@rvvpjxf55aia

The core point that seems to matter most is in v1-0002, where the
patch decides to make what is now a cheap 32-bit volatile manipulation
into an optional compilation-based expensive operation. I don't want
to sound negative here, but I'd recommend to re-read the previous
thread. This kind of change could lead us to make the addition of
more wait events harder to think about, especially if these are in
deeper parts of the backend stack.
--
Michael

On Mon, Jul 13, 2026 at 4:09 AM Michael Paquier <michael@paquier.xyz> wrote:

The core point that seems to matter most is in v1-0002, where the
patch decides to make what is now a cheap 32-bit volatile manipulation
into an optional compilation-based expensive operation. I don't want
to sound negative here, but I'd recommend to re-read the previous
thread. This kind of change could lead us to make the addition of
more wait events harder to think about, especially if these are in
deeper parts of the backend stack.

Thanks for the pointers. I have read that thread end to end, and
I should have cited it in the cover letter. Having done so, I think
the cover letter also failed to distinguish two different forms of
opt-in, so let me be precise about what this series does and where it
differs from what Andres described there.

The series provides operational opt-in:

- Built without --enable-wait-event-timing (the default), the timing
condition is absent from the preprocessed inline wait_start/end
path; the stores are as today.

- Built with it, at wait_event_capture = off (the default), the
recording bodies are out of line and each boundary gains a load
of the process-local wait_event_capture value, a test, and a
not-taken branch. For one call site I examined (FileReadV around
preadv(), gcc 13 -O2, x86-64; other compilers and sites will
differ in detail):

mov 0x0(%rbp),%rax # my_wait_event_info
mov %ecx,(%rax) # *ptr = wait_event_info (as today)
mov (%rbx),%eax # wait_event_capture (new)
test %eax,%eax # (new)
jne <tail> # not taken at off (new)
... preadv() ...
mov (%rbx),%edi # wait_event_capture (new)
test %edi,%edi # (new)
jne <tail> # not taken at off (new)
mov 0x0(%rbp),%rax
movl $0x0,(%rax) # *ptr = 0 (as today)

with the calls placed at the tail of the function, reached only
when capture is enabled.

- When capture is enabled for a backend, the path is intentionally
more expensive: stats takes two timestamps per completed wait and
updates count/total/max and a histogram; trace additionally writes
a ring record.

wait_event_capture is PGC_SUSET and per-backend, so this can be
scoped to selected sessions rather than a whole cluster; but within
an enabled backend, v1 times every wait event it reaches. A newly
added wait event automatically becomes a timed event in that
configuration. The generated lookup tables and the non-persistent
per-backend storage mean a new wait event needs no manual table or
stats-file work, including in stable branches -- but they do not
remove that performance coupling, and I understand your "harder to
think about, deeper in the backend stack" as being exactly about it.

Rereading the recording path with that lens also found one thing I
will change in the next version regardless of the API discussion:
the recorder currently raises an ereport(WARNING) when an overflow
counter first increments, and a recorder has no business calling
ereport() from arbitrarily deep call sites. The same information
is already exposed by pg_stat_wait_event_timing_overflow (0003), so
the WARNINGs will go and the view becomes the only signal.

So, having reread Andres's messages: what he described is explicit
per-call-site opt-in -- code changed over to an extended form, each
conversion reasoned about or measured. v1 does not implement that
split; it makes a different tradeoff: whole-taxonomy per-session
capture behind a runtime level. I chose that deliberately, because
it is a large part of the diagnostic value: selective conversion
leaves blind spots in a wait profile and gaps in the ordered trace,
and the profile of an incident you have not predicted is precisely
where blind spots hurt.
Where the series does follow that thread directly is the payload:
"the extended wait events need to count both the number of
encounters as well as the duration, the number of encounters is not
useful on its own" -- each aggregate here is count, total, max and a
32-bucket log2 histogram, and the trace preserves ordering and query
attribution, which is what lets interval snapshots distinguish more
waits from longer waits -- the distinction Robert pointed out bare
counters cannot make.

On measurement, since methodology was the other half of that thread:
I did not attempt to measure the gate with probes or rdtsc pairs.
The numbers in my second message on this thread are end-to-end
TPS; the observed run-to-run spread on that machine was roughly
+/- 1-2%.  They could not distinguish the compiled-in/off
configuration from the unpatched build within that variation, and a
control experiment with the
gate #ifdef'd out showed signed deltas of a few percent that were
consistent with binary-layout effects rather than attributable to
the gate (which is also why the earlier unlikely() annotation was
dropped: identical codegen either way).  For enabled capture, the
four stress scenarios in that message showed stats-vs-off deltas of
+0.1%, -0.3%, -2.4% and -4.5%, the last on a deliberately contended
hot-row workload.  Those are evidence about the existing call sites
on that machine, not a platform-independent ceiling, and they do not
prove that any future call site would be cheap enough -- which I
take to be part of your point.

I also do not see this as replacing the alternatives proposed in
that thread. Sampling (Andres's suggestion) is cheaper for finding
where time goes; the purpose-built lock or SLRU instrumentation
Robert described can answer domain questions this cannot; and there
is real overlap between some I/O waits and
track_io_timing/pg_stat_io, which I can quantify if that is useful.
The per-backend histograms and the ordered trace are aimed at what
those do not provide.

That leaves two API directions I can see:

1. Keep pgstat_report_wait_start()/end() at their current cost and
add an explicit extended form for selected call sites, each
conversion justified or benchmarked -- closest to what Andres
proposed, at the price of incomplete profiles and traces.

2. Retain session-wide capture as an explicitly diagnostic mode,
with an explicit escape hatch for call sites whose frequency
makes the timing overhead unacceptable -- at the price that the
enabled-path cost of future wait events remains a tradeoff to
acknowledge when they are added.

My preference is the second, because session-wide coverage is the
feature I am trying to provide. But I agree the off-state numbers
alone do not settle your concern. Would you consider that
direction viable, or do you regard explicit per-call-site opt-in as
a prerequisite for the next version?

Regards,
Dmitry Fomin

Hi,

v4 attached. Two changes since v3, no design changes:

* Rebased over current master -- cfbot flagged v3 as needing a rebase
after unrelated drift (typedefs.list and neighbours); no conflicts
in the feature code.

* Dropped the two ereport(WARNING) calls from the recording path, as I
said in my previous message I would do in the next version
regardless. A recorder should not call ereport() from arbitrarily
deep wait sites; the over-cap-LWLock-tranche and unknown-class
overflow conditions stay visible through
pg_stat_wait_event_timing_overflow, which is now their only signal.
Confined to patch 0002.

The API-direction question from my previous message still stands, and
I'd value your read on it whenever you have a moment: whether
whole-session capture behind the runtime level -- with an explicit
escape hatch for call sites where the added cost would be unacceptable
-- is an acceptable shape, or whether explicit per-call-site opt-in is
a prerequisite.

The patches still carry no catversion bump; one is needed at commit
time for 0002, 0003 and 0006.

Regards,
Dmitry Fomin

Dmitry Fomin (7):
wait_event_timing: add --enable-wait-event-timing flag and
wait_event_capture GUC
wait_event_timing: record per-backend wait event statistics (stats
level)
wait_event_timing: expose overflow counters and add reset functions
ci: build one task with --enable-wait-event-timing
wait_event_timing: allocate the per-backend array lazily in DSA
wait_event_timing: add trace level with a per-session ring buffer
wait_event_timing: add query-attribution markers to the trace ring

.github/workflows/pg-ci.yml | 7 +
configure | 32 +
configure.ac | 8 +
doc/src/sgml/config.sgml | 106 +
doc/src/sgml/monitoring.sgml | 783 +++++
meson.build | 1 +
meson_options.txt | 3 +
src/backend/catalog/system_views.sql | 103 +
src/backend/executor/execMain.c | 5 +
src/backend/postmaster/auxprocess.c | 11 +
src/backend/storage/lmgr/proc.c | 5 +
src/backend/tcop/postgres.c | 39 +
src/backend/utils/.gitignore | 1 +
src/backend/utils/Makefile | 9 +-
src/backend/utils/activity/Makefile | 4 +-
src/backend/utils/activity/backend_status.c | 13 +
.../activity/generate-wait_event_types.pl | 179 +
src/backend/utils/activity/meson.build | 1 +
src/backend/utils/activity/wait_event.c | 3 +-
.../utils/activity/wait_event_names.txt | 2 +
.../utils/activity/wait_event_timing.c | 3096 +++++++++++++++++
src/backend/utils/init/postinit.c | 11 +
src/backend/utils/misc/guc_parameters.dat | 29 +
src/backend/utils/misc/guc_tables.c | 1 +
src/backend/utils/misc/postgresql.conf.sample | 5 +
src/include/catalog/pg_proc.dat | 59 +
src/include/pg_config.h.in | 3 +
src/include/storage/lwlocklist.h | 2 +
src/include/storage/subsystemlist.h | 2 +
src/include/utils/.gitignore | 1 +
src/include/utils/guc.h | 1 +
src/include/utils/guc_hooks.h | 3 +
src/include/utils/meson.build | 4 +-
src/include/utils/wait_classes.h | 9 +
src/include/utils/wait_event.h | 49 +
src/include/utils/wait_event_timing.h | 360 ++
src/test/modules/test_misc/meson.build | 1 +
.../t/015_wait_event_trace_seqlock.pl | 122 +
src/test/regress/expected/rules.out | 30 +
.../regress/expected/wait_event_timing.out | 188 +
.../regress/expected/wait_event_timing_1.out | 181 +
src/test/regress/parallel_schedule | 4 +
src/test/regress/sql/wait_event_timing.sql | 113 +
src/tools/pginclude/headerscheck | 2 +
src/tools/pgindent/typedefs.list | 12 +
45 files changed, 5594 insertions(+), 9 deletions(-)
create mode 100644 src/backend/utils/activity/wait_event_timing.c
create mode 100644 src/include/utils/wait_event_timing.h
create mode 100644 src/test/modules/test_misc/t/015_wait_event_trace_seqlock.pl
create mode 100644 src/test/regress/expected/wait_event_timing.out
create mode 100644 src/test/regress/expected/wait_event_timing_1.out
create mode 100644 src/test/regress/sql/wait_event_timing.sql

Hi,

While testing v4, I ran into a backend startup failure when
wait_event_capture=stats was set through PGOPTIONS:

FATAL: ResourceOwnerEnlarge called after release started

This was on macOS arm64 with --enable-wait-event-timing,
--enable-cassert and --enable-debug. I ran a one-statement pgbench
workload with two clients (-c 2 -j 2 -t 1) 500 times. 16 runs
returned non-zero, and five runs produced the FATAL above in the
server log.

The failure is probabilistic. The same test did not reproduce with
one client in 500 runs. The two-client tests with
wait_event_capture=off or trace at startup, and with stats or trace set
after connection startup, were also clean.

The relevant part of the backtrace was:

InitPostgres
-> CommitTransactionCommand
-> ProcReleaseLocks
-> LockReleaseAll
-> LWLockAcquire
-> pgstat_report_wait_end_timing
-> pgstat_wait_event_timing_lazy_attach
-> wait_event_timing_attach_array
-> wait_event_timing_ensure_dsa
-> dsa_attach
-> dsm_attach
-> dsm_create_descriptor
-> ResourceOwnerEnlarge

The first lazy DSA attach is reached from the wait-end path while
InitPostgres is already releasing the current resource owner. The
attach path then reaches dsm_create_descriptor(), which calls
ResourceOwnerEnlarge() after release has started.

Could you address this in the next version?

Regards,
Ilmar

The new status of this patch is: Waiting on Author

Hi,

v5 fixes the startup crash Ilmar Yunusov reported on v4 and rebases
over current master.

* Fix "FATAL: ResourceOwnerEnlarge called after release started" when
wait_event_capture is enabled via PGOPTIONS at startup under
concurrency (0005). The first lazy DSA attach could be triggered by
a wait event during InitPostgres's own transaction cleanup, while the
current resource owner was already mid-release, making
dsm_create_descriptor()'s ResourceOwnerEnlarge() illegal. The lazy
attach now also declines during startup (!IsNormalProcessingMode())
and attaches on the first wait once the backend reaches normal
processing, matching the existing critical-section and LWLock-wait
guards. Reproduced at 2 FATALs / 60 concurrent startups unpatched,
0 / 4800 with the fix; the stats view still populates normally and
the regression and TAP suites pass.

* Rebased over current master.

The API-direction question from the earlier discussion still stands.
The patches still carry no catversion bump; one is needed at commit
time for 0002, 0003 and 0006.

Regards,
Dmitry Fomin

Dmitry Fomin (7):
wait_event_timing: add --enable-wait-event-timing flag and
wait_event_capture GUC
wait_event_timing: record per-backend wait event statistics (stats
level)
wait_event_timing: expose overflow counters and add reset functions
ci: build one task with --enable-wait-event-timing
wait_event_timing: allocate the per-backend array lazily in DSA
wait_event_timing: add trace level with a per-session ring buffer
wait_event_timing: add query-attribution markers to the trace ring

.github/workflows/pg-ci.yml | 7 +
configure | 32 +
configure.ac | 8 +
doc/src/sgml/config.sgml | 106 +
doc/src/sgml/monitoring.sgml | 783 +++++
meson.build | 1 +
meson_options.txt | 3 +
src/backend/catalog/system_views.sql | 103 +
src/backend/executor/execMain.c | 5 +
src/backend/postmaster/auxprocess.c | 11 +
src/backend/storage/lmgr/proc.c | 5 +
src/backend/tcop/postgres.c | 39 +
src/backend/utils/.gitignore | 1 +
src/backend/utils/Makefile | 9 +-
src/backend/utils/activity/Makefile | 4 +-
src/backend/utils/activity/backend_status.c | 13 +
.../activity/generate-wait_event_types.pl | 179 +
src/backend/utils/activity/meson.build | 1 +
src/backend/utils/activity/wait_event.c | 3 +-
.../utils/activity/wait_event_names.txt | 2 +
.../utils/activity/wait_event_timing.c | 3109 +++++++++++++++++
src/backend/utils/init/postinit.c | 11 +
src/backend/utils/misc/guc_parameters.dat | 29 +
src/backend/utils/misc/guc_tables.c | 1 +
src/backend/utils/misc/postgresql.conf.sample | 5 +
src/include/catalog/pg_proc.dat | 59 +
src/include/pg_config.h.in | 3 +
src/include/storage/lwlocklist.h | 2 +
src/include/storage/subsystemlist.h | 2 +
src/include/utils/.gitignore | 1 +
src/include/utils/guc.h | 1 +
src/include/utils/guc_hooks.h | 3 +
src/include/utils/meson.build | 4 +-
src/include/utils/wait_classes.h | 9 +
src/include/utils/wait_event.h | 49 +
src/include/utils/wait_event_timing.h | 360 ++
src/test/modules/test_misc/meson.build | 1 +
.../t/015_wait_event_trace_seqlock.pl | 122 +
src/test/regress/expected/rules.out | 30 +
.../regress/expected/wait_event_timing.out | 188 +
.../regress/expected/wait_event_timing_1.out | 181 +
src/test/regress/parallel_schedule | 4 +
src/test/regress/sql/wait_event_timing.sql | 113 +
src/tools/pginclude/headerscheck | 2 +
src/tools/pgindent/typedefs.list | 12 +
45 files changed, 5607 insertions(+), 9 deletions(-)
create mode 100644 src/backend/utils/activity/wait_event_timing.c
create mode 100644 src/include/utils/wait_event_timing.h
create mode 100644 src/test/modules/test_misc/t/015_wait_event_trace_seqlock.pl
create mode 100644 src/test/regress/expected/wait_event_timing.out
create mode 100644 src/test/regress/expected/wait_event_timing_1.out
create mode 100644 src/test/regress/sql/wait_event_timing.sql

Hi Hackers

v6 is a rebase of v5 over current master (74c77052bc2); cfbot flagged
the set as needing a rebase after about 400 commits of drift. One
mechanical change beyond the rebase: master meanwhile added
src/test/modules/test_misc/t/015_temp_schema_exit_deferrable.pl, so the
injection-point seqlock TAP test moves from 015 to
t/016_wait_event_trace_seqlock.pl. No code changes.

The patches carry no catversion bump; one is needed at commit time for
0002, 0003 and 0006.

Regards,
Dmitry Fomin

Dmitry Fomin (7):
wait_event_timing: add --enable-wait-event-timing flag and
wait_event_capture GUC
wait_event_timing: record per-backend wait event statistics (stats
level)
wait_event_timing: expose overflow counters and add reset functions
ci: build one task with --enable-wait-event-timing
wait_event_timing: allocate the per-backend array lazily in DSA
wait_event_timing: add trace level with a per-session ring buffer
wait_event_timing: add query-attribution markers to the trace ring

.github/workflows/pg-ci.yml | 7 +
configure | 32 +
configure.ac | 8 +
doc/src/sgml/config.sgml | 106 +
doc/src/sgml/monitoring.sgml | 783 +++++
meson.build | 1 +
meson_options.txt | 3 +
src/backend/catalog/system_views.sql | 103 +
src/backend/executor/execMain.c | 5 +
src/backend/postmaster/auxprocess.c | 11 +
src/backend/storage/lmgr/proc.c | 5 +
src/backend/tcop/postgres.c | 39 +
src/backend/utils/.gitignore | 1 +
src/backend/utils/Makefile | 9 +-
src/backend/utils/activity/Makefile | 4 +-
src/backend/utils/activity/backend_status.c | 13 +
.../activity/generate-wait_event_types.pl | 179 +
src/backend/utils/activity/meson.build | 1 +
src/backend/utils/activity/wait_event.c | 3 +-
.../utils/activity/wait_event_names.txt | 2 +
.../utils/activity/wait_event_timing.c | 3109 +++++++++++++++++
src/backend/utils/init/postinit.c | 11 +
src/backend/utils/misc/guc_parameters.dat | 29 +
src/backend/utils/misc/guc_tables.c | 1 +
src/backend/utils/misc/postgresql.conf.sample | 5 +
src/include/catalog/pg_proc.dat | 59 +
src/include/pg_config.h.in | 3 +
src/include/storage/lwlocklist.h | 2 +
src/include/storage/subsystemlist.h | 2 +
src/include/utils/.gitignore | 1 +
src/include/utils/guc.h | 1 +
src/include/utils/guc_hooks.h | 3 +
src/include/utils/meson.build | 4 +-
src/include/utils/wait_classes.h | 9 +
src/include/utils/wait_event.h | 49 +
src/include/utils/wait_event_timing.h | 360 ++
src/test/modules/test_misc/meson.build | 1 +
.../t/016_wait_event_trace_seqlock.pl | 122 +
src/test/regress/expected/rules.out | 30 +
.../regress/expected/wait_event_timing.out | 188 +
.../regress/expected/wait_event_timing_1.out | 181 +
src/test/regress/parallel_schedule | 4 +
src/test/regress/sql/wait_event_timing.sql | 113 +
src/tools/pginclude/headerscheck | 2 +
src/tools/pgindent/typedefs.list | 12 +
45 files changed, 5607 insertions(+), 9 deletions(-)
create mode 100644 src/backend/utils/activity/wait_event_timing.c
create mode 100644 src/include/utils/wait_event_timing.h
create mode 100644 src/test/modules/test_misc/t/016_wait_event_trace_seqlock.pl
create mode 100644 src/test/regress/expected/wait_event_timing.out
create mode 100644 src/test/regress/expected/wait_event_timing_1.out
create mode 100644 src/test/regress/sql/wait_event_timing.sql

On Fri, Sep 4, 2026 at 3:23 PM Dmitry Fomin <fomin.list@gmail.com> wrote:

Hi Hackers

v6 is a rebase of v5 over current master (74c77052bc2); cfbot flagged
the set as needing a rebase after about 400 commits of drift. One
mechanical change beyond the rebase: master meanwhile added
src/test/modules/test_misc/t/015_temp_schema_exit_deferrable.pl, so the
injection-point seqlock TAP test moves from 015 to
t/016_wait_event_trace_seqlock.pl. No code changes.

The patches carry no catversion bump; one is needed at commit time for
0002, 0003 and 0006.

Regards,
Dmitry Fomin

Let me +1 this, as I believe this is incredibly useful.
Keep up the good work.

Kirk Out!

Hi,

I looked at v6 together with Ilmar's EXPLAIN WAITS proposal [0]/messages/by-id/cover.1778280923.git.tanswis42@gmail.com and the
earlier wait-event statistics discussion [1]/messages/by-id/aGKSzFlpQWSh/+2w@ip-10-97-1-34.eu-west-3.compute.internal. I think a small common
hook with the collectors kept outside core is worth prototyping, but the
hook moves rather than removes the main performance question.

The current start/end reporting path is essentially one 32-bit store at
each boundary. The null-hook check would run at every reported wait
transition. For I/O events a predictable null check is probably small
relative to the syscall. However, some paths report a wait without
necessarily reaching a kernel wait: for example, WaitEventSetWait() starts
reporting before checking an already-set latch. The important question
is therefore the null-hook cost paid by every backend that did not enable
the feature. Dmitry's end-to-end measurements exclude a large regression
in the tested workloads, but their 1..2% noise does not isolate that cost
or possible register spills at individual hot call sites.

Michael wrote above that this could "make the addition of more wait
events harder to think about." I think that is partly a useful
constraint rather than only a drawback. In the "Missing wait events"
discussion [2]/messages/by-id/CAM527d9PkaSj-gNjLZqjJXnqaWTD8kHPtm2Yj8-1Gh_0pTRgDA@mail.gmail.com, Andres opposed turning wait events into a CPU profiler.
Adding a reporting point should already require us to establish that it
represents a potential wait and to consider its frequency. Such sites
can still be hot and return without blocking, so this does not prove the
null gate free; it does mean that unbounded proliferation is not the
intended model.

The hook contract would have to be unusually strict. The v4 startup
failure demonstrated that wait reporting can happen during
resource-owner release, and the current implementation also guards
startup, critical sections, LWLock waits, exit, and recursion. We do
already trust extensions with callbacks in awkward contexts, so I do not
think this rules out a hook. I think it should be documented as using
only preallocated backend-local state, with no waits, allocations, locks,
or errors, probably with a recursion guard in core.

The two proposals do not seem to be direct competitors. Dmitry needs
every transition for exact counts and an ordered trace. EXPLAIN WAITS
needs statement/active-node attribution, for which sampling may be a
better tradeoff. Current master already lets extensions add EXPLAIN
options and output. Alternatively, a core EXPLAIN WAITS implementation
could install its collector only for the explicitly requested statement.
In v3, every wait end also walks all active node ancestors and updates
each accumulator, so its enabled cost grows with plan depth.

I found one concrete scalability problem in v6. With the default 192
LWLock tranches, each timing slot contains 544 flat and 192 LWLock
histograms and is a little over 203 KiB. Enabling capture in one backend
allocates the complete array for every ProcNumber: about 200 MiB at 1000
slots. Patch 0005 makes the allocation lazy, but not sparse;
0002--0004 allocate it eagerly. Hundreds of MiB, and eventually GiB,
are not acceptable for realistic high-connection configurations when
only one backend requested capture. The storage should be allocated for
collecting backends rather than every possible ProcNumber.

The deployment concern about extensions is real: diagnostics unavailable
on an inherited managed installation are often useless. But the current
configure-time default also leaves the feature unavailable unless the
provider opted in, while putting the entire collector and presentation in
core leaves PostgreSQL with substantial permanent maintenance cost.

I suggest deciding the observation contract first: sampling, explicitly
selected extended wait sites, or every transition. A useful next
experiment would compare master, the compiled-in/off gate, a null hook, a
preloaded module with collection disabled, and enabled collection. The
first three are the important comparison for users who did not request
the feature. This should include an isolated start/end-pair test and
workloads dominated by short waits. If the null gate is acceptable, one
small core hook and a separately maintained timing/trace extension seem
like a promising deployment model. EXPLAIN WAITS could use the same hook
only while the requested statement is running. The hook API would need
chaining and nesting semantics so that these consumers can coexist.

Thank you!

Best regards, Andrey Borodin.

[0]: /messages/by-id/cover.1778280923.git.tanswis42@gmail.com
[1]: /messages/by-id/aGKSzFlpQWSh/+2w@ip-10-97-1-34.eu-west-3.compute.internal
[2]: /messages/by-id/CAM527d9PkaSj-gNjLZqjJXnqaWTD8kHPtm2Yj8-1Gh_0pTRgDA@mail.gmail.com

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]/messages/by-id/uah2s5tppv3onn7bsf2uelyexfrxwrmye6qqyrbbsjepxny7l5@guymflaarnsr. 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]/messages/by-id/sofkrmi3skg3ekc3y23uwxscbviy5lcbukincoyauypg4ylfdg@6lwzhi6uagc7. 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]: /messages/by-id/uah2s5tppv3onn7bsf2uelyexfrxwrmye6qqyrbbsjepxny7l5@guymflaarnsr
[2]: /messages/by-id/sofkrmi3skg3ekc3y23uwxscbviy5lcbukincoyauypg4ylfdg@6lwzhi6uagc7

Regards,
Dmitry Fomin