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

Hi Andres,

Thank you for the reply.

On 2026-10-28 16:19:46, Andres Freund wrote:
> I suggested earlier that it might be ok to convert *some* cases to timed wait
> events, with one-by-one analysis why that's the best thing for that specific
> wait event. I sure as hell didn't mean "all" by that.

You are right, and I am sorry. In the v11 mail I wrote that the timed pair
is the opt-in shape you asked for. That was my wrong reading of "some".

I still convert all sites, and the reason is the use case. To explain one
slow request, the waits inside it have to be recorded. If only some sites
are timed, the time in the other waits ends up in the unexplained part of
the request, and the answer can be wrong in the same way as with a
sampler.

> I frankly just don't buy the premise that tracking the timing of wait events
> alone is a useful exercise. Tracking the amount of time in specific wait
> events is pretty much *useless* without other information. Knowing that
> there's a lot of time in ClientRead doesn't tell you anything useful, without
> also knowing whether it's in the middle of a statement or such.

I agree that timing alone is not enough. The trace level keeps, per
backend, a fixed-size ring of waits with their durations, together with
statement start/end, transaction commit/abort and idle markers (old
records are overwritten when the ring is full).
pg_wait_event_trace_by_statement() groups the recorded waits by statement
execution, with its query id:

- ClientRead after a statement has ended goes to an <idle> bucket, not to
any statement. ClientRead while a statement is still running stays with
that statement.
- The commit and abort markers are in the trace too, so ClientRead inside
an open transaction (the client is slow to send the next statement) can
be told apart from idle time outside a transaction. In the checkout test
below, ClientRead inside the transaction was the main wait in 192 of the
579 rebuilt requests over 5 ms. The SQL function does not do this split
yet; I did it from the trace.
- Waits before execution starts, such as lock waits at Bind and plan cache
revalidation, go to the following statement with phase = 'pre'. The
function's comments list the cases where attribution is still
ambiguous, for example pipelined Parse messages.
- The trace has the start and end time of each statement (while they are
still in the ring), so the time not covered by recorded waits can be put
next to the wait time. This is not CPU time. If the process is throttled
(cgroup CPU quota), the patch cannot see it, and the throttling can make
recorded waits longer.

> Once you record with sufficient detail, you end up with the overhead being too
> high to do this on every wait event.

Recording is off by default and is turned on by a GUC. The v11
bare-metal run (two-socket Xeon, 16 repetitions in randomized blocks)
measured it, with the module loaded and capture on, against unpatched
master:

- microbenchmark, already-set latch: +36.6 ns per wait start/end pair
(statistics level), +38.1 ns (trace level);
- a lock-heavy workload (about 5 lock waits per transaction): 3.3% (stats)
and 3.1% (trace) lower TPS;
- three other pgbench workloads: from 0.2% higher to 1.0% lower TPS.
Against the same build with capture off, trace costs 0.9% to 1.1% TPS
there, and statistics 0.05% to 0.8%.

These are v11 numbers. v12 to v14 changed the recording path only a
little (statement markers, errno), and I have not re-run the full
matrix. So the cost of recording is real, it is paid only while capture
is on, and on these workloads it is small enough to turn capture on
during an incident. The numbers, the method and the scripts are here:
https://github.com/DmitryNFomin/postgres/tree/v11-evidence-20260923

> I think it'd be much more valuable to have something that efficiently sampling
> wait events at a configurable frequency, grouping it with information state,
> backend_type, whether in a transaction, in a query.

A sampler like that would be useful and I would be happy to see it. I
work as a DBA, and pg_wait_sampling is the first tool I open in an
incident. I am not proposing to replace sampling. This patch comes from
incidents where sampling was not enough, or pointed in the wrong
direction, and the team spent time fixing the wrong thing.

A sample does not give the exact number of waits, the duration of each
wait, or where one request ends and the next one starts. A higher rate
gives better estimates, not exact values per request.

Two examples where this mattered, reproduced on test VMs with plain SQL
workloads (no pg_sleep, no injected delays), each compared with
pg_wait_sampling at its defaults:

1. Slow-request tail. A checkout (16 clients, 2,000 requests/s, ~1.5 ms
average) has a tail of slow requests. A background job updates 100 rows
in one statement of about 17 ms and holds the row locks until it ends.
Sampled profile of the request backends, without ClientRead: WALWrite
33%, WalSync 29%, no wait event ("CPU") 22%, DataFileRead 12%,
Lock:transactionid 2.3%. The two changes this ranking suggests did not
fix the tail: with synchronous_commit = off the mean went from 1.51 to
0.83 ms and requests over 5 ms from 972 to 688, but p99.9 was 11.4 ms
against 11.0 ms before; with 2 GB of prewarmed shared buffers, 954
requests over 5 ms and p99.9 11.3 ms.
With exact per-wait timing, each request in the trace can be rebuilt
from its waits. In 65% of the 286 rebuilt requests over 8 ms,
Lock:transactionid is more than half of the request's server time
(patch; 75% of 189 in a separate run with an external eBPF tracer on
stock PG18). Splitting the job into 5-row statements cut requests over
5 ms from 972 to 388 and p99.9 from 11.0 to 5.8 ms.
The sampler's per-query view does show that the UPDATE waits on locks
(41% of its samples). What it cannot show is that these waits, and not
the commit path, make the slow requests slow: the mean hardly changes
(about 1.5 ms before and after the fix). The aggregate profile ranks
WAL and reads far above locks, and the changes it points to leave
p99.9 where it was.

