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

Hi hackers,

v15 is attached: 9 patches, based on cea96cdfecb.

0001, 0002 and 0003 (the core hooks, the call-site conversion and
test_wait_hook) are unchanged since v14. The patch content is
identical. I did not touch core code for v15. The two kinds of change
are below: fixes in 0004 and 0005, and four new patches, 0006 to 0009.

Fixes since v14 (0004 and 0005)

0004, statistics level:

- The lookup of an LWLock tranche in a backend's table stopped after 8
probes once the table was full. A tranche that was already admitted
but sat farther from its home slot was not found. The lookup now
probes the whole table. A new test (008_lwlock_table) builds a full
table with colliding keys. With the old probe limit put back, it
fails.
- A backend reading the statistics of another backend copied the
payload without a consistency check. A tranche insertion or a reset
by the owner could run during the copy. The payload now has a
sequence counter (seqlock). The reader accepts a copy only if the
counter was even and unchanged, and it checks the table bounds
before using the copy. The owner pays this only on rare structural
changes (new tranche, reset), not at wait begin or end.
- A fixed-slot process that was disabled and then claimed its slot
again got the same pid and start token back, so a reader could not
see that the payload had been re-initialized in between. The
re-initialization now advances the counter, which never goes back.
- New test 009_stats_stress: producers, resetters and readers run
together. It checks that nothing crashes or hangs, that no row shows
a tranche of another process, and that one producer's own rows are
exact.

0005, trace level (test changes only):

- In 016_by_statement_oracle.pl, the three statements meant to be sent
as one simple-query message were sent as three, because of a Perl
escaping error in the test. The by-statement result was correct in
both cases. The test now sends the single message it was written for.
- One check in the same file failed on the Linux 32-bit CI job in one
run. It required every row of the <no-statement> bucket to be
Lock:relation. By the documented rule, that bucket holds any wait
that is not a Client wait, between an idle marker and the end of the
transaction, so an LWLock or IO wait during the failed Bind also
lands there. The test now requires exactly one Lock:relation row
and allows only LWLock, IO and Buffer rows besides it, and it prints
the rows when it fails. 50 runs under CPU load passed.

New in v15: 0006 to 0009, instance-wide totals

Aurora PostgreSQL documents three things that the per-backend views of
this module did not give: cumulative wait counts and times for the
whole instance that still include processes that have exited, waits
per transaction, and a ready interval report. These patches add them.

- 0006: test_wait_totals, a test-only module in src/test/modules. It
emits an exact number of timed waits, so the tests can check exact
counts. It is not installed with the extension.
- 0007: a lifetime ledger for each process slot, and an exit drain.
- 0008: the views pg_stat_wait_event_totals and
pg_stat_wait_event_totals_info.
- 0009: transaction counters, the reset function, and the interval
functions.

The extension goes to version 1.1 (update script
pg_wait_event_tracing--1.0--1.1.sql). New functions:

- pg_wait_event_snapshot(): one jsonb value with the totals at a point
in time.
- pg_wait_event_diff(a, b, include_idle): the difference between two
snapshots, with waits, wait_time_ms, ms_per_wait, waits_per_xact and
ms_per_xact for each event.
- pg_wait_event_report(seconds, include_idle): snapshot, sleep,
snapshot, diff, in one call.
- pg_stat_reset_wait_event_totals(): superuser only.

How it works:

- Each process slot (indexed by ProcNumber) has a fixed-size ledger in
shared memory. It is updated at the existing flush point of pending
completions, so the wait end path has no new work. The flush can be
called from the next wait begin. The ledger is never cleared on exit,
on slot reuse or on the existing per-backend resets.
- An exit drain is registered at process start, through the
init_backend_cb of a custom cumulative statistics kind. It flushes
the last pending completion when a process exits in an orderly way.
An abrupt death can lose that last completion.
- Readers copy each ledger with a seqlock and hold no lock while they
scan. They can be cancelled between retries.
- The reset does not change any ledger. It publishes a baseline and a
generation, and readers subtract the baseline. A diff between
snapshots from different generations or different server incarnations
is an error.

Memory, with the default settings except max_connections: the ledgers
take 3.5 MiB at max_connections = 100 (174 slots) and 21.9 MiB at
max_connections = 1000 (1074 slots), counting all backend, worker and
auxiliary slots. The reset baseline adds one 1 MiB structure in shared
memory. Each call that reads the totals allocates about 1 MiB of
scratch in the calling backend. These numbers are computed from the
structures (21376 bytes per ledger at the default max_tranches of 192)
and are written in the documentation.

The transaction denominator differs from Aurora's documented examples.
Here, xacts is the number of commits plus aborts counted in the
processes that were capturing. Parallel workers are not counted.
Aurora's documented examples count committed transactions. So
waits_per_xact and ms_per_xact are not directly comparable to
Aurora's figures. The documentation says this.

0006 to 0009 can be reviewed after 0001 to 0005 and can be dropped
without affecting them. They touch only contrib/pg_wait_event_tracing,
doc/src/sgml/pgwaiteventtracing.sgml and src/test/modules (the new
test_wait_totals directory and its entries in meson.build and the
Makefile). They change nothing in core.

CI on my fork, tip 49f3ad513d7, all jobs green (Linux 32-bit and
64-bit, Autoconf, macOS, Windows with VS and with MinGW,
CompilerWarnings):

https://github.com/DmitryNFomin/postgres/actions/runs/42845457896

The overhead numbers in my v14 mail still apply to the hook itself,
because 0001 and 0002 did not change. They do not cover the new ledger
update in the flush. I have not measured that cost yet. I will measure
v15 against v14, both with capture = stats and the same pgbench
workloads as in the v14 mail, and post the numbers in this thread.

Regards,
Dmitry