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

Hi hackers,

v17 is attached as one archive, v17-wait-event-timing.tar.gz, with 9
patches, based on 77bba5454f9. 0001 to 0004 and 0006 are unchanged. The
changes are in 0005 (the trace level); 0007 to 0009 only follow them.

cfbot showed "Needs rebase" for v16. The patches did apply. The archive
was the problem: I built it with macOS tar, which added an AppleDouble
file "._v16-0001-..." next to each patch, and git am stopped at the
first of them. The v17 archive has no such files; I unpacked it and ran
git am on master before sending.

What is new in 0005

v16 documented two attribution limits and said the next version would
fix them. v17 does.

1. A delayed Sync. In the extended protocol a client can wait between
Execute and Sync. v16 wrote an Idle marker there, so the waits of the
commit (WAL flush, SyncRep) went to no statement. v17 writes a new
marker, IdleInTransaction, when a transaction that can still commit is
open, and the last statement of that transaction keeps the commit's
waits.

2. ROLLBACK inside a procedure. v16 closed the CALL at the TxnAbort
marker, so waits after the ROLLBACK went to no statement. In v17
TxnCommit and TxnAbort carry the number of utility statements still
running, and the rule ignores a transaction end with a nonzero number.
The same covers COMMIT in a procedure and the internal transactions of
VACUUM and CREATE INDEX CONCURRENTLY.

Three more changes came with these:

- The depth of a marker now counts planner calls and all executor phases
(start, run, finish, end). SQL that a function runs while a plan is
made, during initial partition pruning, or from a cursor fetched later
is nested correctly. v16 counted only ExecutorStart to ExecutorEnd.
- UtilityEnd is written when the utility statement fails too, so a
statement whose error is caught by an EXCEPTION block is closed.
- The rule is now a function of its own,
pg_wait_event_trace_attribute(records[]). It reads only its argument,
so the regression test runs it on hand-made marker streams.

How the depth is kept, and what it costs

The depth must be right again after an error, also an error caught by an
EXCEPTION block or by PL/Perl or PL/Python. I first did this with
PG_TRY/PG_FINALLY in each hook, as pg_stat_statements does. That is 5
sigsetjmp calls for a freshly planned statement, 4 with a cached plan
and 1 for a utility statement, in every capture mode. I did not want to
add that to capture = off, so v17 does it differently.

Each hook pushes an ErrorContextCallback with an empty callback on
error_context_stack and pops it on return, the way PL/pgSQL, SPI and
COPY push theirs. The depth is the number of these entries, and the
module counts them only when it writes a trace marker. Whoever catches
an error restores error_context_stack, so the count is right again
without any cleanup code in the module.

Work added against v16, with the module loaded:

capture = off or stats
- 3 more hook calls for a freshly planned statement (planner,
ExecutorRun, ExecutorFinish), 2 with a cached plan, 0 for a utility
statement. v16 had 4 hooks, v17 has 7.
- 5 / 4 / 1 push and pop pairs per planned / cached / utility
statement, and one more pair for each further ExecutorRun of a cursor.
- No sigsetjmp added. Nothing added per wait.
- Each emitted NOTICE, WARNING or ERROR, and each GET DIAGNOSTICS ...
PG_CONTEXT, calls the empty callback once per entry on the stack.
- With -fstack-protector-strong: 3 / 2 / 0 more canary store and check
pairs per planned / cached / utility statement, and one more for each
further ExecutorRun.

capture = trace, in addition
- one walk of error_context_stack per marker, one on the ClientRead that
ends a statement, and one per TxnCommit or TxnAbort;
- one PG_TRY per utility statement, for the UtilityEnd on error; with
-fstack-protector-strong that path has 2 canary pairs where v16 had 1;
- a depth test at ExecEnd, UtilityEnd and the transaction markers;
- nothing added to an ordinary wait.

In a microbenchmark outside the server (Apple M4, clang -O2) an empty
call costs 0.9 ns, a push and pop pair 0.6 ns and a PG_TRY 2.8 ns. By
that arithmetic v17 adds about 6 / 4 / 0.6 ns per planned / cached /
utility statement with capture off or stats; the PG_TRY variant would
have added about 19 / 15 / 3 ns. These are estimates. I have not
measured the statement hooks in a server yet, on any version.

What I checked only by reading the source

The entries are stack variables, so one must never stay on
error_context_stack after its hook has returned. I read the places in
core and in the bundled PLs that catch errors (PG_CATCH, PG_FINALLY, the
main loops of backends and workers, proc_exit) and the place in
parallel.c that saves the stack pointer for messages from workers. I
found no path where an entry of the module outlives its hook while the
entries that SPI and PL/pgSQL push in the same call chain do not. I
could not run the tests under ASan on my machine. The Linux 64-bit CI
job builds with -fsanitize=address, and it passed.
A third-party extension that catches an error without restoring
error_context_stack would break this, as it would break core's entries.

Assert-enabled builds keep a shadow counter and check it against the
stack. The check is not complete: it does not catch every missing pop.

One behaviour to know: if capture is switched to trace inside a utility
statement and that statement then fails, no UtilityEnd is written for
it, because its UtilityStart is not in the ring either.

Tests

012_trace_markers.pl grew to 121 checks: errors caught in PL/pgSQL,
PL/Perl and PL/Python, cursors (DECLARE, FETCH, WITH HOLD, a suspended
portal), COPY with a trigger, parallel workers that send notices and
errors, and capture switched in the middle of a statement.
016_by_statement_oracle.pl has 194 checks.

Two CI runs of this version on my fork failed in 012, both because of
test helpers. One read psql's stderr up to a token and missed the
newline after it. The other called getpwuid(), which perl on Windows
does not have; that helper now uses raw_connect() from Cluster.pm. Both
are fixed. I also ran both tests 10 to 20 times under CPU load on my
machine.

Still documented as a limit: a failed request that was buffered or
pipelined before the previous statement ended.

The overhead measurement in a server, which I promised in the v15 mail,
is still to come. It will cover v14, v16 and v17 with the module not
loaded, capture off, stats and trace, per statement and per wait.

CI on my fork, tip 2111711e48d: all jobs passed (Linux 64-bit with
ASan, Linux 32-bit, autoconf, compiler warnings, macOS, Visual Studio,
MinGW).
https://github.com/DmitryNFomin/postgres/actions/runs/43489194180

Dmitry