2. Count vs duration. A primary-key lookup with statement_timeout = 10ms,
made slow once by a noisy neighbour on the disk and once by bloat.
Sampled profile: DataFileRead about 97% vs 95%, the same picture. Exact
timing per cancelled execution: 1.9 DataFileRead waits of 7.5 ms
average vs 31.7 waits of 427 us average, so storage vs bloat at once.
pg_stat_statements and pg_stat_io can separate the two as well, when
the completed calls show the same pattern; pg_stat_statements does not
count the cancelled executions.

Scripts, raw data and a README for each case:
1. https://github.com/DmitryNFomin/pg_wait_tracer/tree/master/tests/results/checkout-tail-20261022
2. https://github.com/DmitryNFomin/pg_wait_tracer/tree/master/tests/results/case4-case5-patch-20261022
and https://github.com/DmitryNFomin/pg_wait_tracer/tree/master/tests/results/truncation-and-cancelled-20261022

> I continue to be dead set against that. There's no way it's ok to just inject
> arbitrary code into all the places that use wait events. Nor do I think it's
> ok to increase the code size of all the places that use wait events.

On the hook itself: the rules for a hook are written in wait_event.h (no
allocation, no locks, no waiting, no errors; a depth guard stops
re-entry, and errno is now preserved for the caller), and test_wait_hook
tests them. Reviewing the module against these rules found one call that
could raise an error from inside a hook; v14 removes it (see below).

I also measured what the hook costs when nothing is loaded, not only in
time. Builds of master (4848fd6752a) vs master + 0001 + 0002, -O2, no
extension loaded, x86-64 with GCC 8.5, GCC 13.3 and clang 21:

- At each converted site, start and end each get one test of the hook
pointer, marked unlikely(). The call itself is in a cold out-of-line
function.
- The postgres binary text grows by 0.097% (GCC 8.5), 0.105% (GCC 13) and
0.074% (clang), each compared with the same compiler's master build.
With GCC, about half of the bytes added to the changed functions are in
their .cold parts. The functions I checked that have no converted site
(ProcSleep, WaitLatch, secure_read and others) keep the same size and
stack use.
- The disassembly confirms your register pressure concern: with GCC,
FileReadV and FileWriteV grew their frame from 24 to 40 bytes, because
GCC kept the hook address in a stack slot over the EINTR loop.
LWLockAcquire had no extra spills. Summed over all functions with
converted sites, the static count of stack loads and stores is a bit
higher than in master.

In v14 I put the hook pointers in the same struct as my_wait_event_info,
so the check uses the base register that is already loaded for the wait
event store. With that, FileReadV and FileWriteV are back to a 24-byte
frame with GCC 8.5 and GCC 13, and the text growth is +0.085% / +0.052% /
+0.021% (GCC 8.5 / GCC 13 / clang) against master. These numbers come from
a build of the same change on 4848fd6752a. The summed stack load/store
count does not go down with it, so this fixes the case I found, not every
possible effect. The old names stay as macros, so existing source code
compiles unchanged.

On time, from the same v11 run with 0001 + 0002 and no extension
loaded: against a control build without the hook tests, the
microbenchmark shows +1.63 ns per start/end pair (95% interval 1.48 to
1.77 ns), and none of the four pgbench workloads shows a slowdown.

Changes in v14, besides a rebase onto current master (no conflicts):

- 0001: the struct layout above. The two out-of-line hook functions now
save and restore errno, because callers check errno after the end call
(EINTR retry in FileReadV and others); test_wait_hook tests this.
- 0004: the module no longer calls before_shmem_exit() from inside the
begin hook. That call can raise FATAL when its list is full, which the
hook rules do not allow. Registration now happens only at a safe point.
- Docs and comments no longer say that the timed pair has no cost; they
describe the one pointer test per start and end.

CI:
https://github.com/DmitryNFomin/postgres/actions/runs/41482982301

I understand this does not make the cost zero, and I do not want to argue
that a small cost is no cost. My point is that it buys answers that
sampling does not give, for problems DBAs meet in production.

I tried to answer each concrete concern with code or with measurements.
If there is a wait site where a hook can do real harm, or a cost I have
not measured, please point me to it, and I will measure it or change the
patch.

Regards,
Dmitry