From f8abf1f0cc9062fe2e2203c9905b839a389f585b Mon Sep 17 00:00:00 2001 From: Dmitry Fomin Date: Fri, 18 Sep 2026 13:51:19 +0200 Subject: [PATCH v12 5/5] pg_wait_event_tracing: trace level Extend pg_wait_event_tracing.capture with a third value, "trace" (implies stats, as in v6), that additionally records a bounded, per-session ring of individual completed waits, readable both by the owning session and cross-backend by pg_read_all_stats, and post-mortem after the owning session has exited. The ring lives in its own DSA area, one per session, written through a single-writer position-encoded seqlock (ported from v6): a cross- backend reader validates a slot's identity before and after copying it and discards a record it caught mid-write rather than risk emitting a torn or stale one. Ownership of a ring is tracked by its own token (trace_owner_pid/trace_owner_start), deliberately independent of the statistics-level owner token added earlier in this series: a ring must stay attributable to its producer even after that process has exited and a successor has already reused the same ProcNumber's statistics slot, and sharing one token between the two would let the successor's routine statistics attach silently reattribute a still-live ring to itself. On live capture step-down the ring is freed immediately; on process exit it is orphaned instead (kept, still attributed, in an ORPHANED state) so a session's waits survive it, flight-recorder fashion. A later attach on the same, reused ProcNumber reclaims an orphaned ring as a side effect of attaching its own; one nobody reuses is freed cluster-wide by pg_stat_clear_orphaned_wait_event_rings(), which -- like the statistics level's own reset-all function -- hard- requires superuser() in C rather than relying only on a revocable EXECUTE grant. A ring by itself only says when a wait happened, not which query it belongs to. A small per-backend state machine, advanced only while tracing, appends query-attribution markers to the same ring alongside ordinary wait records: QueryStart from the parse-analyze hook, ExecStart/ExecEnd around the executor, UtilityStart/UtilityEnd around non-plannable statements, TxnCommit/TxnAbort from a transaction callback, and an Idle marker synthesized directly in the wait-event begin hook itself when a ClientRead wait genuinely blocks (no other hook fires while a backend is simply waiting for its next message). Every marker carries the executor nesting depth in effect when it fired, so a statement issued through SPI from inside another one (a SQL/PL function's own query, say) cannot be mistaken for closing the outer statement. pg_wait_event_trace_by_statement() turns this into a by-statement view over a session's ring. A top-level QueryStart always opens a statement bucket; a top-level UtilityStart or ExecStart does too, unless the statement is already open (the nearest preceding top-level start, Idle or transaction end is a QueryStart or UtilityStart), so an extended-protocol execution of a named prepared statement, which writes only an ExecStart, gets its own bucket, while the statements run inside a DO, CALL, EXECUTE or CREATE TABLE AS stay with it. Idle and TxnAbort open the '' bucket, and waits preceding a ring's first such marker are ''. Waits that occur after a request has arrived but before its start marker is written (plan cache locks in Bind, relation locks in parse analysis) are moved to the statement that follows, with phase 'pre', except for Client waits, which are idle time; the waits of a request that fails before any statement starts go to ''. Testing relies on an injection point placed at the exact instant the seqlock's write position has advanced past a slot whose record still holds the previous cycle's content -- the one window a cross-backend read could otherwise be caught in -- following the same convention the statistics level's reset-race test already established. TAP tests cover the orphan lifecycle end to end (post-mortem read, reclaim on reuse, and the sweep function), the seqlock hazard itself under the injection point, a long-running session wrapping a minimum-size ring without losing contiguity for a concurrent reader, and the marker state machine's two corners a single deterministic SQL script cannot force on demand: a real client-side pause producing Idle, and the depth counter's defensive reset after an error raised mid-execution. A regression test extends the statistics level's single-session coverage with the marker sequences produced by autocommit, explicit transactions, multiple statements in one protocol message, utility statements, errors, and nested execution. It also covers the by-statement attribution of prepared-statement executions (with and without a pipeline sync between them), a looping DO block, a simple-protocol utility statement and a multi-statement string, and a two-session TAP test holds a table lock to cover the pre phase of both protocols and the '' bucket. Two more TAP tests check the function against realistic input: pgbench clients in simple, extended and prepared mode blocked by a table lock, and a fixed script of statement shapes whose expected query_ids and waits are known to the client. Discussion: https://postgr.es/m/CAPHG-0mAOn05ae6Kqx1wHXxzOk4E5W7ajjd=QBhgkR7a0uyQmw@mail.gmail.com --- contrib/pg_wait_event_tracing/Makefile | 2 +- .../expected/pg_wait_event_tracing_trace.out | 445 +++++ contrib/pg_wait_event_tracing/meson.build | 9 + .../pg_wait_event_tracing--1.0.sql | 284 +++ .../pg_wait_event_tracing.c | 1720 +++++++++++++++-- .../sql/pg_wait_event_tracing_trace.sql | 304 +++ .../t/005_orphan_reuse.pl | 203 ++ .../t/006_server_processes.pl | 51 +- .../t/010_trace_seqlock.pl | 131 ++ .../pg_wait_event_tracing/t/011_trace_wrap.pl | 143 ++ .../t/012_trace_markers.pl | 222 +++ .../t/013_deferred_flush.pl | 214 ++ .../t/014_by_statement_pre.pl | 190 ++ .../t/015_by_statement_pgbench.pl | 242 +++ .../t/016_by_statement_oracle.pl | 426 ++++ doc/src/sgml/pgwaiteventtracing.sgml | 163 +- src/tools/pgindent/typedefs.list | 4 + 17 files changed, 4595 insertions(+), 158 deletions(-) create mode 100644 contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_trace.out create mode 100644 contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_trace.sql create mode 100644 contrib/pg_wait_event_tracing/t/005_orphan_reuse.pl create mode 100644 contrib/pg_wait_event_tracing/t/010_trace_seqlock.pl create mode 100644 contrib/pg_wait_event_tracing/t/011_trace_wrap.pl create mode 100644 contrib/pg_wait_event_tracing/t/012_trace_markers.pl create mode 100644 contrib/pg_wait_event_tracing/t/013_deferred_flush.pl create mode 100644 contrib/pg_wait_event_tracing/t/014_by_statement_pre.pl create mode 100644 contrib/pg_wait_event_tracing/t/015_by_statement_pgbench.pl create mode 100644 contrib/pg_wait_event_tracing/t/016_by_statement_oracle.pl diff --git a/contrib/pg_wait_event_tracing/Makefile b/contrib/pg_wait_event_tracing/Makefile index b7bb15840df..ef8522ebea6 100644 --- a/contrib/pg_wait_event_tracing/Makefile +++ b/contrib/pg_wait_event_tracing/Makefile @@ -9,7 +9,7 @@ EXTENSION = pg_wait_event_tracing DATA = pg_wait_event_tracing--1.0.sql PGFILEDESC = "pg_wait_event_tracing - statistics and trace collection for explicitly instrumented wait events" -REGRESS = pg_wait_event_tracing +REGRESS = pg_wait_event_tracing pg_wait_event_tracing_trace REGRESS_OPTS = --temp-config $(top_srcdir)/contrib/pg_wait_event_tracing/pg_wait_event_tracing.conf # The tests need the module preloaded, which typical installcheck users diff --git a/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_trace.out b/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_trace.out new file mode 100644 index 00000000000..b71382f4471 --- /dev/null +++ b/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_trace.out @@ -0,0 +1,445 @@ +-- +-- PG_WAIT_EVENT_TRACING_TRACE +-- +-- Exercises the trace level's query-attribution markers (fix 6): the +-- QueryStart/ExecStart/ExecEnd/UtilityStart/UtilityEnd/TxnCommit/TxnAbort +-- marker set and pg_wait_event_trace_by_statement(). The ring buffer's own +-- seqlock/wrap/orphan-lifecycle machinery is exercised by TAP tests with +-- injection points (WP4), not here. +-- +-- Idle is deliberately excluded from every comparison below (see the WHERE +-- clause in the pattern below): whether it appears at all depends on +-- whether the backend actually blocks in ClientRead, which depends on +-- whether the next message psql sends is already buffered by the time the +-- backend looks -- protocol structure (separate messages vs. one +-- multi-statement message) makes it likely but not deterministic either +-- way on a loaded CI runner. A TAP test, where the client can pause +-- deliberately between statements to force the wait, covers Idle instead +-- (WP4b). +-- +-- Reading a session's own ring via SQL is necessarily self-referential: +-- every observing SELECT below writes its own QueryStart+ExecStart into +-- the ring (post_parse_analyze/ExecutorStart fire before its body runs), +-- and the "markN" SELECT used to record a starting ring position finishes +-- writing its own ExecEnd+TxnCommit (and possibly an Idle, excluded here +-- for the same reason as above) *after* that position was captured +-- (captured mid-execution, from inside its own target list). Every case +-- below therefore uses the identical, fully deterministic pattern: +-- +-- SELECT coalesce(max(seq), -1) AS markN FROM pg_backend_wait_event_trace \gset +-- +-- SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +-- FROM pg_backend_wait_event_trace +-- WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :markN; +-- +-- [3:count(*)-2]: index 1-2 are always the "markN" statement's own +-- trailing ExecEnd, TxnCommit (everything it itself writes to the ring +-- after the position was captured from its still-in-progress ExecStart, +-- minus any Idle, already filtered out by the WHERE clause regardless of +-- whether it fired); the last 2 indexes are always this observing SELECT's +-- own leading-in-time-but-trailing-in-the-array QueryStart, ExecStart +-- (written to the ring before its body/aggregate runs). Slicing them off +-- leaves exactly the case's own real, non-Idle markers. Real wait events +-- are deliberately never asserted by exact count (plan sec 5.5): the one +-- case with a real wait (case 7) checks only presence/attribution. +-- +CREATE EXTENSION IF NOT EXISTS pg_wait_event_tracing; +NOTICE: extension "pg_wait_event_tracing" already exists, skipping +-- CI forces debug_parallel_query = regress on some platforms, which +-- would move statements below into a parallel worker, recording their +-- markers under the worker's own ring, not this session's. +SET debug_parallel_query = off; +SET pg_wait_event_tracing.capture = trace; +-- +-- Case 1: a single autocommit statement. +-- Expect: QueryStart, ExecStart, ExecEnd, TxnCommit (Idle excluded; it +-- would follow once the implicit transaction has committed and the +-- backend waits for the next client message -- see the file header). +-- +SELECT coalesce(max(seq), -1) AS mark1 FROM pg_backend_wait_event_trace \gset +SELECT 1; + ?column? +---------- + 1 +(1 row) + +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark1; + markers +------------------------------------------ + {QueryStart,ExecStart,ExecEnd,TxnCommit} +(1 row) + +-- +-- Case 2: an explicit transaction with two statements, each on its own +-- line. The transaction stays open the whole time (no TxnCommit/TxnAbort +-- until the final COMMIT). TxnCommit follows UtilityEnd here, the same +-- as case 4's plain utility statement, not during ProcessUtility: an +-- explicit COMMIT's EndTransactionBlock() only marks the transaction +-- block TBLOCK_END while still inside the utility statement: the actual +-- commit (CommitTransaction(), which fires the xact callback) happens in +-- finish_xact_command(), called by exec_simple_query() (postgres.c) +-- *after* ProcessUtility returns -- the same command-loop point an +-- ordinary autocommit statement's implicit commit happens at. +-- +SELECT coalesce(max(seq), -1) AS mark2 FROM pg_backend_wait_event_trace \gset +BEGIN; +SELECT 1; + ?column? +---------- + 1 +(1 row) + +SELECT 2; + ?column? +---------- + 2 +(1 row) + +COMMIT; +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark2; + markers +--------------------------------------------------------------------------------------------------------------------------------------------- + {QueryStart,UtilityStart,UtilityEnd,QueryStart,ExecStart,ExecEnd,QueryStart,ExecStart,ExecEnd,QueryStart,UtilityStart,UtilityEnd,TxnCommit} +(1 row) + +-- +-- Case 3: two statements sent as ONE simple-query protocol message, both +-- on the same input line so psql sends them together. Each still gets +-- its own individual QueryStart/ExecStart/ExecEnd/TxnCommit -- autocommit +-- commits after every statement in a multi-statement string, not once at +-- the end. +-- +SELECT coalesce(max(seq), -1) AS mark3 FROM pg_backend_wait_event_trace \gset +SELECT 1; SELECT 2; + ?column? +---------- + 1 +(1 row) + + ?column? +---------- + 2 +(1 row) + +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark3; + markers +--------------------------------------------------------------------------------- + {QueryStart,ExecStart,ExecEnd,TxnCommit,QueryStart,ExecStart,ExecEnd,TxnCommit} +(1 row) + +-- +-- Case 4: a utility statement (no executor involvement): UtilityStart/ +-- UtilityEnd only, no ExecStart/ExecEnd, TxnCommit after UtilityEnd -- +-- same shape and same reason as case 2's COMMIT above (the implicit +-- per-statement commit happens in the command loop, after +-- ProcessUtility_hook returns). +-- +SELECT coalesce(max(seq), -1) AS mark4 FROM pg_backend_wait_event_trace \gset +CREATE TABLE pwet_trace_test_t (a int); +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark4; + markers +------------------------------------------------ + {QueryStart,UtilityStart,UtilityEnd,TxnCommit} +(1 row) + +DROP TABLE pwet_trace_test_t; +-- +-- Case 5: an error raised during PLANNING, not execution: 1/0 is a +-- constant expression, and the planner's eval_const_expressions() folds +-- it by calling evaluate_expr() (clauses.c), which builds a throwaway +-- executor state and evaluates the expression right there -- raising the +-- division-by-zero before ExecutorStart is ever reached. So there is no +-- ExecStart/ExecEnd pair to leave unmatched here: QueryStart opens the +-- statement's interval, and TxnAbort -- not TxnCommit -- closes it +-- directly. This no longer exercises pwet_marker_txn_abort()'s +-- defensive pwet_exec_depth reset (needed for a genuinely mid-execution +-- error, which this simple, always-planning-time-erroring form cannot +-- produce); that reset stays uncovered by this regression file. +-- +SELECT coalesce(max(seq), -1) AS mark5 FROM pg_backend_wait_event_trace \gset +SELECT 1/0; +ERROR: division by zero +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark5; + markers +----------------------- + {QueryStart,TxnAbort} +(1 row) + +-- +-- Case 6: a nested query call (depth 1 inside depth 0). LANGUAGE SQL +-- will not do here: inline_function() (clauses.c) inlines a SQL-language +-- function whose body is a single simple SELECT directly into the +-- calling query, so it never runs its own separate, nested executor +-- invocation at all. PL/pgSQL is not inlined, and a PERFORM statement +-- in its body always goes through SPI's normal execute path (unlike a +-- bare RETURN/assignment expression, which plpgsql evaluates directly +-- without SPI when it is "simple enough"), so it reliably produces a +-- real nested ExecStart/ExecEnd pair. plpgsql is installed in every +-- database by default, so this needs no extra CREATE EXTENSION. +-- +-- The function is called once first, outside the measured window, so +-- its PERFORM statement's query is already parsed and its plan cached +-- (plpgsql caches each statement's plan across calls in the same +-- session) by the time of the measured call -- keeping this case about +-- the ExecStart/ExecEnd depth nesting specifically, not about whether a +-- cached call also re-parses (it does not, so no QueryStart happens at +-- nested depth in the measured call). +-- +CREATE FUNCTION pwet_trace_test_nested() RETURNS int +LANGUAGE plpgsql AS $$ BEGIN PERFORM 1; RETURN 1; END $$; +SELECT pwet_trace_test_nested(); + pwet_trace_test_nested +------------------------ + 1 +(1 row) + +SELECT coalesce(max(seq), -1) AS mark6 FROM pg_backend_wait_event_trace \gset +SELECT pwet_trace_test_nested(); + pwet_trace_test_nested +------------------------ + 1 +(1 row) + +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers, + (array_agg(depth ORDER BY seq))[3:count(*)-2] AS depths +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark6; + markers | depths +------------------------------------------------------------+--------------- + {QueryStart,ExecStart,ExecStart,ExecEnd,ExecEnd,TxnCommit} | {0,0,1,1,0,0} +(1 row) + +DROP FUNCTION pwet_trace_test_nested(); +-- +-- Case 7: pg_wait_event_trace_by_statement() attribution. A pg_sleep() +-- inside its own statement guarantees at least one real (Timeout/ +-- PgSleep) wait to attribute; the following bare SELECT has none. Never +-- assert an exact PgSleep count (plan sec 5.5): only that every PgSleep +-- wait this session ever recorded was attributed to a real statement, +-- never to the synthetic / buckets, and that at +-- least one such wait was seen. +-- +SELECT procnumber FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid() LIMIT 1 \gset +SELECT pg_sleep(0.01); + pg_sleep +---------- + +(1 row) + +SELECT 1; + ?column? +---------- + 1 +(1 row) + +SELECT bool_and(bucket NOT IN ('', '')) AS pgsleep_attributed, + sum(calls) >= 1 AS at_least_one_pgsleep +FROM pg_wait_event_trace_by_statement(:procnumber) +WHERE wait_event = 'PgSleep'; + pgsleep_attributed | at_least_one_pgsleep +--------------------+---------------------- + t | t +(1 row) + +-- +-- Cases 8-12: statement attribution of pg_wait_event_trace_by_statement() +-- for the ways a statement can start. Every statement under test sleeps +-- for 10 ms, giving it at least one Timeout/PgSleep wait (a platform may +-- record more than one, so only "at least one" is ever asserted), and +-- each check counts the distinct statement buckets holding such waits +-- after a recorded ring position. A bucket's statement_seq is the seq of +-- the marker that opened it, so looking that marker up in the ring tells +-- which kind of marker opened the bucket. +-- +-- compute_query_id is on so the markers carry a query identifier. +-- +SET compute_query_id = on; +-- +-- Case 8: one named prepared statement executed three times over the +-- extended protocol. Only the first Parse runs post_parse_analyze; each +-- execution writes just an ExecStart. Expect three buckets, all with the +-- query_id of the ExecStart that opened them, and no PgSleep wait in any +-- synthetic bucket. +-- +SELECT coalesce(max(seq), -1) AS mark8 FROM pg_backend_wait_event_trace \gset +SELECT pg_sleep(0.01) AS slept8 \parse pwet_trace_s8 +\bind_named pwet_trace_s8 \g + slept8 +-------- + +(1 row) + +\bind_named pwet_trace_s8 \g + slept8 +-------- + +(1 row) + +\bind_named pwet_trace_s8 \g + slept8 +-------- + +(1 row) + +SELECT count(DISTINCT b.statement_seq) AS buckets, + count(DISTINCT b.query_id) AS query_ids, + bool_and(m.wait_event = 'ExecStart' AND m.query_id = b.query_id + AND b.query_id <> 0) AS opened_by_execstart, + bool_and(b.phase IN ('pre', 'statement')) AS phases_ok +FROM pg_wait_event_trace_by_statement(:procnumber) b + JOIN pg_backend_wait_event_trace m ON m.seq = b.statement_seq +WHERE b.wait_event = 'PgSleep' AND b.statement_seq > :mark8; + buckets | query_ids | opened_by_execstart | phases_ok +---------+-----------+---------------------+----------- + 3 | 1 | t | t +(1 row) + +SELECT count(*) AS sleeps_in_synthetic_buckets +FROM pg_wait_event_trace_by_statement(:procnumber) +WHERE wait_event = 'PgSleep' AND bucket IN ('', '', ''); + sleeps_in_synthetic_buckets +----------------------------- + 0 +(1 row) + +-- +-- Case 9: the same statement run in a pipeline with a sync between the +-- executions. Each sync commits, so every ExecStart follows a TxnCommit +-- with no Idle marker in between (the next message was already +-- buffered). Expect three separate buckets. +-- +SELECT coalesce(max(seq), -1) AS mark9 FROM pg_backend_wait_event_trace \gset +\startpipeline +\bind_named pwet_trace_s8 \sendpipeline +\syncpipeline +\bind_named pwet_trace_s8 \sendpipeline +\syncpipeline +\bind_named pwet_trace_s8 \sendpipeline +\endpipeline + slept8 +-------- + +(1 row) + + slept8 +-------- + +(1 row) + + slept8 +-------- + +(1 row) + +SELECT count(DISTINCT b.statement_seq) AS buckets, + bool_and(m.wait_event = 'ExecStart' AND m.query_id = b.query_id + AND b.query_id <> 0) AS opened_by_execstart +FROM pg_wait_event_trace_by_statement(:procnumber) b + JOIN pg_backend_wait_event_trace m ON m.seq = b.statement_seq +WHERE b.wait_event = 'PgSleep' AND b.statement_seq > :mark9; + buckets | opened_by_execstart +---------+--------------------- + 3 | t +(1 row) + +\close_prepared pwet_trace_s8 +-- +-- Case 10: a DO block looping three times over a statement whose plan is +-- cached after the first iteration. The statements it runs have depth-0 +-- markers (UtilityStart does not raise the depth), but belong to the DO: +-- expect exactly one bucket, opened by the QueryStart of the DO itself, +-- holding at least three PgSleep waits. +-- +SELECT coalesce(max(seq), -1) AS mark10 FROM pg_backend_wait_event_trace \gset +DO $$ BEGIN FOR i IN 1..3 LOOP PERFORM pg_sleep(0.01); END LOOP; END $$; +SELECT count(DISTINCT b.statement_seq) AS buckets, + sum(b.calls) >= 3 AS at_least_three_sleeps, + bool_and(m.wait_event = 'QueryStart') AS opened_by_querystart +FROM pg_wait_event_trace_by_statement(:procnumber) b + JOIN pg_backend_wait_event_trace m ON m.seq = b.statement_seq +WHERE b.wait_event = 'PgSleep' AND b.statement_seq > :mark10; + buckets | at_least_three_sleeps | opened_by_querystart +---------+-----------------------+---------------------- + 1 | t | t +(1 row) + +-- +-- Case 11: a utility statement over the simple protocol writes QueryStart +-- and then UtilityStart; the pair is one statement. CREATE TABLE AS also +-- runs its query inside the utility (ExecStart at depth 0), which must +-- not open another bucket. +-- +SELECT coalesce(max(seq), -1) AS mark11 FROM pg_backend_wait_event_trace \gset +CREATE TEMP TABLE pwet_trace_t11 AS SELECT pg_sleep(0.01)::text AS slept11; +SELECT count(DISTINCT b.statement_seq) AS buckets, + bool_and(m.wait_event = 'QueryStart') AS opened_by_querystart +FROM pg_wait_event_trace_by_statement(:procnumber) b + JOIN pg_backend_wait_event_trace m ON m.seq = b.statement_seq +WHERE b.wait_event = 'PgSleep' AND b.statement_seq > :mark11; + buckets | opened_by_querystart +---------+---------------------- + 1 | t +(1 row) + +DROP TABLE pwet_trace_t11; +-- +-- Case 12: three statements in one simple-query string: one bucket each. +-- +SELECT coalesce(max(seq), -1) AS mark12 FROM pg_backend_wait_event_trace \gset +SELECT pg_sleep(0.01); SELECT pg_sleep(0.01); SELECT pg_sleep(0.01); + pg_sleep +---------- + +(1 row) + + pg_sleep +---------- + +(1 row) + + pg_sleep +---------- + +(1 row) + +SELECT count(DISTINCT b.statement_seq) AS buckets, + bool_and(m.wait_event = 'QueryStart') AS opened_by_querystart +FROM pg_wait_event_trace_by_statement(:procnumber) b + JOIN pg_backend_wait_event_trace m ON m.seq = b.statement_seq +WHERE b.wait_event = 'PgSleep' AND b.statement_seq > :mark12; + buckets | opened_by_querystart +---------+---------------------- + 3 | t +(1 row) + +-- +-- Case 13: no wait of the whole session is lost or counted twice: the +-- function's calls add up to the number of non-marker records in the ring. +-- The ring is read before and after the function (this session can record +-- another wait in between), so the sum is bounded by the two counts; the +-- TAP test 014 checks the exact equality on a quiet session. +-- +SELECT count(*) FROM pg_get_wait_event_trace(:procnumber) +WHERE wait_event_type <> 'Query' \gset before_ +SELECT sum(calls) AS total_calls FROM pg_wait_event_trace_by_statement(:procnumber) \gset +SELECT count(*) FROM pg_get_wait_event_trace(:procnumber) +WHERE wait_event_type <> 'Query' \gset after_ +SELECT :total_calls BETWEEN :before_count AND :after_count AS no_wait_lost_or_doubled; + no_wait_lost_or_doubled +------------------------- + t +(1 row) + +RESET compute_query_id; +RESET pg_wait_event_tracing.capture; diff --git a/contrib/pg_wait_event_tracing/meson.build b/contrib/pg_wait_event_tracing/meson.build index e7e2928f921..03136cdfd1f 100644 --- a/contrib/pg_wait_event_tracing/meson.build +++ b/contrib/pg_wait_event_tracing/meson.build @@ -29,6 +29,7 @@ tests += { 'regress': { 'sql': [ 'pg_wait_event_tracing', + 'pg_wait_event_tracing_trace', ], 'regress_args': ['--temp-config', files('pg_wait_event_tracing.conf')], # Needs shared_preload_libraries, which typical runningcheck users do @@ -44,8 +45,16 @@ tests += { 't/002_ownership.pl', 't/003_reset_acl.pl', 't/004_reset_race.pl', + 't/005_orphan_reuse.pl', 't/006_server_processes.pl', 't/007_lazy_hooks.pl', + 't/010_trace_seqlock.pl', + 't/011_trace_wrap.pl', + 't/012_trace_markers.pl', + 't/013_deferred_flush.pl', + 't/014_by_statement_pre.pl', + 't/015_by_statement_pgbench.pl', + 't/016_by_statement_oracle.pl', ], }, } diff --git a/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0.sql b/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0.sql index 75546d6605e..88c886cdacc 100644 --- a/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0.sql +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0.sql @@ -134,6 +134,290 @@ RETURNS boolean AS 'MODULE_PATHNAME', 'pg_wait_event_tracing_hooks_installed' LANGUAGE C VOLATILE PARALLEL RESTRICTED; +-- Trace level (pg_wait_event_tracing.capture = trace): a per-session ring +-- buffer of individual completed waits plus query-attribution markers. +-- Reading a session's trace exposes its query_id and wait sequence, which +-- can leak across SECURITY DEFINER call chains, so the view AND both +-- underlying SRFs are locked to pg_read_all_stats, matching v6. +CREATE FUNCTION pg_get_backend_wait_event_trace( + OUT seq int8, + OUT timestamp_ns int8, + OUT wait_event_type text, + OUT wait_event text, + OUT duration_us float8, + OUT query_id int8, + OUT depth int4) +RETURNS SETOF record +AS 'MODULE_PATHNAME', 'pg_get_backend_wait_event_trace' +LANGUAGE C VOLATILE PARALLEL RESTRICTED; + +CREATE VIEW pg_backend_wait_event_trace AS + SELECT + t.seq, + t.timestamp_ns, + t.wait_event_type, + t.wait_event, + t.duration_us, + t.query_id, + t.depth + FROM pg_get_backend_wait_event_trace() t; +REVOKE ALL ON pg_backend_wait_event_trace FROM PUBLIC; +GRANT SELECT ON pg_backend_wait_event_trace TO pg_read_all_stats; +-- Revoke the session-local SRF itself, not just the view, so a role that +-- can enable trace cannot read its own ring via the function and bypass +-- the view. +REVOKE EXECUTE ON FUNCTION pg_get_backend_wait_event_trace() FROM PUBLIC; +GRANT EXECUTE ON FUNCTION pg_get_backend_wait_event_trace() TO pg_read_all_stats; + +-- Cross-backend reader, keyed by procnumber (reads ACTIVE and ORPHANED +-- rings alike -- fix 3 -- tagging every row with owner_pid, the ring's +-- producer, live or, for an orphan, its last-known pid; see +-- pg_stat_clear_orphaned_wait_event_rings() below for the orphan +-- lifecycle). +CREATE FUNCTION pg_get_wait_event_trace( + procnumber int4, + OUT owner_pid int4, + OUT seq int8, + OUT timestamp_ns int8, + OUT wait_event_type text, + OUT wait_event text, + OUT duration_us float8, + OUT query_id int8, + OUT depth int4) +RETURNS SETOF record +AS 'MODULE_PATHNAME', 'pg_get_wait_event_trace' +LANGUAGE C VOLATILE PARALLEL RESTRICTED; +REVOKE EXECUTE ON FUNCTION pg_get_wait_event_trace(int4) FROM PUBLIC; +GRANT EXECUTE ON FUNCTION pg_get_wait_event_trace(int4) TO pg_read_all_stats; + +-- Administrative sweep (fix 3): free every trace ring whose owner has +-- exited. Cluster-scope and mutating, so -- like +-- pg_stat_reset_wait_event_timing_all() -- it is superuser-only in C and +-- NOT granted to pg_read_all_stats. +CREATE FUNCTION pg_stat_clear_orphaned_wait_event_rings() +RETURNS int8 +AS 'MODULE_PATHNAME', 'pg_stat_clear_orphaned_wait_event_rings' +LANGUAGE C VOLATILE; +REVOKE EXECUTE ON FUNCTION pg_stat_clear_orphaned_wait_event_rings() FROM PUBLIC; + +-- Query-attribution view over a procnumber's trace ring (fix 6). Each +-- statement's waits are summed per wait event into a bucket named by the +-- statement's opening marker. The rule, applied to the markers in seq +-- order: +-- +-- * Utility level L counts open top-level-or-nested utility statements: +-- UtilityStart adds one (after the marker), UtilityEnd subtracts one +-- but never below zero, Idle and TxnAbort reset it. TxnCommit does +-- not (a COMMIT inside a procedure leaves its CALL open). L at a +-- marker is the value before that marker is applied. A marker is +-- "top-level" when its depth is 0 and L is 0: statements run by a +-- DO block, a CALL, an EXECUTE or CREATE TABLE AS then belong to the +-- outer statement, whose UtilityStart does not raise the executor +-- depth but does raise L. +-- +-- * A top-level QueryStart always opens a statement bucket. A top-level +-- UtilityStart or ExecStart opens one unless the nearest preceding +-- marker among the top-level QueryStart/UtilityStart/ExecStart, Idle, +-- TxnCommit and TxnAbort is a top-level QueryStart or UtilityStart (that +-- statement is already open). So an EXECUTE of a prepared statement +-- over the extended protocol (ExecStart only, no QueryStart) opens a +-- bucket, and so does an ExecStart right after TxnCommit with no Idle +-- in between (the next message was already buffered), but a simple +-- query's QueryStart/ExecStart pair, or a plan revalidation, is one +-- bucket. +-- +-- * Idle and TxnAbort open the synthetic '' bucket. Waits before +-- the first of these or of an opener are ''. +-- +-- * Pre-statement phase. Between the arrival of a request and its +-- opening marker the backend can already wait: plan cache locks in +-- Bind, relation locks in parse analysis. Take an opener O and the +-- nearest closer C (Idle, TxnCommit or TxnAbort) before it; if no other +-- opener lies between them, the waits between C and O whose type is not +-- 'Client' belong to O, with phase 'pre'. Client waits (ClientRead and +-- the like) are idle time and stay in ''. +-- +-- * A request that fails before any statement starts (lock_timeout +-- during Bind, say) has the waits between its Idle and the following +-- TxnAbort or TxnCommit, with no opener in between and type other than +-- 'Client', in the synthetic '' bucket. +-- +-- * Every other wait stays in the bucket of the latest opener, Idle or +-- TxnAbort, so the waits after ExecEnd or TxnCommit but before Idle +-- (commit WAL flush) stay with their statement. +-- +-- Output column phase: 'pre' for the moved waits, 'statement' for the +-- rest of a statement bucket, NULL for the synthetic buckets. +-- Every non-'Query' record in the ring is counted exactly once. +-- +-- Known ambiguities: with no commit between two statements of an +-- explicit transaction or pipeline, waits between the end of one +-- statement and the start marker of the next stay with the earlier one; +-- when the next request was already buffered (no Idle), end-of- +-- transaction work after TxnCommit counts as the next statement's 'pre' +-- phase; an error caught by a PL/pgSQL EXCEPTION block inside a utility +-- statement can leave L too high until the next Idle or TxnAbort, which +-- folds later statements of that top-level statement's call into it; and +-- two Parse messages pipelined ahead of their Executes (QueryStart, +-- QueryStart, ExecStart, ExecStart) attribute the first Execute to the +-- second Parse. +-- +-- Grants match the underlying pg_get_wait_event_trace(): PUBLIC revoked, +-- pg_read_all_stats granted (this is a read-only view over the same +-- data, just pre-aggregated). +CREATE FUNCTION pg_wait_event_trace_by_statement( + procnumber int4, + OUT bucket text, + OUT statement_seq int8, + OUT query_id int8, + OUT phase text, + OUT wait_event_type text, + OUT wait_event text, + OUT calls int8, + OUT total_time_us float8) +RETURNS SETOF record +LANGUAGE SQL +VOLATILE +PARALLEL RESTRICTED +AS $$ +WITH trace AS ( + SELECT seq, wait_event_type, wait_event, duration_us, query_id, depth, + (wait_event_type = 'Query') AS is_marker + FROM pg_get_wait_event_trace(procnumber) +), +-- Utility level L: a running sum clamped at zero, restarted at every +-- Idle/TxnAbort. For a walk clamped at zero, L = P - min(0, min P) where P +-- is the plain running sum. +lvl1 AS ( + SELECT t.*, + count(*) FILTER (WHERE is_marker AND wait_event IN ('Idle', 'TxnAbort')) + OVER (ORDER BY seq ROWS UNBOUNDED PRECEDING) AS ugrp, + CASE WHEN is_marker AND wait_event = 'UtilityStart' THEN 1 + WHEN is_marker AND wait_event = 'UtilityEnd' THEN -1 + ELSE 0 END AS dl + FROM trace t +), +lvl2 AS ( + SELECT l.*, + sum(dl) OVER (PARTITION BY ugrp ORDER BY seq ROWS UNBOUNDED PRECEDING) AS p + FROM lvl1 l +), +lvl3 AS ( + SELECT l.*, + p - least(0, min(p) OVER (PARTITION BY ugrp ORDER BY seq + ROWS UNBOUNDED PRECEDING)) AS l_after + FROM lvl2 l +), +lvl4 AS ( + SELECT l.*, + coalesce(lag(l_after) OVER (PARTITION BY ugrp ORDER BY seq), 0) AS l_before + FROM lvl3 l +), +kinds AS ( + SELECT seq, wait_event_type, wait_event, duration_us, query_id, is_marker, + (is_marker AND wait_event IN ('Idle', 'TxnCommit', 'TxnAbort')) AS is_closer, + CASE WHEN is_marker AND depth = 0 AND l_before = 0 + THEN CASE wait_event WHEN 'QueryStart' THEN 'QS' + WHEN 'UtilityStart' THEN 'US' + WHEN 'ExecStart' THEN 'ES' END + END AS start_kind, + CASE WHEN is_marker AND wait_event IN ('Idle', 'TxnCommit', 'TxnAbort') + THEN wait_event END AS closer_kind + FROM lvl4 +), +-- The marker immediately before each reference marker (top-level start or +-- closer), among reference markers only. +refs AS ( + SELECT seq, + lag(coalesce(start_kind, closer_kind)) OVER (ORDER BY seq) AS prev_ref + FROM kinds + WHERE start_kind IS NOT NULL OR closer_kind IS NOT NULL +), +opened AS ( + SELECT k.*, + (k.start_kind = 'QS' + OR (k.start_kind IN ('US', 'ES') + AND coalesce(r.prev_ref, '') NOT IN ('QS', 'US'))) AS is_opener, + (k.is_marker AND k.wait_event IN ('Idle', 'TxnAbort')) AS is_idle_open + FROM kinds k + LEFT JOIN refs r USING (seq) +), +-- bucket_group numbers the v11-style buckets (latest opener/Idle/TxnAbort); +-- cl_in/cl_ex number the closer-delimited segments, counting the closer +-- itself as the end (cl_ex) or the start (cl_in) of its segment. +grouped AS ( + SELECT o.*, + count(*) FILTER (WHERE is_opener OR is_idle_open) + OVER (ORDER BY seq ROWS UNBOUNDED PRECEDING) AS bucket_group, + count(*) FILTER (WHERE is_closer) + OVER (ORDER BY seq ROWS UNBOUNDED PRECEDING) AS cl_in + FROM opened o +), +seg AS ( + SELECT g.*, + cl_in - (CASE WHEN is_closer THEN 1 ELSE 0 END) AS cl_ex + FROM grouped g +), +seg2 AS ( + SELECT s.*, + min(bucket_group) FILTER (WHERE is_opener) OVER (PARTITION BY cl_ex) + AS seg_opener_group, + min(seq) FILTER (WHERE is_opener) OVER (PARTITION BY cl_ex) + AS seg_opener_seq, + max(closer_kind) OVER (PARTITION BY cl_in) AS seg_start_kind, + max(closer_kind) OVER (PARTITION BY cl_ex) AS seg_end_kind + FROM seg s +), +assigned AS ( + SELECT s.*, + CASE + WHEN NOT is_marker AND wait_event_type <> 'Client' + AND cl_ex >= 1 AND seg_opener_seq > seq + THEN seg_opener_group + WHEN NOT is_marker AND wait_event_type <> 'Client' + AND seg_start_kind = 'Idle' AND seg_opener_seq IS NULL + AND seg_end_kind IN ('TxnAbort', 'TxnCommit') + THEN -1 + ELSE bucket_group + END AS eff_group, + coalesce(NOT is_marker AND wait_event_type <> 'Client' + AND cl_ex >= 1 AND seg_opener_seq > seq, false) AS is_pre + FROM seg2 s +), +bucket_labels AS ( + SELECT bucket_group, + seq AS statement_seq, + query_id AS bucket_query_id, + is_idle_open + FROM assigned + WHERE is_opener OR is_idle_open +) +SELECT + CASE + WHEN a.eff_group = -1 THEN '' + WHEN a.eff_group = 0 THEN '' + WHEN bl.is_idle_open THEN '' + ELSE bl.statement_seq::text + END AS bucket, + CASE WHEN NOT bl.is_idle_open THEN bl.statement_seq END AS statement_seq, + CASE WHEN NOT bl.is_idle_open THEN bl.bucket_query_id END AS query_id, + CASE WHEN a.eff_group > 0 AND NOT bl.is_idle_open + THEN CASE WHEN a.is_pre THEN 'pre' ELSE 'statement' END + END AS phase, + a.wait_event_type, + a.wait_event, + count(*) AS calls, + sum(a.duration_us) AS total_time_us +FROM assigned a +LEFT JOIN bucket_labels bl ON bl.bucket_group = a.eff_group +WHERE NOT a.is_marker +GROUP BY a.eff_group, bl.statement_seq, bl.bucket_query_id, bl.is_idle_open, + (a.is_pre), a.wait_event_type, a.wait_event +ORDER BY min(a.seq), a.wait_event_type, a.wait_event; +$$; +REVOKE EXECUTE ON FUNCTION pg_wait_event_trace_by_statement(int4) FROM PUBLIC; +GRANT EXECUTE ON FUNCTION pg_wait_event_trace_by_statement(int4) TO pg_read_all_stats; + -- The histogram bucket boundaries are a constant lookup table, and the -- per-class capacities are compile-time limits of this module; neither -- says anything about any session, so both stay readable by everyone, diff --git a/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c index 6839d352875..0c2fcffe522 100644 --- a/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c @@ -36,15 +36,29 @@ * slot from inside the begin hook itself (see the claim protocol below), * without allocating, locking, waiting, or erroring. * - * This file carries the statistics level only. The trace level (per-backend - * ring buffer, query markers, trace SRFs) is a separate patch; the slot - * layout below reserves the fields that level will need (trace_ptr, - * trace_state) so that addition does not reshape the control segment. + * This file also carries the trace level (pg_wait_event_tracing.capture = + * trace): a per-backend ring buffer of individual completed waits and + * query-attribution markers, addressed through the same control segment + * (PwetSlot's trace_ptr/trace_state/trace_owner_pid/trace_owner_start + * fields) and allocated in its own DSA area (GetNamedDSA()), lazily, only + * for a backend that enables trace. Trace attach/detach/orphan-reclaim + * always happens at the same safe points as stats attach (the assign hook + * or the post_parse_analyze/ExecutorStart hooks); the begin/end wait hooks + * only ever append an already-allocated ring, lock-free, single-writer, + * exactly like the stats hot path. Query markers are covered in the + * comment on the marker state machine further down. + * + * Trace is not covered by the server-process fixed-memory region (see the + * comment above): a per-server-process ring would cost several MiB each, + * so a server-side process starts tracing only at the first configuration + * reload with capture = trace, via the DSA path in the assign hook, same + * as any client backend's assign-hook attach. * *------------------------------------------------------------------------- */ #include "postgres.h" +#include "access/xact.h" #include "catalog/pg_authid.h" #include "catalog/pg_type_d.h" #include "executor/executor.h" @@ -66,6 +80,7 @@ #include "storage/procarray.h" #include "storage/procnumber.h" #include "storage/shmem.h" +#include "tcop/utility.h" #include "utils/acl.h" #include "utils/array.h" #include "utils/backend_status.h" @@ -90,6 +105,9 @@ PG_FUNCTION_INFO_V1(pg_stat_reset_wait_event_timing); PG_FUNCTION_INFO_V1(pg_stat_reset_wait_event_timing_all); PG_FUNCTION_INFO_V1(pg_wait_event_tracing_capacity); PG_FUNCTION_INFO_V1(pg_wait_event_tracing_hooks_installed); +PG_FUNCTION_INFO_V1(pg_get_backend_wait_event_trace); +PG_FUNCTION_INFO_V1(pg_get_wait_event_trace); +PG_FUNCTION_INFO_V1(pg_stat_clear_orphaned_wait_event_rings); PGDLLEXPORT void _PG_init(void); @@ -98,6 +116,7 @@ PGDLLEXPORT void _PG_init(void); #define PWET_REGION_HEADER_NAME "pg_wait_event_tracing header" #define PWET_SERVER_REGION_NAME "pg_wait_event_tracing server processes" #define PWET_STATS_DSA_NAME "pg_wait_event_tracing_stats" +#define PWET_TRACE_DSA_NAME "pg_wait_event_tracing_trace" #define PWET_NUM_SLOTS (MaxBackends + NUM_AUXILIARY_PROCS) /* @@ -121,15 +140,45 @@ PGDLLEXPORT void _PG_init(void); has_privs_of_role(GetUserId(), role)) /* - * Reserved trace_state values. The trace-level patch adds ACTIVE and - * ORPHANED; this module only ever produces FREE. + * trace_state values (PwetSlot.trace_state). + * + * FREE no ring allocated (trace_ptr invalid). + * ACTIVE a live process is writing to the ring (trace_owner_pid/start + * identify it). + * ORPHANED the owner exited; the ring is post-mortem and immutable, + * kept readable until a successor reclaims it or an + * administrator sweeps it (pg_stat_clear_orphaned_wait_event_ + * rings()). */ #define PWET_TRACE_FREE 0 +#define PWET_TRACE_ACTIVE 1 +#define PWET_TRACE_ORPHANED 2 + +/* + * Trace record type tags (PwetTraceRecord.record_type). Numeric values + * for WAIT/QUERY_START/EXEC_START/EXEC_END are kept where the peer-review + * package already used them (see wp3-trace-parts-from-package.c.txt); the + * package's QUERY_END has no v8 equivalent (v8 closes a statement's + * interval with ExecEnd/UtilityEnd/TxnCommit/TxnAbort/Idle instead, per + * the marker state machine below), so its value (2) is left unused rather + * than reassigned. UTILITY_START/END, TXN_COMMIT/ABORT and IDLE are new + * in v8 (plan sec 5.3, fix 6). + */ +#define PWET_TRACE_WAIT 0 +#define PWET_TRACE_QUERY_START 1 +#define PWET_TRACE_EXEC_START 3 +#define PWET_TRACE_EXEC_END 4 +#define PWET_TRACE_UTILITY_START 5 +#define PWET_TRACE_UTILITY_END 6 +#define PWET_TRACE_TXN_COMMIT 7 +#define PWET_TRACE_TXN_ABORT 8 +#define PWET_TRACE_IDLE 9 typedef enum PwetCaptureLevel { PWET_CAPTURE_OFF = 0, PWET_CAPTURE_STATS, + PWET_CAPTURE_TRACE, } PwetCaptureLevel; typedef struct PwetTimingEntry @@ -177,18 +226,71 @@ typedef struct PwetStats int64 flat_overflow_count; } PwetStats; +/* + * One trace ring record: 32 bytes, seqlock-protected (single writer, the + * owning backend; lock-free readers use the position-encoded identity + * check described on emit_wait_event_trace_for_procnumber()). record_type + * selects which half of the union is meaningful: + * + * PWET_TRACE_WAIT data.wait: a completed wait (event, duration) + * everything else data.marker: a query-attribution marker + * (query_id, and for EXEC_START/EXEC_END the + * executor nesting depth; 0 for the rest) + * + * Field layout and the seqlock protocol are ported from the peer-review + * package (wp3-trace-parts-from-package.c.txt); only the second union arm + * is renamed/repurposed (query.pad2 -> marker.depth) to carry the nesting + * depth the v8 marker set needs, without changing the record size. + */ +typedef struct PwetTraceRecord +{ + uint32 seq; + uint8 record_type; + uint8 pad[3]; + int64 timestamp_ns; + union + { + struct + { + uint32 event; + uint32 pad2; + int64 duration_ns; + } wait; + struct + { + int64 query_id; + int64 depth; + } marker; + } data; +} PwetTraceRecord; + +StaticAssertDecl(sizeof(PwetTraceRecord) == 32, + "PwetTraceRecord must be exactly 32 bytes"); + +/* + * Per-backend trace ring: header plus a runtime-sized records[] array + * (row count decided by pg_wait_event_tracing.trace_ring_size, PGC_POSTMASTER, + * so every ring in this postmaster run has the same dimensions). + */ +typedef struct PwetTraceState +{ + pg_atomic_uint64 write_pos; + uint32 ring_mask; + uint32 pad; + PwetTraceRecord records[FLEXIBLE_ARRAY_MEMBER]; +} PwetTraceState; + /* * One entry per possible ProcNumber, always resident in the control - * segment. trace_ptr/trace_state are unused placeholders reserved for the - * trace-level patch. + * segment. * * owner_pid/owner_start identify the process that currently owns the - * payload (stats_ptr for a client backend; the matching slice of the fixed - * server-process region -- see below -- for a server-side process): every - * reader compares them against the live PgBackendStatus entry for this - * ProcNumber and ignores the slot on a mismatch, so a successor that has - * not (yet) claimed its own payload never gets attributed a predecessor's - * counters. + * stats payload (stats_ptr for a client backend; the matching slice of the + * fixed server-process region -- see below -- for a server-side process): + * every stats reader compares them against the live PgBackendStatus entry + * for this ProcNumber and ignores the slot on a mismatch, so a successor + * that has not (yet) claimed its own payload never gets attributed a + * predecessor's counters. * * A client backend publishes owner_pid/owner_start under pwet_lock, * alongside stats_ptr; a server-side process instead publishes them @@ -199,16 +301,32 @@ typedef struct PwetStats * pwet_request_reset()) can be tied atomically to the owner token that * authorizes it, and so the owning process can later notice it with a * lock-free read (see pwet_wait_end()). + * + * trace_ptr/trace_state/trace_owner_pid/trace_owner_start are the trace + * level's own, independent ownership token for this ProcNumber's ring -- + * deliberately NOT shared with owner_pid/owner_start above. The two + * lifecycles differ: on exit, the stats payload is freed outright + * (pwet_release_stats() clears owner_pid/owner_start), but the trace ring + * is orphaned, not freed -- state becomes ORPHANED and trace_owner_pid/ + * start are RETAINED so a post-mortem reader can still attribute the ring + * to its producer even after a successor has already claimed this + * ProcNumber's stats slot (see pwet_orphan_trace()/pwet_attach_trace()). + * Sharing owner_pid/owner_start between the two would make the successor's + * ordinary stats attach silently reattribute the predecessor's still- + * orphaned trace ring to itself. */ typedef struct PwetSlot { dsa_pointer stats_ptr; /* InvalidDsaPointer when not collecting */ - dsa_pointer trace_ptr; /* reserved for the trace level */ - uint8 trace_state; /* reserved for the trace level */ + dsa_pointer trace_ptr; /* InvalidDsaPointer when trace_state == FREE */ + uint8 trace_state; /* PWET_TRACE_FREE/ACTIVE/ORPHANED */ int owner_pid; /* 0 when unowned */ TimestampTz owner_start; /* MyStartTimestamp of the owner */ pg_atomic_uint32 generation; /* bumped on every ownership change */ pg_atomic_uint32 reset_generation; /* bumped by a reset request */ + int trace_owner_pid; /* producer of trace_ptr's ring, live or + * dead; 0 when trace_state == FREE */ + TimestampTz trace_owner_start; } PwetSlot; /* @@ -233,33 +351,107 @@ typedef struct PwetRegionHeader static const struct config_enum_entry pwet_capture_options[] = { {"off", PWET_CAPTURE_OFF, false}, {"stats", PWET_CAPTURE_STATS, false}, + {"trace", PWET_CAPTURE_TRACE, false}, {NULL, 0, false} }; static int pwet_capture = PWET_CAPTURE_OFF; static int pwet_max_tranches = 192; +/* + * Per-backend trace ring size in KB (same default/min/max/unit as v6's + * wait_event_trace_ring_size). PGC_POSTMASTER: every backend in this + * postmaster run, including an EXEC_BACKEND child re-running _PG_init(), + * ends up with the identical final value (latched at postmaster start, + * unlike pwet_capture), so pwet_trace_records_per_ring below is safe to + * (re)derive independently in every process -- there is no "decision made + * in the postmaster that a child must read back" here, unlike the + * server-process region's presence/bounds (see PwetRegionHeader). + */ +static int pwet_trace_ring_size = 4096; + +/* + * GUC check hook for trace_ring_size: the ring's record count must be a + * power of two for the writer's mask-indexing (pos & ring_mask). Each + * record is 32 bytes, so kb is a power of two iff the record count is. + */ +static bool +pwet_check_trace_ring_size(int *newval, void **extra, GucSource source) +{ + int v = *newval; + + if (v <= 0 || (v & (v - 1)) != 0) + { + GUC_check_errdetail("pg_wait_event_tracing.trace_ring_size must be a positive power of two."); + return false; + } + return true; +} + /* * guc.c's set_config_with_handle() calls a PGC_ENUM variable's assign_hook * BEFORE storing the new value (assign_hook(newval, newextra) precedes * *conf->variable = newval), so pwet_capture is still the *old* value for - * the whole duration of pwet_assign_capture(). A client backend hides - * this: pwet_maybe_attach() also runs from post_parse_analyze_hook / - * ExecutorStart_hook on the next statement, by which point pwet_capture - * has long since been updated. A server-side process has no "next - * statement": with the reserved region absent it depends entirely on the - * assign hook's own synchronous pwet_maybe_attach() call to attach via - * DSA, and with the region present a released fixed slot depends on - * pwet_wait_begin() re-claiming -- which does not go through + * the whole duration of pwet_assign_capture(), including every function it + * calls synchronously (pwet_maybe_attach() and everything that reaches from + * there). pwet_capture_effective mirrors pwet_capture except that + * pwet_assign_capture() updates it first, so code that needs the value + * capture is *becoming* -- not the value that is (still, momentarily) + * current -- can see it. + * + * THE RULE, stated once here for every call site to follow (found the hard + * way: CI run 34703751075 showed the trace regress test recording nothing + * for an entire session, root-caused to exactly one site below getting this + * backwards -- see pwet_maybe_attach()'s comment for the full story): + * + * - An ATTACH decision -- may this process allocate/publish a stats + * payload or a trace ring right now -- tests pwet_capture_effective. + * pwet_can_attach(), pwet_can_attach_trace(), and pwet_maybe_attach()'s + * own trace branch all do. Getting this wrong makes an attach + * triggered by "SET ... = trace" itself silently skip attaching (the + * assign hook sees the stale old value), and if the caller then also + * clears pwet_attach_needed unconditionally, nothing ever retries for + * the rest of the session. + * - A RECORDING decision -- given an already-attached payload, should + * this hook or marker writer actually write to it right now -- tests + * pwet_capture itself, EXCEPT for the wait-event begin/end hooks (see + * below). pwet_trace_write_marker(), and the post_parse_analyze/ + * ExecutorStart/ExecutorEnd/ProcessUtility hooks and the xact + * callback, all do this deliberately: none of them are ever invoked + * synchronously from inside pwet_assign_capture(), so pwet_capture is + * always fully current by the time they run, and recording must + * never start or stop based on a value that has not actually taken + * effect yet. + * + * pwet_wait_begin()/pwet_wait_end() are the one exception: they test + * pwet_rec_stats/pwet_rec_trace (see pwet_update_rec_pointers()), + * which ARE derived from pwet_capture_effective, because -- unlike + * every other recording site above -- these two CAN run synchronously + * from inside pwet_assign_capture(): pwet_maybe_attach() reaches + * pwet_attach_stats()/pwet_attach_trace(), and both take an LWLock, + * itself a timed wait. Testing the stale, stored pwet_capture there + * would just move the "recording starts before the SET has taken + * effect" bug from this file's history (see the CI-run story above) + * onto the exact same values used for attach decisions. Instead, + * pwet_assign_capture() masks pwet_stats_writes_disabled/ + * pwet_trace_writes_disabled for its own duration, so + * pwet_rec_stats/pwet_rec_trace answer exactly what testing the + * stored pwet_capture would have -- see pwet_assign_capture()'s own + * comment for the precise masking rule. + * + * A server-side process is why this matters at all: it has no "next + * statement" to paper over a missed attach the way a client backend would + * (pwet_maybe_attach() also runs from post_parse_analyze_hook/ + * ExecutorStart_hook, which a client backend reaches again almost + * immediately, by which point pwet_capture has long since been updated). + * With the reserved region absent, a server-side process depends entirely + * on the assign hook's own synchronous pwet_maybe_attach() call to attach + * via DSA; with the region present, a released fixed slot depends on + * pwet_wait_begin() re-claiming, which does not go through * pwet_can_attach() at all, but the DSA fallback does, and a stale * pwet_capture there would make pwet_can_attach() see the old (often OFF) * value and refuse forever, since nothing else ever retries it for such a - * process. pwet_capture_effective mirrors pwet_capture except that - * pwet_assign_capture() updates it first, so pwet_can_attach() -- the - * only place this matters -- always sees the value capture is *becoming*. - * The begin/end hooks deliberately keep testing pwet_capture itself (see - * pwet_wait_begin()/pwet_wait_end()), so recording never starts or stops - * based on a value that has not actually taken effect yet. + * process. */ static int pwet_capture_effective = PWET_CAPTURE_OFF; @@ -362,23 +554,58 @@ typedef struct PwetPendingWait static PwetPendingWait pwet_pending; static bool pwet_pending_valid; +static dsa_area *pwet_trace_dsa; +static PwetTraceState *pwet_my_trace; + +/* + * Records per ring, derived from pwet_trace_ring_size on first use and + * cached (PGC_POSTMASTER, so the value is the same in every process for + * the life of this postmaster run; see pwet_trace_ring_size's comment). + */ +static uint32 pwet_trace_records_per_ring; + static bool pwet_active; static bool pwet_attach_needed; static bool pwet_exit_started; static bool pwet_stats_writes_disabled; +static bool pwet_trace_writes_disabled; static bool pwet_exit_callback_registered; +static bool pwet_xact_callback_registered; /* - * The recording gate for the stats level, maintained by + * The single recording gate for each of the two levels, maintained by * pwet_update_rec_pointers() from the inputs above (plus * pwet_capture_effective): non-NULL if and only if this backend should * actually record right now. pwet_wait_begin_impl()/pwet_wait_end_impl() - * test only this, instead of re-deriving the same three-way test (capture - * level, the writes-disabled flag, and the payload pointer) on every - * wait; see pwet_update_rec_pointers()'s own comment for the exact + * test only these, instead of re-deriving the same three-way test + * (capture level, the writes-disabled flag, and the payload pointer) on + * every wait; see pwet_update_rec_pointers()'s own comment for the exact * equivalence and why it is safe. */ static PwetStats *pwet_rec_stats; +static PwetTraceState *pwet_rec_trace; + +/* + * Query-marker state machine (plan sec 5.3, fix 6), per backend, advanced + * only while capture == trace. Never touched by any hook the postmaster + * itself runs (post_parse_analyze/ExecutorStart/ExecutorEnd/ + * ProcessUtility/the xact callback all fire only in a real backend), so + * this cannot be a case of the usual postmaster/fork trap: + * pwet_marker_state simply never leaves its zero-valued + * initial state (PWET_MARKER_IDLE) before any fork(), which is also the + * correct starting state for a freshly forked child. See the comment on + * pwet_marker_query_start() and friends, further down, for the + * transition rules themselves. + */ +typedef enum PwetMarkerState +{ + PWET_MARKER_IDLE = 0, + PWET_MARKER_OPEN, + PWET_MARKER_AFTER_STATEMENT, +} PwetMarkerState; + +static PwetMarkerState pwet_marker_state = PWET_MARKER_IDLE; +static int pwet_exec_depth; /* * Per-process, computed at most once per process (see pwet_wait_begin()): @@ -420,6 +647,8 @@ static bool pwet_wait_hooks_installed; static post_parse_analyze_hook_type prev_post_parse_analyze_hook; static ExecutorStart_hook_type prev_ExecutorStart_hook; +static ExecutorEnd_hook_type prev_ExecutorEnd_hook; +static ProcessUtility_hook_type prev_ProcessUtility_hook; static shmem_request_hook_type prev_shmem_request_hook; static shmem_startup_hook_type prev_shmem_startup_hook; @@ -442,6 +671,12 @@ static bool pwet_is_fixed_procnumber(int procnumber); static PwetStats *pwet_fixed_payload(int procnumber); static void pwet_claim_fixed_slot(void); static void pwet_release_fixed_slot(void); +static bool pwet_ensure_trace_dsa(void); +static bool pwet_attach_trace(void); +static void pwet_release_trace(void); +static void emit_wait_event_trace(int procnumber, ReturnSetInfo *rsinfo); +static void pwet_orphan_trace(void); +static void pwet_xact_callback(XactEvent event, void *arg); static Size pwet_control_size(int nslots) @@ -593,6 +828,8 @@ pwet_control_init(PwetSlot *slots) slots[i].owner_start = 0; pg_atomic_init_u32(&slots[i].generation, 0); pg_atomic_init_u32(&slots[i].reset_generation, 0); + slots[i].trace_owner_pid = 0; + slots[i].trace_owner_start = 0; } } @@ -795,17 +1032,42 @@ pwet_fixed_payload(int procnumber) pwet_server_stride); } +/* + * Is this process at a point where attaching anything (allocating, + * locking, erroring) is safe? Identity- and mode-related only -- says + * nothing about whether capture wants an attach at all, or which of the + * two payload paths (DSA vs. the fixed server-process region) applies. + * Shared by pwet_can_attach() (the DSA stats path) and + * pwet_can_attach_trace(): both need exactly this, plus their own + * capture-level and path-specific tests layered on top. + */ static bool -pwet_can_attach(void) +pwet_at_safe_point(void) { - /* See pwet_capture_effective's comment for why this, not pwet_capture. */ - if (pwet_exit_started || !pwet_active || - pwet_capture_effective == PWET_CAPTURE_OFF) + if (pwet_exit_started || !pwet_active) return false; if (MyProc == NULL || MyProcNumber == INVALID_PROC_NUMBER) return false; if (MyProcNumber < 0 || MyProcNumber >= PWET_NUM_SLOTS) return false; + if (!IsNormalProcessingMode() || CritSectionCount > 0) + return false; + if (MyProc->lwWaiting != LW_WS_NOT_WAITING) + return false; + return true; +} + +/* + * May this process take the DSA stats path right now? See + * pwet_capture_effective's comment for why that, not pwet_capture. + */ +static bool +pwet_can_attach(void) +{ + if (!pwet_at_safe_point()) + return false; + if (pwet_capture_effective == PWET_CAPTURE_OFF) + return false; /* * A ProcNumber inside the reserved region never takes the DSA path @@ -816,36 +1078,62 @@ pwet_can_attach(void) * pwet_is_fixed_procnumber() call sites), so anything recorded there * would silently never be shown. When the region does not exist * (capture was off at postmaster start), this is unreachable and - * today's DSA-at-next-reload behaviour is unchanged. + * today's DSA-at-next-reload behaviour is unchanged. This is why + * this test is here, not folded into pwet_at_safe_point(): a + * fixed-region process IS at a safe point (it can still attach + * trace, which never uses this region -- see pwet_can_attach_trace()), + * it just may not use the DSA stats path. */ if (pwet_is_fixed_procnumber(MyProcNumber)) return false; - if (!IsNormalProcessingMode() || CritSectionCount > 0) + return true; +} + +/* + * May this process attach (or reclaim) a trace ring right now? Trace + * never uses the fixed server-process region (plan sec 4.2a/5.2's own + * scope note), so unlike pwet_can_attach() there is no fixed-procnumber + * exclusion here -- a fixed-slot process is exactly as eligible for the + * (always-DSA) trace path as any client backend, PROVIDED it already has + * a ProcNumber identity established (pwet_my_procno), which for such a + * process only the begin hook's pwet_claim_fixed_slot() can set (this + * function is only ever called from safe points, never the hook itself, + * so it cannot establish that identity on its own). + */ +static bool +pwet_can_attach_trace(void) +{ + if (!pwet_at_safe_point()) return false; - if (MyProc->lwWaiting != LW_WS_NOT_WAITING) + if (pwet_capture_effective != PWET_CAPTURE_TRACE) + return false; + if (pwet_my_procno == INVALID_PROC_NUMBER) return false; return true; } /* - * Recompute pwet_rec_stats, the single recording-gate pointer for the - * stats level, from its three inputs. Called at every site that assigns - * any of pwet_capture_effective, pwet_stats_writes_disabled, or - * pwet_my_stats (find them all with: - * grep -n 'pwet_stats_writes_disabled =\|pwet_my_stats =\|pwet_capture_effective =' - * ), so the pointer is never stale by the time pwet_wait_begin_impl()/ - * pwet_wait_end_impl() next read it. + * Recompute pwet_rec_stats/pwet_rec_trace, the single recording-gate + * pointer for each level, from their six inputs. Called at every site + * that assigns any of pwet_capture_effective, pwet_stats_writes_disabled, + * pwet_my_stats, pwet_trace_writes_disabled, or pwet_my_trace (find them + * all with: + * grep -n 'pwet_stats_writes_disabled =\|pwet_trace_writes_disabled =\|pwet_my_stats =\|pwet_my_trace =\|pwet_capture_effective =' + * ), so the pointers are never stale by the time pwet_wait_begin_impl()/ + * pwet_wait_end_impl() next read them. * * pwet_rec_stats is non-NULL exactly when a test against the STORED * pwet_capture -- (pwet_capture != OFF, !pwet_stats_writes_disabled, - * pwet_my_stats != NULL) -- would answer yes. This function computes it - * from pwet_capture_effective, the "becoming" value, not from - * pwet_capture, the stored one -- deliberately, so the assign hook - * itself, which sets pwet_capture_effective before guc.c stores the new - * value, can call this function and get the right in-progress answer, - * exactly like every other attach decision (see pwet_capture_effective's - * own comment). + * pwet_my_stats != NULL) -- would answer yes; pwet_rec_trace, exactly + * when the equivalent trace-specific test (pwet_capture == TRACE, + * !pwet_trace_writes_disabled, pwet_my_trace != NULL) would. This + * function computes both from pwet_capture_effective, the "becoming" + * value, not from pwet_capture, the stored one -- deliberately, so the + * assign hook itself, which sets pwet_capture_effective before guc.c + * stores the new value, can call this function and get the right + * in-progress answer, exactly like every other attach decision (see + * pwet_capture_effective's own comment). * * Outside the assign hook's own synchronous call chain, * pwet_capture_effective == pwet_capture always (guc.c has, by then, @@ -854,18 +1142,18 @@ pwet_can_attach(void) * is NOT merely academic: pwet_wait_begin_impl()/pwet_wait_end_impl() can * run synchronously from inside it, because pwet_maybe_attach() (called * from pwet_assign_capture() when capture is becoming non-off) reaches - * pwet_attach_stats(), which takes an LWLock to publish the new payload -- - * itself a timed wait. Naively deriving the gate from - * pwet_capture_effective there would start recording mid-assign-hook, - * before the SET has actually taken effect (e.g. "off -> stats" would - * count the attach's own LWLock wait). pwet_assign_capture() is what - * keeps this function's answer correct in that window too: it masks - * pwet_stats_writes_disabled, for its own duration only, to reproduce - * exactly what testing the STORED value would have answered (see its own - * comment for the precise rule and why). This function does not need to - * know, from its inputs alone, whether it is being called from inside - * that masked window -- the masking is what makes the answer right - * either way. + * pwet_attach_stats()/pwet_attach_trace(), and both take an LWLock to + * publish the new payload/ring -- itself a timed wait. Naively deriving + * the gate from pwet_capture_effective there would start recording + * mid-assign-hook, before the SET has actually taken effect (e.g. "off -> + * stats" would count the attach's own LWLock wait). pwet_assign_capture() + * is what keeps this function's answer correct in that window too: it + * masks pwet_stats_writes_disabled/pwet_trace_writes_disabled, for its + * own duration only, to reproduce exactly what testing the STORED value + * would have answered (see its own comment for the precise rule and + * why). This function does not need to know, from its five inputs + * alone, whether it is being called from inside that masked window -- + * the masking is what makes the answer right either way. * * The set of recorded waits is therefore unchanged, byte for byte, in * both cases: outside the chain by the pwet_capture_effective == @@ -878,6 +1166,11 @@ pwet_update_rec_pointers(void) !pwet_stats_writes_disabled && pwet_my_stats != NULL) ? pwet_my_stats : NULL; + + pwet_rec_trace = (pwet_capture_effective == PWET_CAPTURE_TRACE && + !pwet_trace_writes_disabled && + pwet_my_trace != NULL) + ? pwet_my_trace : NULL; } /* @@ -942,6 +1235,27 @@ pwet_claim_fixed_slot(void) pwet_my_procno = MyProcNumber; pwet_last_reset_generation = pg_atomic_read_u32(&slot->reset_generation); pwet_update_rec_pointers(); + + /* + * Register here too, not only in pwet_maybe_attach(): a fixed-slot + * process's stats "attach" is entirely this function, called from the + * begin hook -- a code path pwet_maybe_attach() (the assign hook or + * post_parse_analyze/ExecutorStart) never drives for such a process, + * so if this is skipped, only a later successful trace attach via + * pwet_maybe_attach() would ever register it, leaving a window in + * which this process's fixed-slot stats have no exit cleanup at all. + * The pwet_exit_callback_registered guard makes registering from both + * places safe (whichever runs first wins; the other is a no-op). + * Safe to call from the begin hook: before_shmem_exit() only writes + * into ipc.c's fixed-size before_shmem_exit_list[] array (MAX_ON_EXITS + * slots) -- no allocation, no lock, no ereport on the non-full path, + * so it obeys the hook's rules. + */ + if (!pwet_exit_callback_registered) + { + before_shmem_exit(pwet_before_shmem_exit, (Datum) 0); + pwet_exit_callback_registered = true; + } } /* @@ -980,6 +1294,381 @@ pwet_release_fixed_slot(void) } } +/* + * Lazily attach this backend to the trace DSA area, exactly like + * pwet_ensure_stats_dsa() but for the trace ring; a separate named DSA + * area so trace's much larger per-backend footprint (a few MiB versus + * ~200 KiB for stats) is a distinct GetNamedDSA() consumer from stats. + */ +static bool +pwet_ensure_trace_dsa(void) +{ + bool found; + + if (pwet_trace_dsa != NULL) + return true; + + pwet_trace_dsa = GetNamedDSA(PWET_TRACE_DSA_NAME, &found); + return pwet_trace_dsa != NULL; +} + +/* + * Attach this backend's trace ring, at a safe point (assign hook or + * post_parse_analyze/ExecutorStart -- see pwet_maybe_attach()), never from + * the begin/end wait hooks. Requires stats identity to already be + * established (pwet_my_procno set, by whichever mechanism -- DSA attach or + * the fixed-region claim -- pwet_maybe_attach() used): trace "implies + * stats" (plan sec 5.1), and this function only needs to know which + * control slot is ours, not how its stats payload got there. + * + * If the slot's trace_state is not FREE (ORPHANED from a predecessor that + * exited without anyone reclaiming it yet, or, defensively, an + * unexpected stale ACTIVE), the old ring is freed and replaced: since + * ProcNumbers are exclusively owned one process at a time and + * pwet_my_procno already identifies THIS process as the current + * occupant, any pre-existing ring at this slot can only belong to a + * predecessor, never a live peer -- see the comment on PwetSlot for why + * trace_owner_pid/start (not owner_pid/start) is what the predecessor's + * identity is read from before we overwrite it here. This is also + * where fix 3's orphan reclaim happens; nothing runs at backend init to + * do it earlier, so EXEC_BACKEND start order cannot matter (contrast + * v6's now-removed clear-orphan-at-init step). + */ +static bool +pwet_attach_trace(void) +{ + static bool in_attach; + PwetSlot *slot; + PwetTraceState *ts = NULL; + dsa_pointer ring_ptr = InvalidDsaPointer; + + if (pwet_my_trace != NULL) + return true; + if (in_attach || !pwet_can_attach_trace()) + return false; + + in_attach = true; + PG_TRY(); + { + if (pwet_ensure_trace_dsa()) + { + Size alloc_size; + + if (pwet_trace_records_per_ring == 0) + pwet_trace_records_per_ring = + (uint32) pwet_trace_ring_size * 1024U / + (uint32) sizeof(PwetTraceRecord); + + alloc_size = add_size(offsetof(PwetTraceState, records), + mul_size(pwet_trace_records_per_ring, + sizeof(PwetTraceRecord))); + ring_ptr = dsa_allocate_extended(pwet_trace_dsa, alloc_size, + DSA_ALLOC_ZERO | + DSA_ALLOC_NO_OOM); + if (DsaPointerIsValid(ring_ptr)) + { + ts = dsa_get_address(pwet_trace_dsa, ring_ptr); + pg_atomic_init_u64(&ts->write_pos, 0); + ts->ring_mask = pwet_trace_records_per_ring - 1; + + slot = &pwet_ctl[pwet_my_procno]; + LWLockAcquire(pwet_lock, LW_EXCLUSIVE); + if (DsaPointerIsValid(slot->trace_ptr)) + dsa_free(pwet_trace_dsa, slot->trace_ptr); + slot->trace_ptr = ring_ptr; + slot->trace_state = PWET_TRACE_ACTIVE; + slot->trace_owner_pid = MyProcPid; + slot->trace_owner_start = MyStartTimestamp; + pg_atomic_fetch_add_u32(&slot->generation, 1); + LWLockRelease(pwet_lock); + + pwet_my_trace = ts; + pwet_update_rec_pointers(); + + /* + * Fresh ring: restart the marker state machine so a + * previous trace session's leftover OPEN/AFTER_STATEMENT + * state (from an earlier enable/disable cycle on this same + * backend) can't misattribute the first waits of the new + * session. + */ + pwet_marker_state = PWET_MARKER_IDLE; + pwet_exec_depth = 0; + + /* + * Register once per backend, at first trace attach (a safe + * point): xact.c's callback list is a backend-local static + * array untouched by anything else this module does, so + * there is no reentrancy or allocation concern in calling + * this here. Left registered even across a later + * release/re-attach cycle (pwet_xact_callback() itself + * checks pwet_capture/pwet_my_trace on every call and is a + * cheap no-op otherwise), rather than calling + * UnregisterXactCallback() on release, to avoid growing + * churn in xact.c's list across many enable/disable cycles. + */ + if (!pwet_xact_callback_registered) + { + RegisterXactCallback(pwet_xact_callback, NULL); + pwet_xact_callback_registered = true; + } + } + } + } + PG_FINALLY(); + { + in_attach = false; + } + PG_END_TRY(); + + return pwet_my_trace != NULL; +} + +/* + * Release this backend's trace ring back to DSA immediately: called on a + * live step-down (capture moving away from trace while this process is + * still running -- see pwet_assign_capture()), never on process exit + * (exit orphans the ring instead; see pwet_orphan_trace(), added in the + * fix-3 commit). The operator has affirmatively disabled trace, so, + * like v6, we honour that and reclaim the memory immediately rather than + * leaving a multi-MiB ring pinned for the rest of the session. + * + * Flushes the pending wait, if any, before the ring is freed: a pending + * record's trace half can only be appended while pwet_my_trace still + * points at a live ring, so this is the last chance to write it (the + * stats half, if the payload is still attached, is unaffected by trace + * being released and is accounted the same way regardless). + */ +static void +pwet_release_trace(void) +{ + PwetSlot *slot; + ProcNumber procno = pwet_my_procno; + bool was_disabled = pwet_trace_writes_disabled; + + pwet_flush_pending(); + + if (pwet_my_trace == NULL || pwet_trace_dsa == NULL || + procno == INVALID_PROC_NUMBER) + { + pwet_my_trace = NULL; + pwet_update_rec_pointers(); + return; + } + + pwet_trace_writes_disabled = true; + pwet_my_trace = NULL; + pwet_update_rec_pointers(); + slot = &pwet_ctl[procno]; + + LWLockAcquire(pwet_lock, LW_EXCLUSIVE); + if (DsaPointerIsValid(slot->trace_ptr)) + { + dsa_free(pwet_trace_dsa, slot->trace_ptr); + slot->trace_ptr = InvalidDsaPointer; + slot->trace_state = PWET_TRACE_FREE; + slot->trace_owner_pid = 0; + slot->trace_owner_start = 0; + pg_atomic_fetch_add_u32(&slot->generation, 1); + } + LWLockRelease(pwet_lock); + + if (!pwet_exit_started) + { + pwet_trace_writes_disabled = was_disabled; + pwet_update_rec_pointers(); + } +} + +/* + * Append one query-attribution marker record. Same seqlock protocol and + * hook-rule compliance as the wait-record writer in pwet_wait_end() (no + * allocation, no lock, no wait, no ereport): called from + * post_parse_analyze/ExecutorStart/ExecutorEnd/ProcessUtility -- all safe + * points already, so this is not strictly hook-restricted code, but the + * begin hook's Idle synthesis (see pwet_wait_begin()) reuses the very + * same function from inside the hook, so it is held to the hook's rules + * throughout for uniformity. + * + * query_id/depth: depth is meaningful only for EXEC_START/EXEC_END (see + * pwet_marker_exec_start()/pwet_marker_exec_end()); every other marker + * passes 0. query_id is whatever the caller has on hand -- 0 for a + * utility statement when compute_query_id is off (this module + * deliberately never calls EnableQueryId(); see pwet_post_parse_analyze()'s + * comment) and always 0 for TxnCommit/TxnAbort/Idle, which are pure + * interval boundaries with no statement of their own to name. + */ +static void +pwet_trace_write_marker(uint8 record_type, int64 query_id, int64 depth) +{ + uint64 pos; + PwetTraceRecord *rec; + uint32 seq; + instr_time now; + + if (pwet_capture != PWET_CAPTURE_TRACE || pwet_trace_writes_disabled || + pwet_my_trace == NULL) + return; + + pos = pg_atomic_read_u64(&pwet_my_trace->write_pos); + pg_atomic_write_u64(&pwet_my_trace->write_pos, pos + 1); + rec = &pwet_my_trace->records[pos & pwet_my_trace->ring_mask]; + seq = (uint32) (pos * 2 + 1); + + rec->seq = seq; + pg_write_barrier(); + INSTR_TIME_SET_CURRENT(now); + rec->record_type = record_type; + rec->timestamp_ns = INSTR_TIME_GET_NANOSEC(now); + rec->data.marker.query_id = query_id; + rec->data.marker.depth = depth; + pg_write_barrier(); + rec->seq = seq + 1; +} + +/* + * Query-marker state machine (plan sec 5.3): + * + * IDLE --(QueryStart|UtilityStart|ExecStart)--> OPEN + * OPEN --(ExecEnd at depth 0|UtilityEnd|TxnCommit|TxnAbort)--> AFTER_STATEMENT + * AFTER_STATEMENT --(first ClientRead wait, in the begin hook)--> IDLE, + * emitting a synthetic Idle marker (see pwet_wait_begin()) + * AFTER_STATEMENT --(QueryStart|UtilityStart)--> OPEN, no Idle emitted + * (a pipelined batch, a multi-statement simple-query string, or an + * explicit transaction whose next statement is already buffered -- + * there was no idle time to mark) + * + * The functions below are the only writers of pwet_marker_state; each + * always emits its own marker record first (pwet_trace_write_marker() is + * itself a no-op outside capture == trace, so the FSM and the ring can + * never disagree about whether markers are being recorded at all) and + * then applies exactly the transition above -- "OPEN" is entered + * unconditionally by all three start-markers (whichever one is called + * first out of IDLE or AFTER_STATEMENT is the one that opens the + * interval; note EXECUTE of an already-PREPAREd statement can reach + * pwet_marker_exec_start() with no preceding QueryStart at all, since + * post_parse_analyze does not run again for it). + */ +/* + * QueryStart's depth is pwet_exec_depth at the moment it fires, not + * always 0: post_parse_analyze also runs for a query parsed via SPI + * inside an already-executing outer statement (a SQL/PL function calling + * a dynamically-built query, for instance), so QueryStart can itself be + * nested. Likewise UtilityStart is written with the current depth and + * does not raise it, so the statements a top-level DO, CALL, EXECUTE or + * CREATE TABLE AS runs show markers at depth 0 too. + * pg_wait_event_trace_by_statement() therefore does not open a bucket on + * every depth-0 start marker: it also tracks a utility level (raised by + * UtilityStart, lowered by UtilityEnd, reset by Idle and TxnAbort) and + * treats only depth-0 starts at utility level 0 as top-level; of those, + * QueryStart always opens a bucket, while UtilityStart and ExecStart do + * unless the previous top-level start marker, with no Idle or + * transaction end in between, was a QueryStart or UtilityStart (the same + * statement, already open). An ExecStart with no QueryStart (EXECUTE of + * a prepared statement over the extended protocol) thus opens a bucket, + * as it moves the state machine above to OPEN. Waits between a + * request's arrival and its opening marker are attributed to that + * statement as its 'pre' phase; see the extension script for the full rule. + */ +static void +pwet_marker_query_start(int64 query_id) +{ + pwet_trace_write_marker(PWET_TRACE_QUERY_START, query_id, pwet_exec_depth); + pwet_marker_state = PWET_MARKER_OPEN; +} + +static void +pwet_marker_exec_start(int64 query_id) +{ + pwet_trace_write_marker(PWET_TRACE_EXEC_START, query_id, pwet_exec_depth); + pwet_marker_state = PWET_MARKER_OPEN; + pwet_exec_depth++; +} + +static void +pwet_marker_exec_end(int64 query_id) +{ + if (pwet_exec_depth > 0) + pwet_exec_depth--; + pwet_trace_write_marker(PWET_TRACE_EXEC_END, query_id, pwet_exec_depth); + if (pwet_exec_depth == 0) + pwet_marker_state = PWET_MARKER_AFTER_STATEMENT; +} + +/* See pwet_marker_query_start()'s comment: same nested-depth rationale. */ +static void +pwet_marker_utility_start(int64 query_id) +{ + pwet_trace_write_marker(PWET_TRACE_UTILITY_START, query_id, pwet_exec_depth); + pwet_marker_state = PWET_MARKER_OPEN; +} + +static void +pwet_marker_utility_end(int64 query_id) +{ + pwet_trace_write_marker(PWET_TRACE_UTILITY_END, query_id, 0); + pwet_marker_state = PWET_MARKER_AFTER_STATEMENT; +} + +static void +pwet_marker_txn_commit(void) +{ + pwet_trace_write_marker(PWET_TRACE_TXN_COMMIT, 0, 0); + pwet_marker_state = PWET_MARKER_AFTER_STATEMENT; + pwet_exec_depth = 0; /* defensive: transaction boundary resets it */ +} + +static void +pwet_marker_txn_abort(void) +{ + pwet_trace_write_marker(PWET_TRACE_TXN_ABORT, 0, 0); + pwet_marker_state = PWET_MARKER_AFTER_STATEMENT; + pwet_exec_depth = 0; /* an error unwinds any nested executor calls */ +} + +/* + * XactCallback: mark the end of the transaction (fix 6). The commit + * WAL-flush wait (and any other end-of-transaction wait) precedes this + * call and so is correctly attributed to the last statement, not to + * "after the transaction" -- see the attribution rule on + * pg_wait_event_trace_by_statement() in the extension script. (Work + * after this marker and before an Idle stays with the statement too, + * except when the next request was already buffered and starts before + * any Idle: the rule then counts it as that request's 'pre' phase.) + * XACT_EVENT_PREPARE (two-phase commit's PREPARE TRANSACTION) is treated + * as a commit-like boundary: the local transaction branch is over. + * + * Each marker-writing branch below flushes the pending wait first: the + * commit WAL-flush wait this comment already describes as preceding the + * call is, under deferred accounting, sitting in the pending buffer, not + * yet in the trace ring -- flushing it before the marker is what keeps it + * ordered (and attributed) before TxnCommit/TxnAbort, exactly as if + * accounting had not been deferred. + */ +static void +pwet_xact_callback(XactEvent event, void *arg) +{ + if (pwet_capture != PWET_CAPTURE_TRACE || pwet_my_trace == NULL) + return; + + switch (event) + { + case XACT_EVENT_COMMIT: + case XACT_EVENT_PARALLEL_COMMIT: + case XACT_EVENT_PREPARE: + pwet_flush_pending(); + pwet_marker_txn_commit(); + break; + case XACT_EVENT_ABORT: + case XACT_EVENT_PARALLEL_ABORT: + pwet_flush_pending(); + pwet_marker_txn_abort(); + break; + default: + break; + } +} + static bool pwet_attach_stats(void) { @@ -1068,19 +1757,40 @@ pwet_maybe_attach(void) static void pwet_maybe_attach_slow(void) { - if (!pwet_can_attach()) - return; + bool ready; - if (!pwet_attach_stats()) + /* + * The outer gate is "am I at a safe point at all", not + * pwet_can_attach() (DSA-stats-path eligibility specifically): a + * ProcNumber in the fixed server-process region fails + * pwet_can_attach() unconditionally (see its comment), but it can + * still be eligible to attach a TRACE ring (pwet_can_attach_trace()), + * which never uses that region. Gating on pwet_can_attach() here + * made the trace branch below permanently unreachable for every + * fixed-slot process -- checkpointer, walwriter, background writer, + * startup, WAL receiver, I/O workers, autovacuum workers, WAL + * senders -- exactly the processes plan sec 4.2a/5.2 say should be + * able to trace after a reload. + */ + if (!pwet_at_safe_point()) return; /* - * Registered lazily, per backend, the first time that backend actually - * attaches: on_exit_reset() (called early in every forked/exec'd - * backend, well before shared_preload_libraries processing happens - * again on EXEC_BACKEND, and inherited as a no-op on fork otherwise) - * would discard a registration made from _PG_init() in the postmaster, - * so this is the only place this can usefully happen. + * Register before attempting to attach anything, on any path, + * including a fixed-slot process: whichever attach below succeeds (or + * a fixed-slot process's own pwet_claim_fixed_slot(), called from the + * begin hook rather than from here) needs pwet_before_shmem_exit() to + * run at process exit, to release the DSA stats payload and orphan a + * trace ring (pwet_orphan_trace()). Registering only after a + * successful pwet_attach_stats() call, as a previous version of this + * function did, left every fixed-slot process permanently + * unregistered (their stats "attach" never goes through + * pwet_attach_stats() at all), so a fixed-slot process's trace ring + * would stay ACTIVE forever after that process exited, invisible to + * pg_stat_clear_orphaned_wait_event_rings()'s sweep. Harmless to + * register even when nothing ends up attaching this call: both + * pwet_release_stats() and pwet_orphan_trace() are no-ops when there + * is nothing to release. */ if (!pwet_exit_callback_registered) { @@ -1088,7 +1798,50 @@ pwet_maybe_attach_slow(void) pwet_exit_callback_registered = true; } - pwet_attach_needed = false; + /* + * Attach stats via DSA only if not already attached and eligible. + * For a ProcNumber in the fixed server-process region, + * pwet_can_attach() is always false, so pwet_my_stats stays NULL + * here until pwet_claim_fixed_slot() (from the begin hook) sets it -- + * that is not a failure to retry for, just "nothing for this + * function to do for this process's stats", so fall through to the + * trace section below regardless. + */ + if (pwet_my_stats == NULL && pwet_can_attach() && !pwet_attach_stats()) + return; + + /* + * This is an ATTACH decision: test pwet_capture_effective, not + * pwet_capture -- see the RULE on pwet_capture_effective's own + * declaration for why, and for the CI-found bug (empty trace ring for + * an entire session, every platform) that this line used to cause by + * testing pwet_capture here instead. + */ + ready = true; + if (pwet_capture_effective == PWET_CAPTURE_TRACE) + { + /* + * pwet_can_attach_trace() requires pwet_my_procno to already be + * set. For a fixed-region process that has not yet taken its + * first wait event, that identity does not exist yet (only the + * begin hook's pwet_claim_fixed_slot() can create it), so no ring + * can be attributed yet -- an accepted, documented limitation of + * the assign-hook-only attach point for that class of process, no + * different in kind from the stats-only gap plan sec 4.2a already + * describes. + */ + ready = pwet_can_attach_trace() && pwet_attach_trace(); + } + + /* + * Clear pwet_attach_needed only once everything this capture level + * requires is actually attached; otherwise leave it set so the next + * safe point (client backends: their very next statement; a + * server-side process: the next reload) retries instead of silently + * giving up for the rest of the session, as the bug above did. + */ + if (ready) + pwet_attach_needed = false; } /* @@ -1154,7 +1907,9 @@ pwet_before_shmem_exit(int code, Datum arg) pwet_flush_pending(); pwet_exit_started = true; pwet_stats_writes_disabled = true; + pwet_trace_writes_disabled = true; pwet_update_rec_pointers(); + pwet_orphan_trace(); pwet_release_stats(); pwet_my_procno = INVALID_PROC_NUMBER; } @@ -1164,6 +1919,7 @@ pwet_assign_capture(int newval, void *extra) { int old_stored = pwet_capture; bool saved_stats_disabled = pwet_stats_writes_disabled; + bool saved_trace_disabled = pwet_trace_writes_disabled; /* * Flush the pending wait, if any, before anything below masks @@ -1189,30 +1945,44 @@ pwet_assign_capture(int newval, void *extra) /* * Mask recording, for the rest of this function only, to exactly what * old_stored (the value guc.c has NOT yet overwritten pwet_capture - * with) would have permitted -- even though pwet_rec_stats is computed - * from pwet_capture_effective, the "becoming" value set below, not - * old_stored. + * with) would have permitted -- even though pwet_rec_stats/ + * pwet_rec_trace are computed from pwet_capture_effective, the + * "becoming" value set below, not old_stored. * * This matters because pwet_maybe_attach() below can run synchronously * from inside this very function (see its own call further down), and - * pwet_attach_stats() takes an LWLock to publish the new payload -- - * itself a timed wait, i.e. something pwet_wait_begin()/ - * pwet_wait_end() can observe before this function returns. Before - * pwet_rec_stats existed, the hot path tested pwet_capture directly, - * which guc.c does not store until AFTER this function returns (see - * the RULE comment on pwet_capture_effective): so for the whole - * duration of this function, the old code's recording gate saw - * old_stored, never newval, no matter what got attached in the - * meantime. Deriving the gate from pwet_capture_effective instead - * (which THIS function sets to newval, below) would, without the mask - * here, start recording mid-function the instant an attach triggered - * by the incoming value completes -- e.g. off -> stats would count - * the attach's own LWLock wait in stats. Masking reproduces the old - * gate's answer exactly: stats is masked only when old_stored == OFF, - * the one case where the old gate would have refused to record no - * matter what (pwet_capture == OFF outright); when old_stored is - * already STATS, a payload already exists and the old gate already - * counted this function's own waits under it. + * pwet_attach_stats()/pwet_attach_trace() take an LWLock to publish + * the new payload/ring -- itself a timed wait, i.e. something + * pwet_wait_begin()/pwet_wait_end() can observe before this function + * returns. Before pwet_rec_stats/pwet_rec_trace existed, the hot path + * tested pwet_capture directly, which guc.c does not store until + * AFTER this function returns (see the RULE comment on + * pwet_capture_effective): so for the whole duration of this + * function, the old code's recording gate saw old_stored, never + * newval, no matter what got attached in the meantime. Deriving the + * gate from pwet_capture_effective instead (which THIS function sets + * to newval, below) would, without the mask here, start recording + * mid-function the instant an attach triggered by the incoming value + * completes -- e.g. off -> stats would count the attach's own LWLock + * wait in stats, and off -> trace or stats -> trace would trace waits + * that occur before this SET has actually taken effect. Masking + * reproduces the old gate's answer exactly: + * + * - Trace is masked (writes disabled) unconditionally: old_stored + * can be TRACE only if capture was already trace before this call, + * in which case this is not an off/stats -> trace transition, and + * the block below either releases pwet_my_trace outright (moving + * away from trace) or leaves it untouched (newval == TRACE, a + * no-op SET) -- neither creates a NEW ring to trace into during + * this function, so there is nothing this mask could be hiding + * that the old, stored-pwet_capture gate would have shown anyway. + * - Stats is masked only when old_stored == OFF: that is the one + * case where the old gate would have refused to record no matter + * what (pwet_capture == OFF outright). When old_stored is + * already STATS or TRACE, a payload already exists and the old + * gate already counted this function's own waits under it -- e.g. + * stats -> trace or trace -> stats -- so leaving stats unmasked + * here reproduces that. * * The window between this function returning and guc.c actually * storing newval into pwet_capture contains no wait sites (nothing in @@ -1220,14 +1990,19 @@ pwet_assign_capture(int newval, void *extra) * waits on anything), so masking exactly the inside of this function, * and restoring on every exit (below), is sufficient: the set of * recorded waits is byte-for-byte identical to testing the stored - * pwet_capture throughout, exactly as before pwet_rec_stats existed. - * Deferred accounting (v11 patch 0004 fixup; see - * DECISION-deferred-accounting.md) does not change this: the recording - * decision for a wait is still taken here and in - * pwet_wait_end_impl(), at wait_end time, exactly as before -- only - * the bookkeeping itself, writing the counters, is deferred, never - * the decision of whether to. + * pwet_capture throughout, exactly as before pwet_rec_stats/ + * pwet_rec_trace existed. Deferred accounting (v11 patch 0004 fixup; + * see DECISION-deferred-accounting.md) does not change this: both + * halves of the recording decision for a wait are still taken here + * and in pwet_wait_end_impl(), at wait_end time, exactly as before -- + * pwet_pending.trace records what pwet_rec_trace answered at that + * instant (see pwet_wait_end_impl()'s comment), so nothing about a + * wait recorded (or not) during this masked window depends on when + * pwet_flush_pending() later happens to run; only the bookkeeping + * itself -- writing the counters, appending the ring record -- is + * deferred, never the decision of whether to. */ + pwet_trace_writes_disabled = true; if (old_stored == PWET_CAPTURE_OFF) pwet_stats_writes_disabled = true; @@ -1247,6 +2022,17 @@ pwet_assign_capture(int newval, void *extra) if (pwet_active && !pwet_exit_started) { + /* + * Trace is released here on ANY move away from trace, live (not + * just to off): stepping down to stats should not leave a + * multi-MiB ring pinned, and this call is a harmless no-op when + * pwet_my_trace is already NULL. Exiting the process is handled + * separately, by pwet_before_shmem_exit() (which orphans, rather + * than frees, from the fix-3 commit on). + */ + if (newval != PWET_CAPTURE_TRACE) + pwet_release_trace(); + if (newval == PWET_CAPTURE_OFF) { /* @@ -1281,24 +2067,30 @@ pwet_assign_capture(int newval, void *extra) } /* - * Unmask: restore pwet_stats_writes_disabled to what it was on entry, - * so the mask above is scoped to exactly this function's own duration, - * on every exit path (there is only this one). pwet_release_stats() - * above may itself have already toggled this same flag true and back - * as part of its own release protocol; that nesting composes - * correctly because it restores to "whatever it saw on entry to - * itself", which by then is our masked value -- so after it returns, - * the flag is back to our masked value, and this restores it one - * level further out, to the value from before we masked it. If this - * process is exiting, leave it true instead, matching - * pwet_before_shmem_exit() (which sets pwet_exit_started before this - * hook could even be reached again, but a defensive match costs - * nothing). + * Unmask: restore both writes-disabled flags to what they were on + * entry, so the mask above is scoped to exactly this function's own + * duration, on every exit path (there is only this one). + * pwet_release_stats()/pwet_release_trace() above may themselves have + * already toggled these same flags true and back as part of their own + * release protocol; that nesting composes correctly because each of + * them restores to "whatever it saw on entry to itself", which by + * then is our masked value -- so after they return, the flag is back + * to our masked value, and this restores it one level further out, to + * the value from before we masked it. If this process is exiting, + * leave both true instead, matching pwet_before_shmem_exit() (which + * sets pwet_exit_started before this hook could even be reached + * again, but a defensive match costs nothing). */ if (pwet_exit_started) + { pwet_stats_writes_disabled = true; + pwet_trace_writes_disabled = true; + } else + { pwet_stats_writes_disabled = saved_stats_disabled; + pwet_trace_writes_disabled = saved_trace_disabled; + } pwet_update_rec_pointers(); } @@ -1432,8 +2224,73 @@ pwet_flush_pending(void) state->flat_overflow_count++; } - /* No trace level yet at this point in the series. */ - (void) timestamp_ns; + /* + * Trace: append one 32-byte record for this completed wait, using the + * STORED timestamp -- the same wait_end clock read the duration above + * was computed from, per the decision document's "the trace record's + * timestamp is the same wait_end clock read" invariant -- rather than a + * fresh one. No allocation, no lock, no wait, no ereport -- single + * writer, lock-free, exactly like the stats accounting above. + * + * pwet_pending.trace is the recording decision, taken at wait_end + * time (see pwet_wait_end_impl()); pwet_my_trace != NULL here only + * guards the ring's continued existence, not a second recording + * decision -- every release/orphan site flushes before nulling + * pwet_my_trace, so on the normal path a record with trace == true + * always finds pwet_my_trace still non-NULL. + */ + if (pwet_pending.trace && pwet_my_trace != NULL) + { + PwetTraceState *trace = pwet_my_trace; + uint64 pos; + PwetTraceRecord *rec; + uint32 seq; + + pos = pg_atomic_read_u64(&trace->write_pos); + pg_atomic_write_u64(&trace->write_pos, pos + 1); + rec = &trace->records[pos & trace->ring_mask]; + seq = (uint32) (pos * 2 + 1); + + /* + * Test hazard window for t/010_trace_seqlock.pl (the + * position-encoded identity seqlock, ported from v6): at this + * instant, write_pos has already advanced past this position, but + * rec->seq has not been touched yet -- it still holds whatever a + * PREVIOUS cycle at this same ring slot last completed it to (an + * even value, but the wrong one for THIS position). A + * cross-backend reader that reads write_pos right now and walks + * back exactly one ring's worth of positions lands on this slot + * and, without an identity check (the expected seq for this exact + * position, not just parity), would emit that stale prior-cycle + * record as if it belonged to the new cycle. INJECTION_POINT() + * compiles to nothing unless this build was configured with + * injection points (see utils/injection_point.h), and even then is + * a cheap no-op unless a test has explicitly attached an action to + * this exact point name from another session -- which is the only + * reason an INJECTION_POINT() call is acceptable here, in a + * function that must obey the same no-allocation/no-lock/no-wait/ + * no-ereport rules as the wait-event hooks themselves (see this + * function's own comment above): unlike before this change, this + * code no longer runs only from inside wait_event_end_hook, but + * from every flush point enumerated there, several of which are + * ordinary safe points -- the rule is upheld everywhere regardless. + * pwet_trace_write_marker() stamps a marker record's seq with the + * same two-store bracketing pattern as below, but is not + * separately instrumented: one hazard-window test is enough to + * cover the shared protocol. + */ + INJECTION_POINT("pg-wait-event-tracing-trace-after-write-pos", NULL); + + rec->seq = seq; + pg_write_barrier(); + rec->record_type = PWET_TRACE_WAIT; + rec->timestamp_ns = timestamp_ns; + rec->data.wait.event = event; + rec->data.wait.pad2 = 0; + rec->data.wait.duration_ns = duration_ns; + pg_write_barrier(); + rec->seq = seq + 1; + } } /* @@ -1539,6 +2396,28 @@ pwet_wait_begin_impl(uint32 wait_event_info, bool chain) return; } + /* + * Idle marker synthesis (fix 6, plan sec 5.3): the backend is waiting + * for the client with no statement open (AFTER_STATEMENT) -- this is + * the explicit, unambiguous end of the previous statement's interval, + * and it can only be recognised here, at the first ClientRead wait, + * not at any parse/executor/utility/xact hook (none of them fire + * while a backend is simply waiting for its next message). Obeys the + * hook rules: pwet_trace_write_marker() only appends to an + * already-allocated ring, no allocation/lock/wait/ereport. The + * pending wait, if any, was already flushed by this function's own + * flush call above, before this or anything else in this function + * could write a marker -- see pwet_flush_pending()'s comment, which + * lists this Idle marker as one of the ordering points it covers. + */ + if (pwet_capture == PWET_CAPTURE_TRACE && + pwet_marker_state == PWET_MARKER_AFTER_STATEMENT && + wait_event_info == WAIT_EVENT_CLIENT_READ) + { + pwet_trace_write_marker(PWET_TRACE_IDLE, 0, 0); + pwet_marker_state = PWET_MARKER_IDLE; + } + INSTR_TIME_SET_CURRENT(pwet_wait_start); pwet_current_event = wait_event_info; } @@ -1622,8 +2501,8 @@ pwet_wait_end_impl(uint32 wait_event_info, bool chain) pwet_pending.event = event; pwet_pending.duration_ns = duration_ns; pwet_pending.timestamp_ns = INSTR_TIME_GET_NANOSEC(now); - /* No trace level yet at this point in the series. */ - pwet_pending.trace = false; + /* The trace recording decision, taken here, not at flush. */ + pwet_pending.trace = (pwet_rec_trace != NULL); pwet_pending_valid = true; INSTR_TIME_SET_ZERO(pwet_wait_start); @@ -1684,6 +2563,28 @@ pwet_install_wait_hooks(void) pwet_wait_hooks_installed = true; } +/* + * post_parse_analyze_hook: QueryStart (fix 6). Fires once per parsed + * statement -- including a utility statement, since parse_analyze() + * wraps those in a Query too -- marking "a statement is open" before + * either the executor or ProcessUtility has actually started running it + * (extended protocol: at Parse, before Bind/Execute). + * + * Deliberately does NOT call EnableQueryId(): that would force query + * jumbling on every server that merely preloads this library, even with + * capture off, which is a cluster-wide behavior change no server operator + * asked for. QueryStart is therefore emitted unconditionally (once + * capture == trace), carrying whatever query->queryId already is -- 0 + * unless compute_query_id is on or another loaded module (e.g. + * pg_stat_statements) already turned jumbling on for its own reasons. + * The documentation notes this trade-off; a 0 query_id here does not + * mean "no statement", it means "no id available for this statement". + * + * Flushes the pending wait before the marker: a wait completed since the + * last flush point (typically the backend's own ClientRead, ending as + * this statement's bytes arrived) must land in the trace ring before + * QueryStart, not after, to preserve the recorded order. + */ static void pwet_post_parse_analyze(ParseState *pstate, Query *query, const JumbleState *jstate) @@ -1692,19 +2593,103 @@ pwet_post_parse_analyze(ParseState *pstate, Query *query, prev_post_parse_analyze_hook(pstate, query, jstate); pwet_maybe_attach(); + + if (pwet_capture == PWET_CAPTURE_TRACE) + { + pwet_flush_pending(); + pwet_marker_query_start(query->queryId); + } } +/* + * ExecutorStart_hook / ExecutorEnd_hook: ExecStart/ExecEnd (fix 6), with + * the executor nesting depth (0 = top-level, >0 = a nested invocation + * from inside a SQL-language function, PL/pgSQL, a trigger, etc.). + * Emitted before calling into the standard/chained implementation (and, + * for End, after it returns) so a nested invocation's own ExecStart/ + * ExecEnd pair is correctly bracketed inside the outer one's. + * + * Each flushes the pending wait immediately before its own marker write, + * for the same ordering reason as pwet_post_parse_analyze(): ExecutorEnd's + * flush in particular is what orders a wait completed during execution + * itself before the ExecEnd marker that closes the statement's interval. + */ static void pwet_ExecutorStart(QueryDesc *queryDesc, int eflags) { pwet_maybe_attach(); + if (pwet_capture == PWET_CAPTURE_TRACE) + { + pwet_flush_pending(); + pwet_marker_exec_start(queryDesc->plannedstmt->queryId); + } + if (prev_ExecutorStart_hook != NULL) prev_ExecutorStart_hook(queryDesc, eflags); else standard_ExecutorStart(queryDesc, eflags); } +static void +pwet_ExecutorEnd(QueryDesc *queryDesc) +{ + int64 query_id = queryDesc->plannedstmt->queryId; + + if (prev_ExecutorEnd_hook != NULL) + prev_ExecutorEnd_hook(queryDesc); + else + standard_ExecutorEnd(queryDesc); + + if (pwet_capture == PWET_CAPTURE_TRACE) + { + pwet_flush_pending(); + pwet_marker_exec_end(query_id); + } +} + +/* + * ProcessUtility_hook: UtilityStart/UtilityEnd (fix 6). No PG_TRY/ + * PG_FINALLY around the chained call: if the utility statement errors, + * UtilityEnd is simply never written, exactly like a regular statement's + * ExecEnd on error -- TxnAbort (from the xact callback) closes the open + * interval either way, so there is one uniform error rule for every + * statement kind rather than a special case for utility statements. + * + * Two separate flush points, one before each marker: UtilityStart's flush + * orders a wait already pending when the utility begins (same reasoning + * as post_parse_analyze's); UtilityEnd's flush is required separately + * because the utility's own execution, in between, can itself complete + * waits that must be ordered before UtilityEnd closes the interval. + */ +static void +pwet_ProcessUtility(PlannedStmt *pstmt, const char *queryString, + bool readOnlyTree, ProcessUtilityContext context, + ParamListInfo params, QueryEnvironment *queryEnv, + DestReceiver *dest, QueryCompletion *qc) +{ + int64 query_id = pstmt->queryId; + + if (pwet_capture == PWET_CAPTURE_TRACE) + { + pwet_flush_pending(); + pwet_marker_utility_start(query_id); + } + + if (prev_ProcessUtility_hook != NULL) + prev_ProcessUtility_hook(pstmt, queryString, readOnlyTree, context, + params, queryEnv, dest, qc); + else + standard_ProcessUtility(pstmt, queryString, readOnlyTree, context, + params, queryEnv, dest, qc); + + if (pwet_capture == PWET_CAPTURE_TRACE) + { + pwet_flush_pending(); + pwet_marker_utility_end(query_id); + } +} + /* * Resolve the optional pid SRF argument to a ProcNumber range * [out_start, out_end). Returns false if the SRF should emit zero rows @@ -2292,6 +3277,481 @@ pg_wait_event_tracing_hooks_installed(PG_FUNCTION_ARGS) PG_RETURN_BOOL(pwet_wait_hooks_installed); } +/* Decoded, SRF-shaped view of one trace record; see pwet_decode_trace_record(). */ +typedef struct PwetTraceRowFields +{ + const char *event_type; + const char *event_name; + double duration_us; + int64 query_id; + int32 depth; +} PwetTraceRowFields; + +/* + * Decode one trace record's record_type into the SRF's output row shape. + * Shared by the own-session and cross-backend readers. Returns false + * (nothing should be emitted) for a record_type this build does not + * recognise (defensive; cannot happen with the type list below) or, for + * PWET_TRACE_WAIT, an event id of 0 (a record whose duration/event fields + * were never filled in -- cannot happen either, since the writer only + * ever completes a record after filling them, but kept as a defensive + * symmetry with the seqlock check itself). + */ +static bool +pwet_decode_trace_record(PwetTraceRecord *rec, PwetTraceRowFields *out) +{ + out->duration_us = 0; + out->query_id = 0; + out->depth = 0; + + switch (rec->record_type) + { + case PWET_TRACE_WAIT: + if (rec->data.wait.event == 0) + return false; + out->event_type = pgstat_get_wait_event_type(rec->data.wait.event); + out->event_name = pgstat_get_wait_event(rec->data.wait.event); + out->duration_us = (double) rec->data.wait.duration_ns / 1000.0; + break; + case PWET_TRACE_QUERY_START: + out->event_type = "Query"; + out->event_name = "QueryStart"; + out->query_id = rec->data.marker.query_id; + out->depth = (int32) rec->data.marker.depth; + break; + case PWET_TRACE_EXEC_START: + out->event_type = "Query"; + out->event_name = "ExecStart"; + out->query_id = rec->data.marker.query_id; + out->depth = (int32) rec->data.marker.depth; + break; + case PWET_TRACE_EXEC_END: + out->event_type = "Query"; + out->event_name = "ExecEnd"; + out->query_id = rec->data.marker.query_id; + out->depth = (int32) rec->data.marker.depth; + break; + case PWET_TRACE_UTILITY_START: + out->event_type = "Query"; + out->event_name = "UtilityStart"; + out->query_id = rec->data.marker.query_id; + out->depth = (int32) rec->data.marker.depth; + break; + case PWET_TRACE_UTILITY_END: + out->event_type = "Query"; + out->event_name = "UtilityEnd"; + out->query_id = rec->data.marker.query_id; + break; + case PWET_TRACE_TXN_COMMIT: + out->event_type = "Query"; + out->event_name = "TxnCommit"; + break; + case PWET_TRACE_TXN_ABORT: + out->event_type = "Query"; + out->event_name = "TxnAbort"; + break; + case PWET_TRACE_IDLE: + out->event_type = "Query"; + out->event_name = "Idle"; + break; + default: + return false; + } + + return out->event_type != NULL && out->event_name != NULL; +} + +/* Own-session row shape: no owner_pid column (it is always MyProcPid). */ +static void +pwet_emit_trace_row(ReturnSetInfo *rsinfo, uint64 ring_index, + PwetTraceRecord *rec) +{ + PwetTraceRowFields f; + Datum values[7]; + bool nulls[7] = {0}; + + if (!pwet_decode_trace_record(rec, &f)) + return; + + values[0] = Int64GetDatum((int64) ring_index); + values[1] = Int64GetDatum(rec->timestamp_ns); + values[2] = CStringGetTextDatum(f.event_type); + values[3] = CStringGetTextDatum(f.event_name); + values[4] = Float8GetDatum(f.duration_us); + values[5] = Int64GetDatum(f.query_id); + values[6] = Int32GetDatum(f.depth); + + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls); +} + +/* + * Cross-backend row shape: leads with owner_pid, the pid of the ring's + * producer -- live or, for an ORPHANED ring (fix 3), the pid it had before + * it exited -- so a caller can identify a post-mortem ring's origin + * without a second lookup that would fail anyway (the producer's + * PgBackendStatus entry no longer exists once it has exited). + */ +static void +pwet_emit_trace_row_for_procnumber(ReturnSetInfo *rsinfo, int owner_pid, + uint64 ring_index, PwetTraceRecord *rec) +{ + PwetTraceRowFields f; + Datum values[8]; + bool nulls[8] = {0}; + + if (!pwet_decode_trace_record(rec, &f)) + return; + + values[0] = Int32GetDatum(owner_pid); + values[1] = Int64GetDatum((int64) ring_index); + values[2] = Int64GetDatum(rec->timestamp_ns); + values[3] = CStringGetTextDatum(f.event_type); + values[4] = CStringGetTextDatum(f.event_name); + values[5] = Float8GetDatum(f.duration_us); + values[6] = Int64GetDatum(f.query_id); + values[7] = Int32GetDatum(f.depth); + + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls); +} + +/* + * SQL function: pg_get_backend_wait_event_trace() + * + * Own-session trace ring reader. No lock needed: this backend is the + * ring's sole writer, and it is reading its own memory. Flushes its own + * pending wait first, so a wait completed by, e.g., pg_sleep() earlier in + * the same statement is always visible here immediately, without waiting + * for the next flush point (see the module comment / commit message). + */ +Datum +pg_get_backend_wait_event_trace(PG_FUNCTION_ARGS) +{ + ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + uint64 write_pos; + uint64 read_start; + uint64 ring_size; + uint64 i; + + InitMaterializedSRF(fcinfo, 0); + + pwet_maybe_attach(); + pwet_flush_pending(); + if (pwet_my_trace == NULL) + PG_RETURN_VOID(); + + write_pos = pg_atomic_read_u64(&pwet_my_trace->write_pos); + if (write_pos == 0) + PG_RETURN_VOID(); + + ring_size = (uint64) pwet_my_trace->ring_mask + 1; + read_start = write_pos > ring_size ? write_pos - ring_size : 0; + + for (i = read_start; i < write_pos; i++) + { + PwetTraceRecord *rec = &pwet_my_trace->records[i & pwet_my_trace->ring_mask]; + uint32 expected_seq = (uint32) (i * 2 + 2); + uint32 seq_before; + uint32 seq_after; + PwetTraceRecord copy; + + seq_before = rec->seq; + pg_read_barrier(); + if (seq_before != expected_seq) + continue; + copy = *rec; + pg_read_barrier(); + seq_after = rec->seq; + if (seq_after != expected_seq) + continue; + + pwet_emit_trace_row(rsinfo, i, ©); + } + + PG_RETURN_VOID(); +} + +/* + * Snapshot procnumber's trace ring and emit its records into the SRF's + * tuplestore. Returns silently for a FREE slot or an empty ring. + * + * Cross-backend reader protocol (ported from v6's + * emit_wait_event_trace_for_procnumber(), same rationale throughout, + * INCLUDING v6's own lock-scope discipline -- an earlier version of this + * function held pwet_lock across the tuplestore_putvalues() loop too, + * which defeated the whole point of buffering locally first; fixed on + * review): + * 1. Allocate the worst-case result buffer -- sized from + * pwet_trace_records_per_ring, the cluster-wide ring capacity every + * ring shares, not from this specific ring (not yet resolved) -- + * BEFORE taking any lock: a palloc this size can bottom out in a + * glibc mmap() syscall, and doing that while holding pwet_lock would + * serialise every concurrent attach/release/reset/orphan-sweep + * through one VMA-modifying kernel operation. + * 2. Acquire pwet_lock LW_SHARED; every trace_state/trace_ptr transition + * (pwet_attach_trace(), pwet_release_trace(), pwet_orphan_trace(), + * the orphan sweep) takes it LW_EXCLUSIVE, so the ring's identity and + * address are stable for the whole iteration. + * 3. Re-check trace_state under the lock and resolve the ring address. + * 4. Walk [read_start, write_pos): for each position, the + * POSITION-ENCODED IDENTITY seqlock check against shared memory (NOT + * just parity -- see v6's WaitEventTraceRecord seqlock comment for + * why parity alone accepts a stale previous-cycle record after a + * wraparound): a record at ring index i is valid only if its seq + * equals (uint32)(i*2+2), read before AND after copying the record, + * with a read barrier on each side. + * 5. Release the lock -- BEFORE emitting a single row: a 4 MB default + * ring is up to 131072 rows, and tuplestore_putvalues() can spill to + * disk for a large result, none of which should happen while every + * other backend's attach/release/reset/orphan-sweep is blocked on + * this lock. + * + * Both ACTIVE and ORPHANED slots are read the same way: for ACTIVE, the + * live owner is concurrently appending and the seqlock catches torn + * reads; for ORPHANED, the ring is immutable post-mortem data, so the + * check is a pass-through (it still correctly skips one trailing + * odd-seq record if the owner died mid-write). + */ +static void +emit_wait_event_trace(int procnumber, ReturnSetInfo *rsinfo) +{ + PwetSlot *slot = &pwet_ctl[procnumber]; + PwetTraceState *ts; + uint64 write_pos; + uint64 read_start; + uint64 ring_size; + uint64 i; + PwetTraceRecord *valid_records; + uint64 *valid_indexes; + uint64 valid_count = 0; + int owner_pid = 0; + + if (pwet_trace_records_per_ring == 0) + pwet_trace_records_per_ring = + (uint32) pwet_trace_ring_size * 1024U / + (uint32) sizeof(PwetTraceRecord); + + /* See point 1 above: sized from the cluster-wide capacity, no lock yet. */ + valid_records = palloc(sizeof(PwetTraceRecord) * pwet_trace_records_per_ring); + valid_indexes = palloc(sizeof(uint64) * pwet_trace_records_per_ring); + + LWLockAcquire(pwet_lock, LW_SHARED); + + if (slot->trace_state == PWET_TRACE_FREE || !DsaPointerIsValid(slot->trace_ptr)) + { + LWLockRelease(pwet_lock); + pfree(valid_records); + pfree(valid_indexes); + return; + } + + ts = dsa_get_address(pwet_trace_dsa, slot->trace_ptr); + owner_pid = slot->trace_owner_pid; + + write_pos = pg_atomic_read_u64(&ts->write_pos); + if (write_pos == 0) + { + LWLockRelease(pwet_lock); + pfree(valid_records); + pfree(valid_indexes); + return; + } + + ring_size = (uint64) ts->ring_mask + 1; + read_start = write_pos > ring_size ? write_pos - ring_size : 0; + + for (i = read_start; i < write_pos; i++) + { + PwetTraceRecord *rec_shared = &ts->records[i & ts->ring_mask]; + uint32 expected_seq = (uint32) (i * 2 + 2); + uint32 seq_before; + uint32 seq_after; + + seq_before = rec_shared->seq; + pg_read_barrier(); + if (seq_before != expected_seq) + continue; + valid_records[valid_count] = *rec_shared; + pg_read_barrier(); + seq_after = rec_shared->seq; + if (seq_after != expected_seq) + continue; + valid_indexes[valid_count] = i; + valid_count++; + } + + LWLockRelease(pwet_lock); + + /* No shared-memory access below: safe to run unlocked, even a spill. */ + for (i = 0; i < valid_count; i++) + pwet_emit_trace_row_for_procnumber(rsinfo, owner_pid, + valid_indexes[i], &valid_records[i]); + + pfree(valid_records); + pfree(valid_indexes); +} + +/* + * SQL function: pg_get_wait_event_trace(procnumber int4) + * + * Cross-backend trace ring reader. Returns the records belonging to + * whichever backend currently or previously occupied procnumber's trace + * slot, each tagged with that backend's pid (owner_pid; see + * pwet_emit_trace_row_for_procnumber()); FREE slots (never traced, or + * already swept) return an empty result. This is the in-tree consumer of + * orphan-preserved data (fix 3): a backend that exited while capture = + * trace leaves its ring ORPHANED, readable here (with its last-known pid + * still attached) until a successor reclaims the slot or + * pg_stat_clear_orphaned_wait_event_rings() sweeps it. + * + * When procnumber is the CALLING backend's own, this flushes its own + * pending wait first, for the same reason pg_get_backend_wait_event_trace() + * does: this function (and pg_wait_event_trace_by_statement(), built on + * top of it in the extension script) is the only way a backend can read + * its own ring by procnumber rather than through the dedicated own-session + * reader, and it must show the same "always see your own completed waits" + * behavior either way. A procnumber belonging to any other backend is + * the genuine cross-backend case, unaffected: only that backend's own next + * flush point can ever move its own pending record into its own ring. + */ +Datum +pg_get_wait_event_trace(PG_FUNCTION_ARGS) +{ + ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + int32 procnumber = PG_GETARG_INT32(0); + + InitMaterializedSRF(fcinfo, 0); + + if (procnumber < 0 || procnumber >= PWET_NUM_SLOTS) + PG_RETURN_VOID(); + + if (procnumber == MyProcNumber) + pwet_flush_pending(); + + /* Unlocked fast-path: skip a FREE slot without taking the lock. */ + if (pwet_ctl[procnumber].trace_state == PWET_TRACE_FREE) + PG_RETURN_VOID(); + + if (!pwet_ensure_trace_dsa()) + PG_RETURN_VOID(); + + emit_wait_event_trace(procnumber, rsinfo); + + PG_RETURN_VOID(); +} + +/* + * Transition this backend's trace ring to ORPHANED on process exit (fix + * 3), instead of freeing it: trace_owner_pid/trace_owner_start are left + * untouched (they already identify this process, the one now exiting), + * so pg_get_wait_event_trace() keeps attributing the ring to its producer + * post-mortem, like a flight recorder. A successor that later claims + * this ProcNumber and attaches trace reclaims (frees) the orphan in + * pwet_attach_trace(); pg_stat_clear_orphaned_wait_event_rings() lets an + * administrator sweep every orphan explicitly, for procnumbers that + * never get reused (e.g. a long-lived connection pool with capture + * briefly enabled). Nothing runs at process start to reclaim an orphan + * earlier (contrast v6's now-removed clear-orphan-at-init step, whose + * EXEC_BACKEND ordering bug was V6-3): reclaim happens lazily, at the + * successor's own trace attach, which is always a safe point -- so + * EXEC_BACKEND's relative ordering of shared-memory attachment and + * backend initialization cannot matter here. + * + * Flushes the pending wait, if any, before orphaning: the ring is about + * to become immutable post-mortem data, so this is the last chance to + * append a still-pending trace record to it (see pwet_flush_pending()'s + * comment). + */ +static void +pwet_orphan_trace(void) +{ + PwetSlot *slot; + ProcNumber procno = pwet_my_procno; + + pwet_flush_pending(); + + if (pwet_my_trace == NULL || procno == INVALID_PROC_NUMBER) + { + pwet_my_trace = NULL; + pwet_update_rec_pointers(); + return; + } + + pwet_my_trace = NULL; + pwet_update_rec_pointers(); + slot = &pwet_ctl[procno]; + + LWLockAcquire(pwet_lock, LW_EXCLUSIVE); + if (DsaPointerIsValid(slot->trace_ptr)) + { + slot->trace_state = PWET_TRACE_ORPHANED; + pg_atomic_fetch_add_u32(&slot->generation, 1); + } + LWLockRelease(pwet_lock); +} + +/* + * SQL function: pg_stat_clear_orphaned_wait_event_rings() + * + * Free every trace ring whose owner has exited (trace_state ORPHANED). + * Superuser-only in C, matching this module's pg_stat_reset_wait_event_ + * timing_all() (fix 4's C-level hard-superuser policy for cluster-scope + * mutating admin functions, rather than v6's plain SQL-level REVOKE-only + * default): this operation, like that one, can disrupt any concurrent + * cross-backend reader of any orphan. + * + * Per-slot lock acquire/release rather than one lock held across the + * whole sweep, so a long sweep never holds pwet_lock for more than one + * slot's worth of work at a time; CHECK_FOR_INTERRUPTS() lets a caller + * cancel a long sweep between slots. An unlocked fast-path skips a + * non-ORPHANED slot without taking the lock at all; the authoritative + * re-check under the lock means a concurrent reclaim by a successor's own + * attach is never raced (we only ever free a slot we ourselves saw, and + * re-saw under the lock, as ORPHANED). + */ +Datum +pg_stat_clear_orphaned_wait_event_rings(PG_FUNCTION_ARGS) +{ + int64 freed = 0; + int i; + + if (!superuser()) + ereport(ERROR, + (errcode(ERRCODE_INSUFFICIENT_PRIVILEGE), + errmsg("permission denied to clear orphaned wait event trace rings"), + errdetail("Only roles with the %s attribute may free orphaned trace rings.", + "SUPERUSER"))); + + if (!pwet_ensure_trace_dsa()) + PG_RETURN_INT64(0); + + for (i = 0; i < PWET_NUM_SLOTS; i++) + { + PwetSlot *slot = &pwet_ctl[i]; + + CHECK_FOR_INTERRUPTS(); + + /* Unlocked fast-path: skip a non-ORPHANED slot cheaply. */ + if (slot->trace_state != PWET_TRACE_ORPHANED) + continue; + + LWLockAcquire(pwet_lock, LW_EXCLUSIVE); + if (slot->trace_state == PWET_TRACE_ORPHANED && + DsaPointerIsValid(slot->trace_ptr)) + { + dsa_free(pwet_trace_dsa, slot->trace_ptr); + slot->trace_ptr = InvalidDsaPointer; + slot->trace_state = PWET_TRACE_FREE; + slot->trace_owner_pid = 0; + slot->trace_owner_start = 0; + pg_atomic_fetch_add_u32(&slot->generation, 1); + freed++; + } + LWLockRelease(pwet_lock); + } + + PG_RETURN_INT64(freed); +} + void _PG_init(void) { @@ -2323,6 +3783,18 @@ _PG_init(void) NULL, NULL, NULL); + DefineCustomIntVariable("pg_wait_event_tracing.trace_ring_size", + "Per-backend trace ring size.", + NULL, + &pwet_trace_ring_size, + 4096, + 8, + 32768, + PGC_POSTMASTER, + GUC_UNIT_KB | GUC_NOT_IN_SAMPLE, + pwet_check_trace_ring_size, + NULL, + NULL); MarkGUCPrefixReserved("pg_wait_event_tracing"); prev_shmem_request_hook = shmem_request_hook; @@ -2341,6 +3813,10 @@ _PG_init(void) post_parse_analyze_hook = pwet_post_parse_analyze; prev_ExecutorStart_hook = ExecutorStart_hook; ExecutorStart_hook = pwet_ExecutorStart; + prev_ExecutorEnd_hook = ExecutorEnd_hook; + ExecutorEnd_hook = pwet_ExecutorEnd; + prev_ProcessUtility_hook = ProcessUtility_hook; + ProcessUtility_hook = pwet_ProcessUtility; pwet_active = true; pwet_attach_needed = (pwet_capture != PWET_CAPTURE_OFF); diff --git a/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_trace.sql b/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_trace.sql new file mode 100644 index 00000000000..214cd4678aa --- /dev/null +++ b/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_trace.sql @@ -0,0 +1,304 @@ +-- +-- PG_WAIT_EVENT_TRACING_TRACE +-- +-- Exercises the trace level's query-attribution markers (fix 6): the +-- QueryStart/ExecStart/ExecEnd/UtilityStart/UtilityEnd/TxnCommit/TxnAbort +-- marker set and pg_wait_event_trace_by_statement(). The ring buffer's own +-- seqlock/wrap/orphan-lifecycle machinery is exercised by TAP tests with +-- injection points (WP4), not here. +-- +-- Idle is deliberately excluded from every comparison below (see the WHERE +-- clause in the pattern below): whether it appears at all depends on +-- whether the backend actually blocks in ClientRead, which depends on +-- whether the next message psql sends is already buffered by the time the +-- backend looks -- protocol structure (separate messages vs. one +-- multi-statement message) makes it likely but not deterministic either +-- way on a loaded CI runner. A TAP test, where the client can pause +-- deliberately between statements to force the wait, covers Idle instead +-- (WP4b). +-- +-- Reading a session's own ring via SQL is necessarily self-referential: +-- every observing SELECT below writes its own QueryStart+ExecStart into +-- the ring (post_parse_analyze/ExecutorStart fire before its body runs), +-- and the "markN" SELECT used to record a starting ring position finishes +-- writing its own ExecEnd+TxnCommit (and possibly an Idle, excluded here +-- for the same reason as above) *after* that position was captured +-- (captured mid-execution, from inside its own target list). Every case +-- below therefore uses the identical, fully deterministic pattern: +-- +-- SELECT coalesce(max(seq), -1) AS markN FROM pg_backend_wait_event_trace \gset +-- +-- SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +-- FROM pg_backend_wait_event_trace +-- WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :markN; +-- +-- [3:count(*)-2]: index 1-2 are always the "markN" statement's own +-- trailing ExecEnd, TxnCommit (everything it itself writes to the ring +-- after the position was captured from its still-in-progress ExecStart, +-- minus any Idle, already filtered out by the WHERE clause regardless of +-- whether it fired); the last 2 indexes are always this observing SELECT's +-- own leading-in-time-but-trailing-in-the-array QueryStart, ExecStart +-- (written to the ring before its body/aggregate runs). Slicing them off +-- leaves exactly the case's own real, non-Idle markers. Real wait events +-- are deliberately never asserted by exact count (plan sec 5.5): the one +-- case with a real wait (case 7) checks only presence/attribution. +-- +CREATE EXTENSION IF NOT EXISTS pg_wait_event_tracing; + +-- CI forces debug_parallel_query = regress on some platforms, which +-- would move statements below into a parallel worker, recording their +-- markers under the worker's own ring, not this session's. +SET debug_parallel_query = off; + +SET pg_wait_event_tracing.capture = trace; + +-- +-- Case 1: a single autocommit statement. +-- Expect: QueryStart, ExecStart, ExecEnd, TxnCommit (Idle excluded; it +-- would follow once the implicit transaction has committed and the +-- backend waits for the next client message -- see the file header). +-- +SELECT coalesce(max(seq), -1) AS mark1 FROM pg_backend_wait_event_trace \gset +SELECT 1; +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark1; + +-- +-- Case 2: an explicit transaction with two statements, each on its own +-- line. The transaction stays open the whole time (no TxnCommit/TxnAbort +-- until the final COMMIT). TxnCommit follows UtilityEnd here, the same +-- as case 4's plain utility statement, not during ProcessUtility: an +-- explicit COMMIT's EndTransactionBlock() only marks the transaction +-- block TBLOCK_END while still inside the utility statement: the actual +-- commit (CommitTransaction(), which fires the xact callback) happens in +-- finish_xact_command(), called by exec_simple_query() (postgres.c) +-- *after* ProcessUtility returns -- the same command-loop point an +-- ordinary autocommit statement's implicit commit happens at. +-- +SELECT coalesce(max(seq), -1) AS mark2 FROM pg_backend_wait_event_trace \gset +BEGIN; +SELECT 1; +SELECT 2; +COMMIT; +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark2; + +-- +-- Case 3: two statements sent as ONE simple-query protocol message, both +-- on the same input line so psql sends them together. Each still gets +-- its own individual QueryStart/ExecStart/ExecEnd/TxnCommit -- autocommit +-- commits after every statement in a multi-statement string, not once at +-- the end. +-- +SELECT coalesce(max(seq), -1) AS mark3 FROM pg_backend_wait_event_trace \gset +SELECT 1; SELECT 2; +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark3; + +-- +-- Case 4: a utility statement (no executor involvement): UtilityStart/ +-- UtilityEnd only, no ExecStart/ExecEnd, TxnCommit after UtilityEnd -- +-- same shape and same reason as case 2's COMMIT above (the implicit +-- per-statement commit happens in the command loop, after +-- ProcessUtility_hook returns). +-- +SELECT coalesce(max(seq), -1) AS mark4 FROM pg_backend_wait_event_trace \gset +CREATE TABLE pwet_trace_test_t (a int); +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark4; +DROP TABLE pwet_trace_test_t; + +-- +-- Case 5: an error raised during PLANNING, not execution: 1/0 is a +-- constant expression, and the planner's eval_const_expressions() folds +-- it by calling evaluate_expr() (clauses.c), which builds a throwaway +-- executor state and evaluates the expression right there -- raising the +-- division-by-zero before ExecutorStart is ever reached. So there is no +-- ExecStart/ExecEnd pair to leave unmatched here: QueryStart opens the +-- statement's interval, and TxnAbort -- not TxnCommit -- closes it +-- directly. This no longer exercises pwet_marker_txn_abort()'s +-- defensive pwet_exec_depth reset (needed for a genuinely mid-execution +-- error, which this simple, always-planning-time-erroring form cannot +-- produce); that reset stays uncovered by this regression file. +-- +SELECT coalesce(max(seq), -1) AS mark5 FROM pg_backend_wait_event_trace \gset +SELECT 1/0; +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark5; + +-- +-- Case 6: a nested query call (depth 1 inside depth 0). LANGUAGE SQL +-- will not do here: inline_function() (clauses.c) inlines a SQL-language +-- function whose body is a single simple SELECT directly into the +-- calling query, so it never runs its own separate, nested executor +-- invocation at all. PL/pgSQL is not inlined, and a PERFORM statement +-- in its body always goes through SPI's normal execute path (unlike a +-- bare RETURN/assignment expression, which plpgsql evaluates directly +-- without SPI when it is "simple enough"), so it reliably produces a +-- real nested ExecStart/ExecEnd pair. plpgsql is installed in every +-- database by default, so this needs no extra CREATE EXTENSION. +-- +-- The function is called once first, outside the measured window, so +-- its PERFORM statement's query is already parsed and its plan cached +-- (plpgsql caches each statement's plan across calls in the same +-- session) by the time of the measured call -- keeping this case about +-- the ExecStart/ExecEnd depth nesting specifically, not about whether a +-- cached call also re-parses (it does not, so no QueryStart happens at +-- nested depth in the measured call). +-- +CREATE FUNCTION pwet_trace_test_nested() RETURNS int +LANGUAGE plpgsql AS $$ BEGIN PERFORM 1; RETURN 1; END $$; +SELECT pwet_trace_test_nested(); + +SELECT coalesce(max(seq), -1) AS mark6 FROM pg_backend_wait_event_trace \gset +SELECT pwet_trace_test_nested(); +SELECT (array_agg(wait_event ORDER BY seq))[3:count(*)-2] AS markers, + (array_agg(depth ORDER BY seq))[3:count(*)-2] AS depths +FROM pg_backend_wait_event_trace +WHERE wait_event_type = 'Query' AND wait_event <> 'Idle' AND seq > :mark6; +DROP FUNCTION pwet_trace_test_nested(); + +-- +-- Case 7: pg_wait_event_trace_by_statement() attribution. A pg_sleep() +-- inside its own statement guarantees at least one real (Timeout/ +-- PgSleep) wait to attribute; the following bare SELECT has none. Never +-- assert an exact PgSleep count (plan sec 5.5): only that every PgSleep +-- wait this session ever recorded was attributed to a real statement, +-- never to the synthetic / buckets, and that at +-- least one such wait was seen. +-- +SELECT procnumber FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid() LIMIT 1 \gset + +SELECT pg_sleep(0.01); +SELECT 1; + +SELECT bool_and(bucket NOT IN ('', '')) AS pgsleep_attributed, + sum(calls) >= 1 AS at_least_one_pgsleep +FROM pg_wait_event_trace_by_statement(:procnumber) +WHERE wait_event = 'PgSleep'; + +-- +-- Cases 8-12: statement attribution of pg_wait_event_trace_by_statement() +-- for the ways a statement can start. Every statement under test sleeps +-- for 10 ms, giving it at least one Timeout/PgSleep wait (a platform may +-- record more than one, so only "at least one" is ever asserted), and +-- each check counts the distinct statement buckets holding such waits +-- after a recorded ring position. A bucket's statement_seq is the seq of +-- the marker that opened it, so looking that marker up in the ring tells +-- which kind of marker opened the bucket. +-- +-- compute_query_id is on so the markers carry a query identifier. +-- +SET compute_query_id = on; + +-- +-- Case 8: one named prepared statement executed three times over the +-- extended protocol. Only the first Parse runs post_parse_analyze; each +-- execution writes just an ExecStart. Expect three buckets, all with the +-- query_id of the ExecStart that opened them, and no PgSleep wait in any +-- synthetic bucket. +-- +SELECT coalesce(max(seq), -1) AS mark8 FROM pg_backend_wait_event_trace \gset +SELECT pg_sleep(0.01) AS slept8 \parse pwet_trace_s8 +\bind_named pwet_trace_s8 \g +\bind_named pwet_trace_s8 \g +\bind_named pwet_trace_s8 \g +SELECT count(DISTINCT b.statement_seq) AS buckets, + count(DISTINCT b.query_id) AS query_ids, + bool_and(m.wait_event = 'ExecStart' AND m.query_id = b.query_id + AND b.query_id <> 0) AS opened_by_execstart, + bool_and(b.phase IN ('pre', 'statement')) AS phases_ok +FROM pg_wait_event_trace_by_statement(:procnumber) b + JOIN pg_backend_wait_event_trace m ON m.seq = b.statement_seq +WHERE b.wait_event = 'PgSleep' AND b.statement_seq > :mark8; +SELECT count(*) AS sleeps_in_synthetic_buckets +FROM pg_wait_event_trace_by_statement(:procnumber) +WHERE wait_event = 'PgSleep' AND bucket IN ('', '', ''); + +-- +-- Case 9: the same statement run in a pipeline with a sync between the +-- executions. Each sync commits, so every ExecStart follows a TxnCommit +-- with no Idle marker in between (the next message was already +-- buffered). Expect three separate buckets. +-- +SELECT coalesce(max(seq), -1) AS mark9 FROM pg_backend_wait_event_trace \gset +\startpipeline +\bind_named pwet_trace_s8 \sendpipeline +\syncpipeline +\bind_named pwet_trace_s8 \sendpipeline +\syncpipeline +\bind_named pwet_trace_s8 \sendpipeline +\endpipeline +SELECT count(DISTINCT b.statement_seq) AS buckets, + bool_and(m.wait_event = 'ExecStart' AND m.query_id = b.query_id + AND b.query_id <> 0) AS opened_by_execstart +FROM pg_wait_event_trace_by_statement(:procnumber) b + JOIN pg_backend_wait_event_trace m ON m.seq = b.statement_seq +WHERE b.wait_event = 'PgSleep' AND b.statement_seq > :mark9; +\close_prepared pwet_trace_s8 + +-- +-- Case 10: a DO block looping three times over a statement whose plan is +-- cached after the first iteration. The statements it runs have depth-0 +-- markers (UtilityStart does not raise the depth), but belong to the DO: +-- expect exactly one bucket, opened by the QueryStart of the DO itself, +-- holding at least three PgSleep waits. +-- +SELECT coalesce(max(seq), -1) AS mark10 FROM pg_backend_wait_event_trace \gset +DO $$ BEGIN FOR i IN 1..3 LOOP PERFORM pg_sleep(0.01); END LOOP; END $$; +SELECT count(DISTINCT b.statement_seq) AS buckets, + sum(b.calls) >= 3 AS at_least_three_sleeps, + bool_and(m.wait_event = 'QueryStart') AS opened_by_querystart +FROM pg_wait_event_trace_by_statement(:procnumber) b + JOIN pg_backend_wait_event_trace m ON m.seq = b.statement_seq +WHERE b.wait_event = 'PgSleep' AND b.statement_seq > :mark10; + +-- +-- Case 11: a utility statement over the simple protocol writes QueryStart +-- and then UtilityStart; the pair is one statement. CREATE TABLE AS also +-- runs its query inside the utility (ExecStart at depth 0), which must +-- not open another bucket. +-- +SELECT coalesce(max(seq), -1) AS mark11 FROM pg_backend_wait_event_trace \gset +CREATE TEMP TABLE pwet_trace_t11 AS SELECT pg_sleep(0.01)::text AS slept11; +SELECT count(DISTINCT b.statement_seq) AS buckets, + bool_and(m.wait_event = 'QueryStart') AS opened_by_querystart +FROM pg_wait_event_trace_by_statement(:procnumber) b + JOIN pg_backend_wait_event_trace m ON m.seq = b.statement_seq +WHERE b.wait_event = 'PgSleep' AND b.statement_seq > :mark11; +DROP TABLE pwet_trace_t11; + +-- +-- Case 12: three statements in one simple-query string: one bucket each. +-- +SELECT coalesce(max(seq), -1) AS mark12 FROM pg_backend_wait_event_trace \gset +SELECT pg_sleep(0.01); SELECT pg_sleep(0.01); SELECT pg_sleep(0.01); +SELECT count(DISTINCT b.statement_seq) AS buckets, + bool_and(m.wait_event = 'QueryStart') AS opened_by_querystart +FROM pg_wait_event_trace_by_statement(:procnumber) b + JOIN pg_backend_wait_event_trace m ON m.seq = b.statement_seq +WHERE b.wait_event = 'PgSleep' AND b.statement_seq > :mark12; + +-- +-- Case 13: no wait of the whole session is lost or counted twice: the +-- function's calls add up to the number of non-marker records in the ring. +-- The ring is read before and after the function (this session can record +-- another wait in between), so the sum is bounded by the two counts; the +-- TAP test 014 checks the exact equality on a quiet session. +-- +SELECT count(*) FROM pg_get_wait_event_trace(:procnumber) +WHERE wait_event_type <> 'Query' \gset before_ +SELECT sum(calls) AS total_calls FROM pg_wait_event_trace_by_statement(:procnumber) \gset +SELECT count(*) FROM pg_get_wait_event_trace(:procnumber) +WHERE wait_event_type <> 'Query' \gset after_ +SELECT :total_calls BETWEEN :before_count AND :after_count AS no_wait_lost_or_doubled; + +RESET compute_query_id; + +RESET pg_wait_event_tracing.capture; diff --git a/contrib/pg_wait_event_tracing/t/005_orphan_reuse.pl b/contrib/pg_wait_event_tracing/t/005_orphan_reuse.pl new file mode 100644 index 00000000000..760beecea06 --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/005_orphan_reuse.pl @@ -0,0 +1,203 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: trace ring orphan lifecycle and reclaim (fix 3). +# +# On exit, a backend's trace ring is not freed: trace_state moves to +# ORPHANED and trace_owner_pid/trace_owner_start (independent of the +# stats-level owner_pid/owner_start -- see the PwetSlot comment in +# pg_wait_event_tracing.c) are left untouched, so pg_get_wait_event_trace() +# keeps attributing the ring to its producer post-mortem, like a flight +# recorder. A successor that later attaches trace on the same ProcNumber +# reclaims (frees) the orphan as a side effect of its own attach, with no +# separate step and no call to the administrative sweep function. This +# test exercises both reclaim paths: automatic (a live successor reusing +# the ProcNumber) and explicit (pg_stat_clear_orphaned_wait_event_rings(), +# for a ProcNumber nobody ever reuses). +# +# PGPROC's free list is FIFO, not LIFO: InitProcess() pops the head +# (src/backend/storage/lmgr/proc.c) and ProcKill() pushes to the tail, so +# a freed ProcNumber is only handed out again once every other free slot +# has been used first. max_connections is kept small here so that "every +# other free slot" is a short list, and a successor is found by opening +# candidate connections in a loop, each checking its own ProcNumber via +# pg_stat_get_backend_idset()/pg_stat_get_backend_pid() (the same +# ProcNumber this module's own "procnumber" column reports) and dropping +# itself if it isn't the one being waited for. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $max_connections = 10; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init(auth_extra => ['--create-role', 'regress_orphan']); +$node->append_conf('postgresql.conf', + "shared_preload_libraries = 'pg_wait_event_tracing'"); +$node->append_conf('postgresql.conf', "max_connections = $max_connections"); +# Keep pg_sleep() running in the session that issued it, not a parallel +# worker, so its wait is recorded under the pid/ring this test is +# watching. +$node->append_conf('postgresql.conf', "debug_parallel_query = off"); +$node->start; +$node->safe_psql( + 'postgres', q( +CREATE EXTENSION pg_wait_event_tracing; +CREATE ROLE regress_orphan LOGIN; +)); + +# --------------------------------------------------------------------- +# Part 1: A traces and exits; its ring stays readable post-mortem; a +# successor B that reuses A's ProcNumber gets a fresh ring, reclaiming +# (without ever calling the sweep function) A's orphan in the process. +# --------------------------------------------------------------------- +my $A = $node->background_psql('postgres'); +$A->query_safe("SET pg_wait_event_tracing.capture = trace;"); +$A->query_safe("SELECT pg_sleep(0.01);"); + +my $a_pid = $A->query_safe("SELECT pg_backend_pid();"); +my $a_procnumber = $node->safe_psql( + 'postgres', + "SELECT procnumber FROM pg_stat_wait_event_timing " + . "WHERE pid = $a_pid AND wait_event = 'PgSleep';"); +# The exact PgSleep record, read from A's own session, so its survival +# (not just "some PgSleep row") can be confirmed post-mortem below. +my $a_pgsleep_ts = $A->query_safe( + "SELECT timestamp_ns FROM pg_backend_wait_event_trace " + . "WHERE wait_event = 'PgSleep' ORDER BY seq DESC LIMIT 1;"); + +$A->quit; +$node->poll_query_until( + 'postgres', + "SELECT NOT EXISTS (SELECT 1 FROM pg_stat_activity WHERE pid = $a_pid);" +) or die "backend $a_pid did not disappear from pg_stat_activity"; + +is( $node->safe_psql( + 'postgres', + "SELECT owner_pid FROM pg_get_wait_event_trace($a_procnumber) " + . "WHERE wait_event = 'PgSleep' ORDER BY seq DESC LIMIT 1;" + ), + $a_pid, + "A's orphaned ring is still readable post-mortem, still tagged with A's pid" +); +is( $node->safe_psql( + 'postgres', + "SELECT timestamp_ns FROM pg_get_wait_event_trace($a_procnumber) " + . "WHERE wait_event = 'PgSleep' ORDER BY seq DESC LIMIT 1;" + ), + $a_pgsleep_ts, + "...and the exact PgSleep record survives, untouched, in the orphan"); + +my $B; +my $attempts = 0; +my $max_attempts = 3 * $max_connections; +while ($attempts < $max_attempts) +{ + $attempts++; + my $candidate = $node->background_psql('postgres'); + my $candidate_procnumber = $candidate->query_safe( + "SELECT id FROM pg_stat_get_backend_idset() AS id " + . "WHERE pg_stat_get_backend_pid(id) = pg_backend_pid();"); + if ($candidate_procnumber eq $a_procnumber) + { + $B = $candidate; + last; + } + $candidate->quit; +} + +SKIP: +{ + skip "ProcNumber $a_procnumber was not reused by any of $attempts " + . "connections; cannot exercise the reclaim path in this run", 3 + unless defined $B; + + my $b_pid = $B->query_safe("SELECT pg_backend_pid();"); + + # B attaches trace and records its own wait; this alone, with no call + # to pg_stat_clear_orphaned_wait_event_rings(), must reclaim A's + # orphan (pwet_attach_trace() frees any pre-existing ring at the + # slot before publishing its own). + $B->query_safe("SET pg_wait_event_tracing.capture = trace;"); + $B->query_safe("SELECT pg_sleep(0.02);"); + + is( $node->safe_psql( + 'postgres', + "SELECT owner_pid FROM pg_get_wait_event_trace($a_procnumber) " + . "WHERE wait_event = 'PgSleep' ORDER BY seq DESC LIMIT 1;" + ), + $b_pid, + "B owns a fresh ring at the reused ProcNumber"); + is( $node->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($a_procnumber) " + . "WHERE timestamp_ns = $a_pgsleep_ts;" + ), + '0', + "A's record is gone from the reclaimed ring"); + cmp_ok( + $node->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($a_procnumber) " + . "WHERE wait_event = 'PgSleep';" + ), + '>', + 0, + "...replaced by B's own PgSleep record(s)"); + + $B->quit; +} + +# --------------------------------------------------------------------- +# Part 2: A2 traces and exits; nobody reuses its ProcNumber. The +# explicit sweep function frees the orphan; a non-superuser cannot call +# it at all. +# --------------------------------------------------------------------- +my $A2 = $node->background_psql('postgres'); +$A2->query_safe("SET pg_wait_event_tracing.capture = trace;"); +$A2->query_safe("SELECT pg_sleep(0.01);"); +my $a2_pid = $A2->query_safe("SELECT pg_backend_pid();"); +my $a2_procnumber = $node->safe_psql( + 'postgres', + "SELECT procnumber FROM pg_stat_wait_event_timing " + . "WHERE pid = $a2_pid AND wait_event = 'PgSleep';"); +$A2->quit; +$node->poll_query_until( + 'postgres', + "SELECT NOT EXISTS (SELECT 1 FROM pg_stat_activity WHERE pid = $a2_pid);" +) or die "backend $a2_pid did not disappear from pg_stat_activity"; + +cmp_ok( + $node->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($a2_procnumber);"), + '>', + 0, + "A2's orphaned ring is readable before the sweep"); + +# A non-superuser cannot sweep orphaned rings. A one-shot connection is +# required here, not a BackgroundPsql session: the expected ERROR would +# make a plain background_psql session (on_error_stop by default) die. +my ($ret, $out, $err) = $node->psql( + 'postgres', + 'SELECT pg_stat_clear_orphaned_wait_event_rings();', + connstr => $node->connstr('postgres') . ' user=regress_orphan'); +isnt($ret, 0, "a non-superuser cannot sweep orphaned trace rings"); +like($err, qr/permission denied/, "...and gets a permission-denied error"); + +my $freed = $node->safe_psql('postgres', + 'SELECT pg_stat_clear_orphaned_wait_event_rings();'); +cmp_ok($freed, '>=', 1, "the superuser sweep frees at least A2's orphan"); + +is( $node->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($a2_procnumber);"), + '0', + "A2's orphan is gone after the sweep"); + +$node->stop; + +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/006_server_processes.pl b/contrib/pg_wait_event_tracing/t/006_server_processes.pl index 55961dccd04..a45e22f435e 100644 --- a/contrib/pg_wait_event_tracing/t/006_server_processes.pl +++ b/contrib/pg_wait_event_tracing/t/006_server_processes.pl @@ -57,17 +57,50 @@ $node1->safe_psql( CHECKPOINT; )); -# Case 1: rows for checkpointer, walwriter, background writer, and an I/O -# worker, despite this node never having reloaded its configuration. -for my $backend_type (qw(checkpointer walwriter), 'background writer') +# Case 1: at least one of checkpointer/walwriter/background writer has +# rows in pg_stat_wait_event_timing, despite this node never having +# reloaded its configuration. This test's subject is "a server-side +# process collects without a reload", not "every one of these three +# background processes performs a recorded wait within a fixed timeout on +# a possibly slow, idle CI runner" -- polling for each individually (an +# earlier version of this test did) is not reliable there: CI run +# 34703751075 timed out on the checkpointer check on MinGW while +# walwriter, background writer, and the I/O worker check below all +# passed within 0.1s immediately afterward (both region checks passed +# too), and the same thing happened to walwriter instead on MSVC, with +# checkpointer passing -- a different single process missing each run, +# everything else green. The module was working correctly both times. +# +# None of the fixed literal backend-type values below need SQL-escaping. +my @server_backend_types = ('checkpointer', 'walwriter', 'background writer'); +my $backend_type_list = join(', ', map { "'$_'" } @server_backend_types); + +ok( $node1->poll_query_until( + 'postgres', + "SELECT EXISTS (SELECT 1 FROM pg_stat_wait_event_timing WHERE backend_type IN ($backend_type_list))" + ), + 'at least one of checkpointer/walwriter/background writer has rows in pg_stat_wait_event_timing without a reload' +); + +# Soft, non-polling evidence for each type individually: assert only for +# whichever ones already have rows by now (the disjunction above already +# proved the reserved-region path works at all), and skip -- not fail -- +# the rest, since a specific one's own wait may simply not have landed +# yet on a slow runner. +for my $backend_type (@server_backend_types) { - # None of these fixed literal values need SQL-escaping. - ok( $node1->poll_query_until( - 'postgres', - "SELECT EXISTS (SELECT 1 FROM pg_stat_wait_event_timing WHERE backend_type = '$backend_type')" - ), - "$backend_type has rows in pg_stat_wait_event_timing without a reload" + my $has_rows = $node1->safe_psql('postgres', + "SELECT EXISTS (SELECT 1 FROM pg_stat_wait_event_timing WHERE backend_type = '$backend_type')" ); + + SKIP: + { + skip "$backend_type has no rows yet on this run; the disjunction above already covers it", + 1 + unless $has_rows eq 't'; + + ok(1, "$backend_type has rows in pg_stat_wait_event_timing without a reload"); + } } # I/O workers only exist under io_method = worker; several CI jobs force diff --git a/contrib/pg_wait_event_tracing/t/010_trace_seqlock.pl b/contrib/pg_wait_event_tracing/t/010_trace_seqlock.pl new file mode 100644 index 00000000000..e5368e663fa --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/010_trace_seqlock.pl @@ -0,0 +1,131 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Test the position-encoded identity seqlock that protects cross-backend +# reads of the wait-event trace ring (pg_wait_event_tracing.capture = +# trace). Ported from v6's +# src/test/modules/test_misc/t/016_wait_event_trace_seqlock.pl onto this +# module's names; same hazard, same assertions. +# +# The hazard: the trace writer advances write_pos and only then stamps +# the record's seq (see the injection point's comment in pwet_wait_end(), +# pg_wait_event_tracing.c). A cross-backend reader that observes the new +# write_pos before the seq store has propagated sees, at the in-flight +# ring slot, the PREVIOUS cycle's record -- complete, with an even seq. +# A parity-only seqlock would accept it and emit a stale record +# attributed to the wrong ring index; the identity check (seq must equal +# the writer's completion value for that exact position) must reject it +# instead. +# +# That window is unobservable on TSO hardware without instrumentation, +# so the writer carries INJECTION_POINT("pg-wait-event-tracing-trace- +# after-write-pos") between the write_pos advance and the seq stamp -- +# compiled in only for an injection-point build, and a no-op even there +# unless a test explicitly attaches an action to it, which is why the +# call is acceptable inside a hook that must not otherwise allocate, +# lock, wait, or ereport (see the comment beside it). This test: +# +# 1. fills and wraps a minimum-size ring (8kB = 256 records), so every +# slot holds a complete record from the previous cycle; +# 2. wedges the writer at the injection point, mid-record; +# 3. reads the ring cross-backend: the reader must return exactly +# ring_size - 1 records, skipping the in-flight slot whose stale +# prior-cycle record a parity-only check would have emitted; +# 4. releases the writer and verifies the ring reads full again. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +plan skip_all => 'Injection points not supported by this build' + unless ($ENV{enable_injection_points} // '') eq 'yes'; + +my $ring_records = 256; # 8kB ring / 32-byte records + +my $node = PostgreSQL::Test::Cluster->new('seqlock'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing, injection_points' +pg_wait_event_tracing.trace_ring_size = '8kB' +debug_parallel_query = off +)); +$node->start; + +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing;'); +$node->safe_psql('postgres', 'CREATE EXTENSION injection_points;'); + +my $point = 'pg-wait-event-tracing-trace-after-write-pos'; + +# Writer session: enable trace and wrap the ring. 400 pg_sleep calls, +# all inside one statement, emit at least 400 PgSleep wait records into a +# 256-record ring, so every slot holds a complete record from the +# current window by the time the statement finishes. +my $writer = $node->background_psql('postgres'); +$writer->query_safe("SET pg_wait_event_tracing.capture = trace;"); +$writer->query_safe( + 'SELECT count(pg_sleep(0.001)) FROM generate_series(1, 400);'); + +my $writer_proc = $writer->query_safe( + 'SELECT procnumber FROM pg_stat_get_wait_event_timing(pg_backend_pid())' + . ' LIMIT 1;'); +like($writer_proc, qr/^\d+$/, 'writer reported its procnumber'); + +# With the ring wrapped and the writer idle, a cross-backend read returns +# exactly ring_size records: every slot is complete and identity-valid +# (a mix of wait and query-marker records -- fix 6 added markers on top +# of v6's design -- but the seqlock protocol treats them identically). +my $count_full = $node->safe_psql('postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($writer_proc);"); +is($count_full, $ring_records, 'wrapped ring reads full before the wedge'); + +# Wedge the writer mid-record: arm the injection point, then send a +# statement. The arrival of the statement's bytes completes the +# writer's blocked ClientRead wait; recording that wait's completion +# advances write_pos and then blocks at the injection point, before +# stamping the record's seq. +$node->safe_psql('postgres', + "SELECT injection_points_attach('$point', 'wait');"); +$writer->query_until( + qr/wedge_sent/, q( +\echo wedge_sent +SELECT 1; +)); +$node->wait_for_event('client backend', $point); + +# The decisive read: the in-flight slot still holds the previous cycle's +# complete record. A parity-only seqlock would emit it (ring_size rows, +# one misattributed); the identity check must skip exactly that slot. +my $count_wedged = $node->safe_psql('postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($writer_proc);"); +is($count_wedged, $ring_records - 1, + 'reader skips the in-flight slot instead of emitting the stale ' + . 'prior-cycle record'); + +# The read is stable and repeatable while the writer is wedged. +my $count_wedged2 = $node->safe_psql('postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($writer_proc);"); +is($count_wedged2, $count_wedged, 'wedged-ring read is stable'); + +# Release the writer: detach first so the nested wakeup wait does not +# re-arm, then wake it. +$node->safe_psql('postgres', + "SELECT injection_points_detach('$point');"); +$node->safe_psql('postgres', "SELECT injection_points_wakeup('$point');"); + +# The writer completes the wedged record (and its pending "SELECT 1" +# statement); the ring must read full again. This query_safe's own +# return value is not meaningful (query_until above left "SELECT 1"'s +# own result unconsumed, ahead of this one in the pipe), only that it +# completes, proving the writer is no longer wedged. +$writer->query_safe("SELECT 'resync';"); +my $count_after = $node->safe_psql('postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($writer_proc);"); +is($count_after, $ring_records, 'ring reads full again after release'); + +$writer->quit; +$node->stop; + +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/011_trace_wrap.pl b/contrib/pg_wait_event_tracing/t/011_trace_wrap.pl new file mode 100644 index 00000000000..70d851bd88b --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/011_trace_wrap.pl @@ -0,0 +1,143 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: trace ring wrap, and reading it while it wraps, +# while it is disabled, and after its owner has exited. +# +# The ring's "seq" column (see pg_get_wait_event_trace() in +# pg_wait_event_tracing.c) is the ABSOLUTE, monotonically increasing +# write position, not a ring-wrapped index, so once a ring has wrapped, +# the surviving records' seq values are exactly the top ring_size +# integers the writer has produced so far: contiguous, with the oldest +# ones (the low seq values) evicted. That is what "wrapped and +# contiguous" is checked against below, with no need to reproduce the +# writer's own modular indexing in Perl. +# +# pg_sleep(0) is not a real wait on Linux (it returns without ever +# calling WaitLatch), so it would not reliably produce one PgSleep +# record per iteration; pg_sleep(0.001) always does. + +use strict; +use warnings FATAL => 'all'; + +use Time::HiRes qw(usleep); + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $ring_records = 256; # 8kB ring / 32-byte records: the GUC minimum + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +pg_wait_event_tracing.trace_ring_size = '8kB' +debug_parallel_query = off +)); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing;'); + +my $writer = $node->background_psql('postgres'); +$writer->query_safe("SET pg_wait_event_tracing.capture = trace;"); +my $writer_pid = $writer->query_safe("SELECT pg_backend_pid();"); +my $writer_proc = $writer->query_safe( + 'SELECT procnumber FROM pg_stat_get_wait_event_timing(pg_backend_pid())' + . ' LIMIT 1;'); +like($writer_proc, qr/^\d+$/, 'writer reported its procnumber'); + +# Launch, without waiting for it to finish, one statement that produces +# far more wait records than the ring holds: 800 iterations of +# pg_sleep(0.003) is ~2.4s of real waits, comfortably more than the +# handful of concurrent reads below need, and comfortably more than +# ring_records (256) waits to guarantee at least one full wrap. The +# \echo fires (and is seen by query_until) before the SELECT completes, +# handing control back to this script while the writer is still busy. +$writer->query_until( + qr/loop_started/, q( +\echo loop_started +SELECT count(pg_sleep(0.003)) FROM generate_series(1, 800); +)); + +# Concurrent reads while the writer is still (probably) running: on +# every read, whatever the reader sees must have no duplicate seq and no +# gap other than possibly missing the single newest, still-in-flight +# record (never a gap in the middle -- the writer is single-threaded and +# strictly sequential, so only the very last position it is currently +# writing can ever be caught incomplete). A read is capped at +# ring_records rows by construction (the reader never looks back further +# than one ring's worth of positions). +for my $i (1 .. 5) +{ + my $row = $node->safe_psql( + 'postgres', qq( + SELECT count(*), count(DISTINCT seq), min(seq), max(seq) + FROM pg_get_wait_event_trace($writer_proc); + )); + my ($count, $distinct_count, $min_seq, $max_seq) = split /\|/, $row; + + next unless length($count) && $count > 0; + + is($distinct_count, $count, + "concurrent read $i: no duplicate seq values"); + is($max_seq - $min_seq + 1, $count, + "concurrent read $i: no gap other than possibly the newest record"); + cmp_ok($count, '<=', $ring_records, + "concurrent read $i: never more than the ring's capacity"); + + usleep(300_000); +} + +# Let the writer's statement actually finish before checking the final, +# settled ring state. +$node->poll_query_until('postgres', + "SELECT state = 'idle' FROM pg_stat_activity WHERE pid = $writer_pid;" +) or die "writer backend $writer_pid did not go idle"; + +my $final_row = $node->safe_psql( + 'postgres', qq( + SELECT count(*), min(seq), max(seq) + FROM pg_get_wait_event_trace($writer_proc); +)); +my ($final_count, $final_min, $final_max) = split /\|/, $final_row; + +is($final_count, $ring_records, + 'record count equals the ring capacity once the writer is idle'); +is($final_max - $final_min + 1, $final_count, + 'surviving sequence numbers are contiguous'); +cmp_ok($final_min, '>', 0, + 'the oldest records (starting at seq 0) were overwritten'); + +# Reading after the writer disables trace: the ring is freed outright +# (a live step-down, not an exit -- see pwet_release_trace()), so the +# read must succeed and simply come back empty, not error. +$writer->query_safe('SET pg_wait_event_tracing.capture = stats;'); +is( $node->safe_psql('postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($writer_proc);"), + '0', + 'reading after the writer disables trace succeeds, and finds nothing' +); + +# Reading after the writer exits: re-enable trace, record one more wait +# so the ring is non-empty again, then quit the session outright. Exit +# orphans the ring instead of freeing it (fix 3; the full reclaim/sweep +# lifecycle has its own dedicated coverage in t/005_orphan_reuse.pl) -- +# here only "the read still succeeds" is being checked. +$writer->query_safe('SET pg_wait_event_tracing.capture = trace;'); +$writer->query_safe('SELECT pg_sleep(0.01);'); +$writer->quit; +$node->poll_query_until( + 'postgres', + "SELECT NOT EXISTS (SELECT 1 FROM pg_stat_activity WHERE pid = $writer_pid);" +) or die "writer backend $writer_pid did not disappear from pg_stat_activity"; + +cmp_ok( + $node->safe_psql('postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($writer_proc);"), + '>', + 0, + 'reading after the writer exits succeeds, and finds its last records'); + +$node->stop; + +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/012_trace_markers.pl b/contrib/pg_wait_event_tracing/t/012_trace_markers.pl new file mode 100644 index 00000000000..9d0398ab087 --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/012_trace_markers.pl @@ -0,0 +1,222 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: two marker-set corners the module's own regress +# test (sql/pg_wait_event_tracing_trace.sql) deliberately does not cover, +# because a deterministic .sql script cannot produce either hazard on +# demand: +# +# (a) the Idle marker. pwet_wait_begin() only synthesizes it when a +# ClientRead wait actually blocks -- and secure_read() (be-secure.c) +# only reports WAIT_EVENT_CLIENT_READ from the branch taken after a +# non-blocking read returns EWOULDBLOCK, never around a read that is +# immediately satisfied from already-buffered client bytes. Whether +# that happens for two statements sent from a .sql file depends on +# loaded-runner scheduling, not protocol structure, so the regress +# test filters Idle out of every case entirely and documents this +# exact deferral. A TAP test controls the client side directly: a +# real pause between two statements must produce an Idle marker +# between them. +# +# The opposite check -- two statements that share ONE simple-query +# protocol message never see an Idle between them -- needs an +# actual single message, not just two statements on one input +# line: CI showed that psql, reading a script from a file (or +# $node->safe_psql's string), sends each ;-terminated statement as +# its own message regardless of shared line placement, so "two +# statements, one line" was exactly as timing-dependent as the +# thing being tested, and failed on Windows/macOS while passing on +# Linux. `psql -c 'SELECT 1; SELECT 2;'` does send the whole +# string as one message; see the case's own comment below for the +# exact marker sequence that message produces and how its +# identity (needed to read the ring back afterward) is captured +# without perturbing it. Also note psql's own documented rule +# (psql-ref.sgml, "-c"/"-f"): once any -c or -f is given, psql +# never reads a script from standard input at all, so the target +# message and everything needed to identify its session must all +# be passed as -c arguments -- nothing can be layered in via the +# piped script $node->psql() would otherwise send. +# +# (b) pwet_marker_txn_abort()'s defensive pwet_exec_depth reset. The +# regress test's own error case (SELECT 1/0) raises at PLANNING +# time -- eval_const_expressions() folds the constant division +# before ExecutorStart is ever reached -- so pwet_exec_depth never +# moves and the reset is never exercised. Here, a PL/pgSQL PERFORM +# divides by a column value that is only zero on the second row of +# a table scan, so the division-by-zero can only be discovered +# while genuinely executing that nested statement. The call is +# wrapped in a PROCEDURE, not a plain function: CALL is dispatched +# through ProcessUtility (T_CallStmt in standard_ProcessUtility), +# not the executor, so the outer call contributes a UtilityStart +# marker without ever touching pwet_exec_depth, and exactly ONE +# nested executor level -- the PERFORM's own -- is left unclosed by +# the error. Without the reset, every later statement's own +# ExecStart would be off by exactly that one level. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +)); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing;'); + +# --------------------------------------------------------------------- +# (a) Idle marker: present after a real client-side pause between two +# statements, absent between two statements sent as one simple-query +# message. +# --------------------------------------------------------------------- +my $psql = $node->background_psql('postgres'); +$psql->query_safe('SET pg_wait_event_tracing.capture = trace;'); + +my $mark_a = $psql->query_safe( + "SELECT coalesce(max(seq), -1) FROM pg_backend_wait_event_trace;"); +$psql->query_safe('SELECT 1;'); + +# A real, generous client-side pause: by the time this session next +# tries to read the following message, nothing has arrived yet, so +# secure_read() genuinely blocks in WaitEventSetWait(WAIT_EVENT_CLIENT_ +# READ) -- the only place the Idle marker is synthesized (see the file +# header). A couple of seconds is comfortably more than any scheduling +# jitter on a loaded CI runner needs to be sure of that. +sleep(2); +$psql->query_safe('SELECT 2;'); + +my $markers_a = $psql->query_safe( + "SELECT string_agg(wait_event, ',' ORDER BY seq) " + . "FROM pg_backend_wait_event_trace " + . "WHERE wait_event_type = 'Query' AND seq > $mark_a;"); +like($markers_a, qr/(^|,)Idle(,|$)/, + 'a real client-side pause between two statements produces an Idle marker' +); + +$psql->quit; + +# Everything runs as -c arguments, never a piped script (see the file +# header for why the latter cannot be mixed with -c at all). Multiple +# -c's are fine -- each is processed in turn, in one connection/session +# -- so the pid/procnumber lookups run as their own two single-statement +# messages, BEFORE the target message enables capture, and so add zero +# markers to this session's ring (pwet_trace_write_marker() is a no-op +# outside capture = trace). That leaves the ring holding nothing but +# the target message's own markers, so no anchor/window bookkeeping is +# needed to isolate them from anything earlier; LIMIT 8 below only +# guards against a possible trailing Idle marker from the session's own +# eventual exit (belt-and-braces, not otherwise relied on). +# +# The target message is "SET pg_wait_event_tracing.capture = trace; +# SELECT 1; SELECT 2;" -- three statements, one message, so it can never +# see a ClientRead wait (and so no Idle) between any of them. The SET's +# effect (verified by reading exec_simple_query() in postgres.c +# directly) is visible to the later statements in the SAME message: a +# GUC assign hook runs synchronously as part of executing the SET, well +# before the message is done. But because more than one statement +# shares this message, postgres.c wraps the whole thing in one implicit +# transaction block that commits only once, when the LAST statement +# (SELECT 2) finishes -- not once per statement, unlike two statements +# each sent as their own separate message (unlike case 3 of the +# module's own regress test). So the expected marker sequence is: +# UtilityEnd for the SET (its UtilityStart is skipped: capture is still +# off when that check runs, before the SET's own assign hook has fired), +# then QueryStart/ExecStart/ExecEnd for SELECT 1 and again for SELECT 2 +# with no TxnCommit of their own (mid-block statements only get a +# CommandCounterIncrement, not a real commit), and finally one TxnCommit +# -- for the whole block -- once SELECT 2 closes it. Eight markers, +# none of them Idle, since nothing in this design ever gives the backend +# a reason to attempt a read before the message is fully processed. +# +# The session then exits (a one-shot $node->psql call, not a persistent +# BackgroundPsql session), orphaning its ring (same mechanism as +# t/005_orphan_reuse.pl), which is read back cross-backend once the +# backend is confirmed gone. +my (undef, $case2_out, undef) = $node->psql( + 'postgres', '', + on_error_die => 1, + extra_params => [ + '-c', 'SELECT pg_backend_pid();', + '-c', 'SELECT id FROM pg_stat_get_backend_idset() AS id ' + . 'WHERE pg_stat_get_backend_pid(id) = pg_backend_pid();', + '-c', 'SET pg_wait_event_tracing.capture = trace; ' + . 'SELECT 1; SELECT 2;', + ]); +my ($case2_pid, $case2_procnumber) = split /\n/, $case2_out; + +$node->poll_query_until( + 'postgres', + "SELECT NOT EXISTS (SELECT 1 FROM pg_stat_activity WHERE pid = $case2_pid);" +) or die "backend $case2_pid did not disappear from pg_stat_activity"; + +my $markers_b = $node->safe_psql( + 'postgres', qq( + SELECT string_agg(wait_event, ',' ORDER BY seq) FROM ( + SELECT wait_event, seq + FROM pg_get_wait_event_trace($case2_procnumber) + WHERE wait_event_type = 'Query' + ORDER BY seq + LIMIT 8 + ) t; +)); +is( $markers_b, + 'UtilityEnd,QueryStart,ExecStart,ExecEnd,QueryStart,ExecStart,ExecEnd,TxnCommit', + 'the SET+SELECT1+SELECT2 single message produces exactly its own ' + . 'eight markers, with no Idle between any of them'); + +# --------------------------------------------------------------------- +# (b) pwet_marker_txn_abort()'s defensive pwet_exec_depth reset, after an +# error raised during execution (not planning), inside a nested call. +# --------------------------------------------------------------------- +$node->safe_psql( + 'postgres', q( +CREATE TABLE pwet_trace_divzero_rows (d int); +INSERT INTO pwet_trace_divzero_rows VALUES (1), (0); +CREATE PROCEDURE pwet_trace_test_divzero() LANGUAGE plpgsql AS $body$ +DECLARE + r record; +BEGIN + FOR r IN SELECT d FROM pwet_trace_divzero_rows ORDER BY d DESC LOOP + PERFORM 1 / r.d; + END LOOP; +END +$body$; +)); + +# on_error_stop => 0: the CALL below is expected to fail, and the same +# session must survive it to run a following statement. A check that +# expects an ERROR must not use a plain background_psql session (its +# default on_error_stop would make psql exit on the error, and the next +# call into this session would die with "process ended prematurely"). +my $psql2 = $node->background_psql('postgres', on_error_stop => 0); +$psql2->query_safe('SET pg_wait_event_tracing.capture = trace;'); + +$psql2->query('CALL pwet_trace_test_divzero();'); +like($psql2->{stderr}, qr/division by zero/, + 'the PERFORM divides by zero on the second row, mid-execution'); +$psql2->{stderr} = ''; + +# The next, ordinary statement's own ExecStart marker is self- +# referential (same as the regress test: post_parse_analyze/ +# ExecutorStart write this SELECT's own QueryStart/ExecStart before its +# body runs), so its depth field reports the nesting level in effect +# right after the abort. Without pwet_marker_txn_abort()'s reset, the +# PERFORM's own ExecStart -- never matched by an ExecEnd, since the +# error struck mid-execution -- would leave pwet_exec_depth stuck at 1 +# forever. +my $depth = $psql2->query_safe( + "SELECT depth FROM pg_backend_wait_event_trace " + . "WHERE wait_event = 'ExecStart' ORDER BY seq DESC LIMIT 1;"); +is($depth, '0', + "a normal statement's ExecStart depth is back at 0 after the aborted CALL" +); + +$psql2->quit; +$node->stop; + +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/013_deferred_flush.pl b/contrib/pg_wait_event_tracing/t/013_deferred_flush.pl new file mode 100644 index 00000000000..d10784fd4b1 --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/013_deferred_flush.pl @@ -0,0 +1,214 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: deferred accounting (v11 patch 0004 fixup; see +# DECISION-deferred-accounting.md). pwet_wait_end_impl() no longer accounts +# a completed wait immediately: it stashes it in a one-slot, backend-local +# pending buffer, applied later by pwet_flush_pending() at the next timed +# wait or one of several other ordering/lifetime points (every SQL reader +# of a backend's own data, a marker write, a capture change, a reset, a +# release/orphan, and process exit). This file exercises the one +# consequence a single-session regress script cannot: bounded visibility +# latency for a CROSS-BACKEND reader, and the two corners that latency +# touches: +# +# (a) a wait completed by session A, immediately followed by ~2 seconds +# of pure CPU work with no further wait of its OWN in it, becomes +# visible to session B once that one statement finishes (in trace +# mode, ExecutorEnd's own flush-before-marker; either way, well +# before A next goes idle). The decision document promises a +# BOUNDED delay, not invisibility in the meantime: this file does +# not assert that B sees nothing before the statement finishes, +# because A performing some OTHER timed wait during the same +# statement -- outside this test's control, and observed in +# practice on at least one platform -- would flush the record +# earlier, which is equally correct and not a bug; +# (b) when A then exits with nothing further pending of its own, the +# ALREADY-flushed wait is not the interesting case -- this instead +# confirms that ordinary exit cleanup (pwet_before_shmem_exit()'s +# own flush, then pwet_orphan_trace()'s) does not somehow lose or +# duplicate a wait that a peer's own read had already flushed +# earlier, complementing t/005_orphan_reuse.pl's own, differently- +# timed orphan checks (there, the record is still pending at exit; +# here, it never is). +# +# A third, independent case (marker ordering in trace mode) closes with a +# statement-boundary check: a completed wait must be flushed into the +# ring before the marker that follows it, even though the two are now +# produced by different code paths (pwet_wait_begin_impl()'s flush for an +# ordinary inter-statement gap vs. post_parse_analyze's flush-before- +# marker for the next statement's own QueryStart -- see +# pwet_flush_pending()'s comment for the full list of call sites). + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +)); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing;'); + +# --------------------------------------------------------------------- +# (a)/(b): cross-backend visibility gap while A computes, closing once +# A's long statement finishes; A's exit afterward does not lose or +# duplicate anything. capture = trace throughout, so pg_stat_wait_event_ +# timing (trace "implies stats") covers the visibility-gap check and +# pg_get_wait_event_trace() covers the post-exit orphan check, in the +# same session, matching the scenario as a single continuous story. +# --------------------------------------------------------------------- +my $A = $node->background_psql('postgres'); +$A->query_safe('SET pg_wait_event_tracing.capture = trace;'); +my $a_pid = $A->query_safe('SELECT pg_backend_pid();'); + +# A's ProcNumber, needed later to read its ring post-mortem. Looked up +# via the backend id set, not pg_stat_wait_event_timing (which would +# still be empty here: A has not completed a wait yet, so it has no row +# there until the statement below runs). +my $a_procnumber = $A->query_safe( + 'SELECT id FROM pg_stat_get_backend_idset() AS id ' + . 'WHERE pg_stat_get_backend_pid(id) = pg_backend_pid();'); + +# One wait, then ~2 seconds of pure CPU work with no wait event in it at +# all, both inside the body of ONE plain SQL statement -- deliberately +# NOT a PL/pgSQL DO block: a plpgsql PERFORM (the only way to call +# pg_sleep() from inside one) always runs through SPI, which means its +# own separate, nested ExecutorStart/ExecutorEnd -- and so, in trace +# mode, this module's own flush-before-marker at THAT ExecutorEnd -- would +# flush the wait immediately after the PERFORM returns, before any +# surrounding loop even started. A single top-level statement instead +# has exactly one ExecutorStart/ExecutorEnd pair for the whole thing: +# pg_sleep() runs (and completes, becoming pending) while evaluating the +# target list, then the count(*) subquery runs entirely inside the SAME +# executor invocation, and only THAT statement's own ExecutorEnd -- once +# everything is done -- triggers a flush. AND's left-to-right, short- +# circuiting evaluation (only reached because pg_sleep() IS NULL is true) +# is what guarantees the sleep completes before the counting starts. +# generate_series(1, 30_000_000) is calibrated to run several seconds on +# this module's own debugoptimized+cassert build (the only kind these +# suites run under; see the module's own build instructions), giving +# poll_query_until below something real to poll for rather than finding +# the record already flushed on its very first check. +my $cpu_bound_rows = 30_000_000; +$A->query_until( + qr/deferred_flush_started/, qq( +\\echo deferred_flush_started +SELECT pg_sleep(0.05) IS NULL AND + (SELECT count(*) FROM generate_series(1, $cpu_bound_rows)) IS NOT NULL; +)); + +# B, a completely separate session, does NOT check here that A's PgSleep +# wait is invisible yet: DECISION-deferred-accounting.md promises only a +# bounded visibility delay, never that a cross-backend reader sees +# nothing in the meantime. A itself may incur some OTHER timed wait +# while evaluating this same statement -- nothing in its text rules that +# out, and it has been observed in practice on at least one platform (a +# wait bound up in generate_series()'s own execution, or in this +# process's ordinary background activity) -- and any such wait's own +# wait_begin would flush the pending PgSleep record right then, well +# before the statement finishes. That is not a bug: it only makes the +# delay shorter than the worst case this test is about to confirm, so +# asserting non-visibility here would be asserting a guarantee the +# module never made, flaky on any platform where it happens to be false. +# +# Once A's statement finishes, its own ExecutorEnd flushes the pending +# PgSleep record (trace mode's flush-before-marker, ahead of writing that +# statement's own ExecEnd marker). Poll rather than a fixed sleep: this +# is the actual event under test, not a guessed delay. +$node->poll_query_until( + 'postgres', + "SELECT count(*) > 0 FROM pg_stat_wait_event_timing " + . "WHERE pid = $a_pid AND wait_event = 'PgSleep';" +) or die "A's PgSleep wait never became visible to B after A's statement finished"; + +pass("A's completed wait becomes visible to B once its long statement finishes"); + +# A exits with nothing further pending of its own (the visibility check +# above already consumed/flushed the record, well before this point). +# Ordinary exit cleanup must not disturb it: the PgSleep record already +# flushed is still in the now-orphaned ring, neither lost nor duplicated. +# Not an exact count, though: pg_sleep() loops, calling WaitLatch again +# until its own clock says the requested time is up, and on some +# platforms (seen on Windows in CI) the latch timeout and that clock can +# disagree, so a single pg_sleep() call can record more than one PgSleep +# wait (see t/002_ownership.pl's comment on the same behaviour). The +# module is right to count every one of them, so this only checks "at +# least one", never an exact count. +$A->quit; +$node->poll_query_until( + 'postgres', + "SELECT NOT EXISTS (SELECT 1 FROM pg_stat_activity WHERE pid = $a_pid);" +) or die "backend $a_pid did not disappear from pg_stat_activity"; + +cmp_ok( + $node->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_get_wait_event_trace($a_procnumber) " + . "WHERE wait_event = 'PgSleep';" + ), + '>', 0, + "A's orphaned trace ring still holds at least one PgSleep wait " + . "after A's exit"); + +# --------------------------------------------------------------------- +# Marker ordering: a wait completed just before a statement boundary must +# be flushed into the ring before that statement's own QueryStart marker, +# even though the two are produced by different flush call sites +# (pwet_wait_begin_impl()'s own flush for the ordinary inter-statement +# gap, post_parse_analyze's flush-before-marker for the QueryStart). A +# real client-side pause (as in t/012_trace_markers.pl) forces a genuine +# ClientRead wait between the two statements, so the ordering is +# exercised by the SAME mechanism a real idle gap would use, not a +# same-message shortcut. +# +# Every statement issued to read the ring is itself self-referential +# (post_parse_analyze/ExecutorStart write its own QueryStart+ExecStart +# before its body runs) -- same caveat sql/pg_wait_event_tracing_trace.sql +# documents at length -- so the mark-fetching statement's own trailing +# ExecEnd/TxnCommit, and the observing statement's own leading +# QueryStart/ExecStart, both land inside the naive "seq > mark" window. +# The standard [3:count(*)-2] trim removes exactly those, in order, +# leaving only what the statements under test actually wrote; Idle is +# filtered out separately since whether it fires is not this test's +# concern. What is checked afterward, in Perl, is only the ordering +# invariant: a real QueryStart -- there are two in the trimmed sequence: +# the PgSleep statement's own (necessarily before its wait, no news +# there) and the following "SELECT 1"'s (the one actually under test) -- +# appears strictly after the single PgSleep wait record. +# --------------------------------------------------------------------- +my $B = $node->background_psql('postgres'); +$B->query_safe('SET pg_wait_event_tracing.capture = trace;'); +my $mark = $B->query_safe( + 'SELECT coalesce(max(seq), -1) FROM pg_backend_wait_event_trace;'); +$B->query_safe('SELECT pg_sleep(0.02);'); +sleep(2); +$B->query_safe('SELECT 1;'); + +my $trimmed = $B->query_safe( + "SELECT array_to_string(" + . "(array_agg(wait_event ORDER BY seq))[3:count(*)-2], ',') " + . "FROM pg_backend_wait_event_trace " + . "WHERE seq > $mark AND wait_event <> 'Idle';"); +my @events = split /,/, $trimmed; +my ($pgsleep_idx) = grep { $events[$_] eq 'PgSleep' } 0 .. $#events; +ok(defined $pgsleep_idx, "the PgSleep wait record is present in the ring") + or diag("trimmed ring contents: $trimmed"); +my $querystart_after = defined $pgsleep_idx + && $pgsleep_idx < $#events + && grep { $_ eq 'QueryStart' } @events[($pgsleep_idx + 1) .. $#events]; +ok($querystart_after, + "the pending wait is flushed into the ring before the next " + . "statement's own QueryStart marker") + or diag("trimmed ring contents: $trimmed"); + +$B->quit; +$node->stop; + +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/014_by_statement_pre.pl b/contrib/pg_wait_event_tracing/t/014_by_statement_pre.pl new file mode 100644 index 00000000000..dc0e840c407 --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/014_by_statement_pre.pl @@ -0,0 +1,190 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: pg_wait_event_trace_by_statement() attribution of +# waits that happen after a request has arrived but before its statement +# start marker is written -- the 'pre' phase -- and of requests that fail +# before any statement starts. +# +# Two sessions: A (not traced) holds an ACCESS EXCLUSIVE lock on a table, +# B (traced) runs into it. A deterministic .sql script cannot do this, +# because it needs a second session holding a lock across B's request. +# The waiter is detected by polling pg_locks, never by a fixed sleep; the +# only fixed delay is the time A keeps holding the lock once B is known +# to wait, which just makes the wait long enough to be recorded. +# +# (1) extended protocol, named prepared statement: the relation lock is +# taken in Bind (plan cache), before ExecStart. The wait must be in +# the statement bucket opened by that ExecStart, phase 'pre'. +# (2) simple protocol: the lock is taken in parse analysis, before +# QueryStart. Same expectation, bucket opened by the QueryStart. +# (3) lock_timeout expires during Bind of a prepared statement: no +# statement ever starts; the wait belongs to ''. +# Finally, on the then idle session B, the function's calls add up to +# exactly the number of non-marker records of its ring. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +compute_query_id = on +)); +$node->start; +$node->safe_psql( + 'postgres', q( +CREATE EXTENSION pg_wait_event_tracing; +CREATE TABLE pwet_pre_t (id int PRIMARY KEY, payload text); +INSERT INTO pwet_pre_t SELECT g, 'x' FROM generate_series(1, 10) g; +)); + +my $psql_a = $node->background_psql('postgres'); +my $psql_b = $node->background_psql('postgres', on_error_stop => 0); + +$psql_b->query_safe('SET pg_wait_event_tracing.capture = trace;'); +my $b_pid = $psql_b->query_safe('SELECT pg_backend_pid();'); +# B's own lookup: a cross-backend read of its timing rows could lag behind +# (its last wait is flushed only at its next wait_start). +my $b_pn = $psql_b->query_safe( + 'SELECT id FROM pg_stat_get_backend_idset() AS id ' + . 'WHERE pg_stat_get_backend_pid(id) = pg_backend_pid();'); +chomp($b_pid); +chomp($b_pn); + +# Prepare before any lock is held, so the Parse itself does not block. +$psql_b->query_safe( + "SELECT count(*) AS n FROM pwet_pre_t \\parse pwet_pre_s\n"); + +sub ring_mark +{ + return $node->safe_psql('postgres', + "SELECT coalesce(max(seq), -1) FROM pg_get_wait_event_trace($b_pn);" + ); +} + +sub wait_for_b_blocked +{ + $node->poll_query_until( + 'postgres', qq( + SELECT EXISTS (SELECT 1 FROM pg_locks + WHERE NOT granted AND locktype = 'relation' + AND relation = 'pwet_pre_t'::regclass + AND pid = $b_pid); + )) or die "backend $b_pid never blocked on the table lock"; +} + +# Lock:relation rows after $mark: "||" +sub lock_rows +{ + my ($mark) = @_; + return $node->safe_psql( + 'postgres', qq( + SELECT string_agg(coalesce(b.phase, 'NULL') || '|' || m.wait_event + || '|' || (b.query_id = m.query_id AND b.query_id <> 0), + ',' ORDER BY b.statement_seq) + FROM pg_wait_event_trace_by_statement($b_pn) b + JOIN pg_get_wait_event_trace($b_pn) m ON m.seq = b.statement_seq + WHERE b.wait_event_type = 'Lock' AND b.wait_event = 'relation' + AND b.statement_seq > $mark; + )); +} + +sub lock_calls_in +{ + my ($bucket) = @_; + return $node->safe_psql( + 'postgres', qq( + SELECT coalesce(sum(calls), 0) + FROM pg_wait_event_trace_by_statement($b_pn) + WHERE wait_event_type = 'Lock' AND wait_event = 'relation' + AND bucket = '$bucket'; + )); +} + +# --------------------------------------------------------------------- +# (1) Bind of a named prepared statement blocks on the plan's lock. +# --------------------------------------------------------------------- +my $mark1 = ring_mark(); +$psql_a->query_safe("BEGIN;\nLOCK TABLE pwet_pre_t IN ACCESS EXCLUSIVE MODE;"); +$psql_b->query_until(qr/B_SENT_1/, + "\\echo B_SENT_1\n\\bind_named pwet_pre_s \\g\n\\echo B_DONE_1\n"); +wait_for_b_blocked(); +select(undef, undef, undef, 0.2); +$psql_a->query_safe('COMMIT;'); +$psql_b->query_until(qr/B_DONE_1/, ''); + +is(lock_rows($mark1), 'pre|ExecStart|true', + 'extended protocol: Bind-time lock wait is in the execution\'s ' + . 'statement bucket, phase pre, query_id from its ExecStart'); +is(lock_calls_in(''), '0', 'extended protocol: none in '); + +# --------------------------------------------------------------------- +# (2) Parse analysis of a simple-protocol query blocks on the table. +# --------------------------------------------------------------------- +my $mark2 = ring_mark(); +$psql_a->query_safe("BEGIN;\nLOCK TABLE pwet_pre_t IN ACCESS EXCLUSIVE MODE;"); +$psql_b->query_until(qr/B_SENT_2/, + "\\echo B_SENT_2\nSELECT count(*) AS n FROM pwet_pre_t;\n\\echo B_DONE_2\n"); +wait_for_b_blocked(); +select(undef, undef, undef, 0.2); +$psql_a->query_safe('COMMIT;'); +$psql_b->query_until(qr/B_DONE_2/, ''); + +is(lock_rows($mark2), 'pre|QueryStart|true', + 'simple protocol: parse-analysis lock wait is in the query\'s ' + . 'statement bucket, phase pre, query_id from its QueryStart'); +is(lock_calls_in(''), '0', 'simple protocol: none in '); + +# --------------------------------------------------------------------- +# (3) lock_timeout during Bind: the request fails before any statement. +# --------------------------------------------------------------------- +is(lock_calls_in(''), '0', + 'no wait before the failing request'); +$psql_b->query_safe("SET lock_timeout = '100ms';"); +my $mark3 = ring_mark(); +$psql_a->query_safe("BEGIN;\nLOCK TABLE pwet_pre_t IN ACCESS EXCLUSIVE MODE;"); +my ($out3, $err3) = $psql_b->query("\\bind_named pwet_pre_s \\g\n"); +is($err3, 1, 'Bind with an expiring lock_timeout fails'); +$psql_a->query_safe('COMMIT;'); + +cmp_ok(lock_calls_in(''), '>=', 1, + 'lock wait of the failed Bind is in '); +is(lock_rows($mark3), '', + 'the failed Bind opened no statement bucket with a lock wait'); +is( $node->safe_psql( + 'postgres', qq( + SELECT count(*) FROM pg_wait_event_trace_by_statement($b_pn) + WHERE bucket = '' + AND (phase IS NOT NULL OR statement_seq IS NOT NULL + OR query_id IS NOT NULL); + )), + '0', + ' rows carry no phase, statement_seq or query_id'); + +# --------------------------------------------------------------------- +# Invariant on the quiet session B: no wait lost or counted twice. +# --------------------------------------------------------------------- +$node->poll_query_until( + 'postgres', qq( + SELECT wait_event = 'ClientRead' FROM pg_stat_activity WHERE pid = $b_pid; +)) or die "backend $b_pid did not return to ClientRead"; +is( $node->safe_psql( + 'postgres', qq( + SELECT (SELECT sum(calls) FROM pg_wait_event_trace_by_statement($b_pn)) + = (SELECT count(*) FROM pg_get_wait_event_trace($b_pn) + WHERE wait_event_type <> 'Query'); + )), + 't', + 'sum(calls) equals the number of non-marker records of the ring'); + +$psql_a->quit; +$psql_b->quit; +$node->stop; +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/015_by_statement_pgbench.pl b/contrib/pg_wait_event_tracing/t/015_by_statement_pgbench.pl new file mode 100644 index 00000000000..fbc89f3cce2 --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/015_by_statement_pgbench.pl @@ -0,0 +1,242 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: pg_wait_event_trace_by_statement() under a +# realistic client load. +# +# The earlier by-statement tests (the regress script, t/014) run one +# statement at a time from a hand-written session. A real client sends +# the same statement shapes over and over, over three different protocols +# (simple, extended, extended with prepared statements), from several +# connections at once, and a heavy lock on a hot table makes all of them +# wait in the places where a wait is not yet attributable to a statement: +# plan cache locks in Bind, relation locks in parse analysis. That is the +# convoy case seen in the field, where waits taken before a statement's +# start marker were reported in ''. +# +# For each of pgbench's three protocol modes this test runs 4 clients of a +# one-statement read-only script against a small table, with +# pg_wait_event_tracing.capture = trace (passed through PGOPTIONS, so only +# the clients are traced). Once every client has run a few statements -- +# so that in prepared mode the statements are already cached and the lock +# is taken in Bind -- a second, untraced session takes ACCESS EXCLUSIVE on +# the table, waits (polling pg_locks) until at least one client is blocked, +# holds the lock for a short while so that the wait is long enough to be +# recorded, and commits. +# +# The clients' rings are read after pgbench has finished. The ring of an +# exited backend is kept as an orphan and stays readable by procnumber, so +# there is no need to keep the clients alive; each client's procnumber is +# looked up (by pid) while it is still connected. A ring that is complete +# and final also lets the invariant below be exact. Per client: +# +# (1) sum(calls) over the function equals the number of non-marker +# records of the ring: no wait lost, none counted twice. +# (2) no wait of a type other than 'Client' is in ''. +# (3) over all clients of the mode, at least one Lock:relation wait was +# recorded, and every one of them is in a statement bucket (not +# '', '' or ''), phase 'pre' or +# 'statement'. Which phase they land in is reported with note(). +# (4) every statement bucket has a non-zero query_id. +# +# Nothing here depends on how many waits a statement records or on timing, +# apart from the wait for the pgbench clients to get going and to block, +# which is polled. + +use strict; +use warnings FATAL => 'all'; + +use IPC::Run (); +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +compute_query_id = on +max_connections = 30 +# Large enough that no client's ring wraps during a run, so that nothing +# is '' for that reason. +pg_wait_event_tracing.trace_ring_size = 8192 +)); +$node->start; +$node->safe_psql( + 'postgres', q( +CREATE EXTENSION pg_wait_event_tracing; +CREATE TABLE pwet_pgb_t (id int PRIMARY KEY, payload text); +INSERT INTO pwet_pgb_t SELECT g, 'x' FROM generate_series(1, 10) g; +)); + +my $script = $node->basedir . '/pwet_pgb.sql'; +append_to_file($script, + "\\set id random(1, 10)\n" + . "SELECT payload FROM pwet_pgb_t WHERE id = :id;\n"); + +my $clients = 4; + +# The session that blocks the clients. Not traced. +my $locker = $node->background_psql('postgres'); + +# Procnumbers of the pgbench backends and the pids they belong to. +sub client_backends +{ + my $out = $node->safe_psql( + 'postgres', q( + SELECT id || '|' || pg_stat_get_backend_pid(id) + FROM pg_stat_get_backend_idset() AS id + WHERE pg_stat_get_backend_pid(id) IN + (SELECT pid FROM pg_stat_activity + WHERE application_name = 'pwet_pgbench') + ORDER BY 1; + )); + return map { [ split /\|/ ] } split /\n/, $out; +} + +foreach my $mode (qw(simple extended prepared)) +{ + # -R keeps the rate (and with it the ring fill) low and predictable. + # -T is only an upper bound for how long the clients run; the lock + # cycle below normally takes a fraction of it. + my @cmd = ( + 'pgbench', '-n', '-M', $mode, '-c', $clients, '-j', 1, + '-R', 200, '-T', 6, '-f', $script, '-d', 'postgres', + '-h', $node->host, '-p', $node->port); + my ($pgb_out, $pgb_err) = ('', ''); + my $pgb; + { + local $ENV{PGOPTIONS} = '-c pg_wait_event_tracing.capture=trace'; + # how the clients are told apart from the test's own sessions + local $ENV{PGAPPNAME} = 'pwet_pgbench'; + $pgb = IPC::Run::start(\@cmd, '>' => \$pgb_out, '2>' => \$pgb_err, + IPC::Run::timeout($PostgreSQL::Test::Utils::timeout_default)); + } + + # All clients connected, and each has completed a few statements + # (ExecEnd markers in its own ring). + my @be; + my $ready = 0; + for (1 .. $PostgreSQL::Test::Utils::timeout_default * 10) + { + @be = client_backends(); + if (@be == $clients) + { + my $n = scalar grep { + $node->safe_psql('postgres', + "SELECT count(*) >= 20 FROM pg_get_wait_event_trace($_->[0]) " + . "WHERE wait_event = 'ExecEnd';") eq 't' + } @be; + if ($n == $clients) { $ready = 1; last; } + } + select(undef, undef, undef, 0.1); + } + ok($ready, "$mode: $clients pgbench clients connected and running"); + + my $pid_list = join(',', map { $_->[1] } @be); + + # Take the lock. This waits for statements in flight, and the + # clients queue behind it. + $locker->query_safe( + "BEGIN;\nLOCK TABLE pwet_pgb_t IN ACCESS EXCLUSIVE MODE;"); + $node->poll_query_until( + 'postgres', qq( + SELECT EXISTS (SELECT 1 FROM pg_locks + WHERE NOT granted AND locktype = 'relation' + AND relation = 'pwet_pgb_t'::regclass + AND pid IN ($pid_list)); + )) or die "no pgbench client ever blocked on the table lock"; + # The only fixed delay: make the wait long enough to be recorded. + select(undef, undef, undef, 0.2); + $locker->query_safe('COMMIT;'); + + $pgb->finish; + is($pgb->result(0), 0, "$mode: pgbench finished successfully") + or diag($pgb_err); + + $node->poll_query_until('postgres', + "SELECT NOT EXISTS (SELECT 1 FROM pg_stat_activity " + . "WHERE application_name = 'pwet_pgbench');") + or die "pgbench backends did not exit"; + + my ($lock_total, %lock_phase) = (0); + foreach my $c (@be) + { + my ($pn, $pid) = @$c; + my $name = "$mode backend $pid"; + + # The ring must still be this client's (an orphan). + is( $node->safe_psql( + 'postgres', + "SELECT count(DISTINCT owner_pid) || ',' || min(owner_pid) " + . "FROM pg_get_wait_event_trace($pn);"), + "1,$pid", + "$name: ring is the client's, read post-mortem"); + + # (1) every non-marker record counted exactly once + is( $node->safe_psql( + 'postgres', qq( + SELECT (SELECT sum(calls) + FROM pg_wait_event_trace_by_statement($pn)) + = (SELECT count(*) FROM pg_get_wait_event_trace($pn) + WHERE wait_event_type <> 'Query'); + )), + 't', + "$name: sum(calls) equals the number of non-marker records"); + + # (2) nothing but Client waits in + is( $node->safe_psql( + 'postgres', qq( + SELECT coalesce(string_agg(DISTINCT wait_event_type || ':' + || wait_event, ','), '') + FROM pg_wait_event_trace_by_statement($pn) + WHERE bucket = '' AND wait_event_type <> 'Client'; + )), + '', + "$name: no non-Client wait in "); + + # (4) statement buckets carry a query_id + is( $node->safe_psql( + 'postgres', qq( + SELECT count(*) + FROM pg_wait_event_trace_by_statement($pn) + WHERE statement_seq IS NOT NULL + AND (query_id IS NULL OR query_id = 0); + )), + '0', + "$name: every statement bucket has a non-zero query_id"); + + # (3) collect Lock:relation waits: bucket kind and phase + my $rows = $node->safe_psql( + 'postgres', qq( + SELECT CASE WHEN statement_seq IS NOT NULL THEN 'statement' + ELSE bucket END || '|' || coalesce(phase, 'NULL') + || '|' || calls + FROM pg_wait_event_trace_by_statement($pn) + WHERE wait_event_type = 'Lock' AND wait_event = 'relation'; + )); + foreach my $r (split /\n/, $rows) + { + my ($kind, $phase, $calls) = split /\|/, $r; + $lock_total += $calls; + $lock_phase{"$kind/$phase"} += $calls; + } + } + + # (3) + cmp_ok($lock_total, '>=', 1, + "$mode: at least one Lock:relation wait was recorded"); + my @bad = grep { !/^statement\/(pre|statement)$/ } sort keys %lock_phase; + is(scalar @bad, 0, + "$mode: every Lock:relation wait is in a statement bucket, " + . "phase pre or statement") + or diag("Lock:relation waits by bucket/phase: " + . join(', ', map { "$_=$lock_phase{$_}" } sort keys %lock_phase)); + note("$mode: Lock:relation waits by bucket/phase: " + . join(', ', map { "$_=$lock_phase{$_}" } sort keys %lock_phase)); +} + +$locker->quit; +$node->stop; +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/016_by_statement_oracle.pl b/contrib/pg_wait_event_tracing/t/016_by_statement_oracle.pl new file mode 100644 index 00000000000..72fa00cd2bf --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/016_by_statement_oracle.pl @@ -0,0 +1,426 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: pg_wait_event_trace_by_statement() against +# client-side ground truth. +# +# The client knows which statement it sent, and in which order. This test +# runs a fixed script of statement shapes in one traced session, each +# statement carrying a wait it causes itself (pg_sleep() inside execution, +# or a relation lock held by a second session when the wait is meant to +# happen before the statement's start marker), and checks that each wait +# is in the bucket of the statement that caused it. +# +# The expected query_id of a statement is NOT taken from the trace. Every +# statement calls ora_id(), which raises a NOTICE with the session's +# pg_stat_activity.query_id while the statement is running; the client +# collects it from the NOTICE. Query jumbling ignores constants, so each +# statement gets a distinct structure (a different number of constant +# columns), and the collected ids are asserted to be pairwise distinct +# before they are used. A statement is then found in the function's output +# by that id, and by the statement_seq order it has in the script. +# +# Waits are never counted exactly: Windows can record two PgSleep waits +# for one pg_sleep(). Where several waits are expected (a DO loop of 3 +# sleeps) the test asserts "at least". +# +# Shapes: +# simple simple protocol, single statement +# m1..m3 one simple-query message holding three statements +# ext extended protocol, unnamed statement (\bind) +# np named prepared statement, executed 3 times +# sp SQL PREPARE / EXECUTE +# pl prepared statement x3 in a pipeline with \syncpipeline +# tx1, tx2 explicit transaction BEGIN; s1; s2; COMMIT +# do DO block looping 3 times over a cached statement +# call CALL of a procedure that sleeps, COMMITs, sleeps +# err, after a statement that sleeps and then fails, and the next one +# lkb lock wait during Bind of a named prepared statement +# lks lock wait during parse analysis of a simple query +# (lock_timeout) lock_timeout expiring during Bind: '' +# +# Not tested, because a test cannot produce them deterministically (they +# depend on whether the next client message is already buffered when the +# backend looks, or on the exact point at which a wait happens between +# two statements): the documented ambiguities of statements without a +# commit between them, of a buffered next request, of a PL/pgSQL EXCEPTION +# block in a utility statement, and of pipelined Parse messages. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +compute_query_id = on +)); +$node->start; +$node->safe_psql( + 'postgres', q( +CREATE EXTENSION pg_wait_event_tracing; +CREATE TABLE ora_lock_t (id int); +INSERT INTO ora_lock_t VALUES (1); +CREATE TABLE ora_zero (d int); +INSERT INTO ora_zero VALUES (0); + +-- Report the calling session's current top-level query_id. +CREATE FUNCTION ora_id(tag text) RETURNS void LANGUAGE plpgsql AS $$ +DECLARE q bigint; +BEGIN + SELECT query_id INTO q FROM pg_stat_activity WHERE pid = pg_backend_pid(); + RAISE NOTICE 'ORA:%:%', tag, q; +END $$; + +CREATE PROCEDURE ora_proc() LANGUAGE plpgsql AS $$ +BEGIN + PERFORM ora_id('call'); + PERFORM pg_sleep(0.01); + COMMIT; + PERFORM pg_sleep(0.01); +END $$; +)); + +my $psql_a = $node->background_psql('postgres'); +my $psql_b = $node->background_psql('postgres', on_error_stop => 0); + +$psql_b->query_safe('SET pg_wait_event_tracing.capture = trace;'); +my $b_pid = $psql_b->query_safe('SELECT pg_backend_pid();'); +my $b_pn = $psql_b->query_safe( + 'SELECT id FROM pg_stat_get_backend_idset() AS id ' + . 'WHERE pg_stat_get_backend_pid(id) = pg_backend_pid();'); +chomp($b_pid); +chomp($b_pn); + +# --------------------------------------------------------------------- +# Driving session B +# --------------------------------------------------------------------- + +# tag => [ query_id, ... ] as reported by ora_id(), in order of arrival +my %ids; +# errors seen on stderr by the last b_finish() +my $b_errors = ''; +my $run_cnt = 0; + +# Send $sql and return a token to wait for. Does not wait for completion. +sub b_start +{ + my ($sql) = @_; + my $token = 'ORACLE_DONE_' . ++$run_cnt; + $psql_b->{stderr} = ''; + $psql_b->{stdin} .= "$sql\n\\warn $token\n\\echo $token\n"; + # hand the input to psql now: the caller may poll before b_finish() + $psql_b->{run}->pump_nb; + return $token; +} + +# Wait for completion, collect ora_id() notices. +sub b_finish +{ + my ($token) = @_; + pump_until($psql_b->{run}, $psql_b->{timeout}, \$psql_b->{stdout}, + qr/$token/); + pump_until($psql_b->{run}, $psql_b->{timeout}, \$psql_b->{stderr}, + qr/$token/); + my $err = $psql_b->{stderr}; + $psql_b->{stdout} = ''; + $psql_b->{stderr} = ''; + while ($err =~ /NOTICE:\s+ORA:(\w+):(-?\d+)/g) + { + push @{ $ids{$1} }, $2; + } + $err =~ s/^.*NOTICE:.*\n//mg; + $err =~ s/^.*$token.*\n?//mg; + $b_errors = $err; +} + +sub b_run +{ + b_finish(b_start(@_)); +} + +sub wait_for_b_blocked +{ + $node->poll_query_until( + 'postgres', qq( + SELECT EXISTS (SELECT 1 FROM pg_locks + WHERE NOT granted AND locktype = 'relation' + AND relation = 'ora_lock_t'::regclass + AND pid = $b_pid); + )) or die "backend $b_pid never blocked on the table lock"; +} + +# Run $sql in B while session A holds ACCESS EXCLUSIVE on ora_lock_t, and +# release it once B is known to wait (polling pg_locks; the only fixed +# delay is the hold that makes the wait long enough to be recorded). +sub b_run_blocked +{ + my ($sql) = @_; + $psql_a->query_safe( + "BEGIN;\nLOCK TABLE ora_lock_t IN ACCESS EXCLUSIVE MODE;"); + my $token = b_start($sql); + wait_for_b_blocked(); + select(undef, undef, undef, 0.2); + $psql_a->query_safe('COMMIT;'); + b_finish($token); +} + +# A statement with $k constant columns, which is what makes its query_id +# differ from every other statement's. $from is an optional FROM clause. +sub sel +{ + my ($k, $from) = @_; + return 'SELECT pg_sleep(0.01)' . (', 1' x $k) . ($from ? " $from" : ''); +} + +sub sel_param +{ + my ($k, $from) = @_; + return 'SELECT pg_sleep($1)' . (', 1' x $k) . ($from ? " $from" : ''); +} + +# The expected query_id of a plannable statement, from EXPLAIN (VERBOSE) in +# another session. pg_stat_activity.query_id cannot serve here: it holds +# the id of the first statement of a message or transaction, so the second +# and third statement of a multi-statement string would report the first's. +my %id; +sub explain_id +{ + my ($tag, $sql, $generic) = @_; + my $out = $node->safe_psql('postgres', + 'EXPLAIN (VERBOSE, COSTS OFF' . ($generic ? ', GENERIC_PLAN' : '') + . ") $sql"); + $out =~ /Query Identifier: (-?\d+)/ + or die "no Query Identifier in the plan of $tag: $out"; + $id{$tag} = $1; +} + +# --------------------------------------------------------------------- +# The script. [ tag, executions, minimum PgSleep calls over them ], in +# script order. Statements whose id can be had from EXPLAIN get it before +# they run; utility statements (EXECUTE, DO, CALL) report their own id +# with ora_id(). +# --------------------------------------------------------------------- +my @script; +my @from_notice = qw(sp do call); + +# simple protocol, single statement +explain_id('simple', sel(0)); +b_run(sel(0) . ';'); +push @script, [ 'simple', 1, 1 ]; + +# one simple-query message, three statements (\; keeps them in one message) +explain_id('m1', sel(1)); +explain_id('m2', sel(2)); +explain_id('m3', sel(3)); +b_run(sel(1) . " \;\n" . sel(2) . " \;\n" . sel(3) . ';'); +push @script, [ 'm1', 1, 1 ], [ 'm2', 1, 1 ], [ 'm3', 1, 1 ]; + +# extended protocol, unnamed statement +explain_id('ext', sel_param(4), 1); +b_run(sel_param(4) . " \\bind 0.01 \\g"); +push @script, [ 'ext', 1, 1 ]; + +# named prepared statement, three executions +explain_id('np', sel_param(5), 1); +b_run(sel_param(5) . " \\parse ora_np"); +b_run("\\bind_named ora_np 0.01 \\g\n" x 3); +push @script, [ 'np', 3, 3 ]; + +# SQL PREPARE / EXECUTE: the bucket is the EXECUTE utility statement's +b_run('PREPARE ora_sp AS SELECT ora_id(\'sp\'), pg_sleep(0.01)' + . (', 1' x 6) . ';'); +b_run('EXECUTE ora_sp;'); +push @script, [ 'sp', 1, 1 ]; + +# pipeline with a sync between the executions: each execution commits, +# and the next one starts without an Idle in between +explain_id('pl', sel_param(7), 1); +b_run(sel_param(7) . " \\parse ora_pl"); +b_run( "\\startpipeline\n" + . "\\bind_named ora_pl 0.01 \\sendpipeline\n" + . "\\syncpipeline\n" + . "\\bind_named ora_pl 0.01 \\sendpipeline\n" + . "\\syncpipeline\n" + . "\\bind_named ora_pl 0.01 \\sendpipeline\n" + . "\\endpipeline"); +push @script, [ 'pl', 3, 3 ]; + +# explicit transaction +explain_id('tx1', sel(8)); +explain_id('tx2', sel(9)); +b_run("BEGIN;\n" . sel(8) . ";\n" . sel(9) . ";\nCOMMIT;"); +push @script, [ 'tx1', 1, 1 ], [ 'tx2', 1, 1 ]; + +# DO block, looping over a cached statement +b_run( 'DO $$ BEGIN PERFORM ora_id(\'do\'); ' + . 'FOR i IN 1..3 LOOP PERFORM pg_sleep(0.01); END LOOP; END $$;'); +push @script, [ 'do', 1, 3 ]; + +# CALL of a procedure that COMMITs inside, with a sleep on each side +b_run('CALL ora_proc();'); +push @script, [ 'call', 1, 2 ]; + +# a statement that sleeps and then fails (the divisor comes from a table, +# so the error is raised during execution, after the sleep), then a normal +# statement in the same session +my $err_sql = sel(10, ', 1 / d FROM ora_zero'); +explain_id('err', $err_sql); +b_run("$err_sql;"); +like($b_errors, qr/division by zero/, 'the failing statement failed'); +explain_id('after', sel(11)); +b_run(sel(11) . ';'); +push @script, [ 'err', 1, 1 ], [ 'after', 1, 1 ]; + +# lock wait during Bind of a named prepared statement: the statement was +# parsed before the lock was taken, so the wait is in plan cache +# revalidation, before the ExecStart that opens the statement +explain_id('lkb', sel_param(12, 'FROM ora_lock_t'), 1); +b_run(sel_param(12, 'FROM ora_lock_t') . " \\parse ora_lk"); +b_run_blocked("\\bind_named ora_lk 0.01 \\g"); +push @script, [ 'lkb', 1, 1 ]; + +# lock wait during parse analysis of a simple query, before QueryStart +explain_id('lks', sel(13, 'FROM ora_lock_t')); +b_run_blocked(sel(13, 'FROM ora_lock_t') . ';'); +push @script, [ 'lks', 1, 1 ]; + +# lock_timeout expiring during Bind: no statement ever starts +b_run("SELECT count(*), 1, 2, 3 FROM ora_lock_t \\parse ora_lt"); +b_run("SET lock_timeout = '100ms';"); +$psql_a->query_safe("BEGIN;\nLOCK TABLE ora_lock_t IN ACCESS EXCLUSIVE MODE;"); +b_run("\\bind_named ora_lt \\g"); +$psql_a->query_safe('COMMIT;'); +like($b_errors, qr/lock timeout/, 'Bind with an expiring lock_timeout fails'); +b_run("RESET lock_timeout;"); + +# --------------------------------------------------------------------- +# Collect the expected ids and the function's output +# --------------------------------------------------------------------- +foreach my $tag (@from_notice) +{ + my @got = @{ $ids{$tag} || [] }; + is(scalar @got, 1, "$tag: reported its query_id once"); + $id{$tag} = $got[0]; +} +my @tags = map { $_->[0] } @script; +is(scalar(keys %{ { map { $_ => 1 } values %id } }), + scalar(@tags), 'the statements\' query_ids are pairwise distinct'); +ok(!grep({ !$_ } values %id), '...and none of them is zero'); + +# B quiet: all its waits flushed to the ring +$node->poll_query_until( + 'postgres', qq( + SELECT wait_event = 'ClientRead' FROM pg_stat_activity WHERE pid = $b_pid; +)) or die "backend $b_pid did not return to ClientRead"; + +my @rows; +foreach my $line ( + split /\n/, + $node->safe_psql( + 'postgres', qq( + SELECT bucket, statement_seq, query_id, phase, wait_event_type, + wait_event, calls + FROM pg_wait_event_trace_by_statement($b_pn); + ))) +{ + my @f = split /\|/, $line, -1; + push @rows, + { + bucket => $f[0], + seq => $f[1] eq '' ? undef : $f[1], + qid => $f[2] eq '' ? undef : $f[2], + phase => $f[3], + type => $f[4], + event => $f[5], + calls => $f[6], + }; +} + +# rows of statement $tag for $type:$event +sub rows_of +{ + my ($tag, $type, $event) = @_; + return grep { + defined $_->{qid} + && $_->{qid} eq $id{$tag} + && $_->{type} eq $type + && $_->{event} eq $event + } @rows; +} + +# --------------------------------------------------------------------- +# Every statement's sleep is in its own bucket(s), in script order +# --------------------------------------------------------------------- +my $prev_max = -1; +foreach my $s (@script) +{ + my ($tag, $execs, $min_calls) = @$s; + my @r = rows_of($tag, 'Timeout', 'PgSleep'); + my %seqs = map { $_->{seq} => 1 } @r; + my $sleeps = 0; + $sleeps += $_->{calls} foreach @r; + + is(scalar keys %seqs, $execs, + "$tag: PgSleep waits are in exactly $execs statement bucket(s)"); + cmp_ok($sleeps, '>=', $min_calls, + "$tag: at least $min_calls PgSleep call(s) in them"); + is(join(',', sort { $a cmp $b } map { $_->{phase} } @r), + join(',', ('statement') x scalar @r), + "$tag: ...in phase 'statement'"); + + my ($min, $max) = (sort { $a <=> $b } keys %seqs)[ 0, -1 ]; + cmp_ok($min // -1, '>', $prev_max, + "$tag: its bucket(s) come after those of the previous statement"); + $prev_max = $max // $prev_max; +} + +# Waits before the start marker: phase 'pre' of the statement's bucket +foreach my $tag (qw(lkb lks)) +{ + my @r = rows_of($tag, 'Lock', 'relation'); + ok(@r == 1 && $r[0]{phase} eq 'pre' && $r[0]{calls} >= 1, + "$tag: Lock:relation wait is in the statement's bucket, phase pre"); +} + +# lock_timeout during Bind: the wait is in , which has +# no statement_seq, query_id or phase +my @nostmt = grep { $_->{bucket} eq '' } @rows; +ok(@nostmt >= 1 && !grep({ $_->{type} ne 'Lock' || $_->{event} ne 'relation' } + @nostmt), + 'lock_timeout during Bind: Lock:relation wait is in '); +ok( !grep({ defined $_->{seq} || defined $_->{qid} || $_->{phase} ne '' } + @nostmt), + '...which carries no statement_seq, query_id or phase'); + +# --------------------------------------------------------------------- +# Final: nothing lost into the idle buckets, and the invariant +# --------------------------------------------------------------------- +my @lost = grep { + ($_->{bucket} eq '' || $_->{bucket} eq '') + && ($_->{event} eq 'PgSleep' || $_->{type} eq 'Lock') +} @rows; +is(scalar @lost, 0, + 'no PgSleep or Lock wait in or ') + or diag(join(', ', + map { "$_->{bucket}:$_->{type}:$_->{event}=$_->{calls}" } @lost)); + +is( $node->safe_psql( + 'postgres', qq( + SELECT (SELECT sum(calls) + FROM pg_wait_event_trace_by_statement($b_pn)) + = (SELECT count(*) FROM pg_get_wait_event_trace($b_pn) + WHERE wait_event_type <> 'Query'); + )), + 't', + 'sum(calls) equals the number of non-marker records of the ring'); + +$psql_a->quit; +$psql_b->quit; +$node->stop; +done_testing(); diff --git a/doc/src/sgml/pgwaiteventtracing.sgml b/doc/src/sgml/pgwaiteventtracing.sgml index a2050eb605e..1c41e79f75b 100644 --- a/doc/src/sgml/pgwaiteventtracing.sgml +++ b/doc/src/sgml/pgwaiteventtracing.sgml @@ -689,8 +689,10 @@ shared_preload_libraries = 'pg_wait_event_tracing' The bucket's own opening seq as - text, or the synthetic value <idle> or - <unattributed>. + text, or one of the synthetic values + <idle>, + <unattributed> or + <no-statement>. @@ -698,10 +700,10 @@ shared_preload_libraries = 'pg_wait_event_tracing' statement_seq bigint - seq of the QueryStart - or UtilityStart marker that opened this - bucket; NULL for - <idle>/<unattributed>. + seq of the QueryStart, + UtilityStart or ExecStart + marker that opened this bucket; NULL for the + synthetic buckets. @@ -710,8 +712,19 @@ shared_preload_libraries = 'pg_wait_event_tracing' query_id carried by that start - marker; NULL for - <idle>/<unattributed>. + marker; NULL for the synthetic buckets. + + + + + phase text + + + pre for waits that happened after the + statement's request arrived but before its start marker was + written (see ), + statement for the rest of a statement bucket; + NULL for the synthetic buckets. @@ -1353,39 +1366,137 @@ AFTER_STATEMENT --(QueryStart | UtilityStart)--> OPEN (no Idle emitted) pg_wait_event_trace_by_statement() assigns - every ordinary wait record to exactly one bucket, using only three - kinds of marker as boundaries: + every ordinary wait record to exactly one bucket, reading a + backend's markers in order. The number of calls over all returned + rows equals the number of ordinary (non-marker) records in the ring. + + + + A start marker is top-level when its nesting + depth is 0 and no utility statement is open. The + function tracks the number of open utility statements: a + UtilityStart adds one, a + UtilityEnd removes one (never going below zero), + and Idle and TxnAbort reset + the count; TxnCommit does not, so a + COMMIT inside a procedure leaves its + CALL open. The statements that a top-level + DO, CALL, + EXECUTE or CREATE TABLE AS + runs write their markers at depth 0 as well, but + belong to the top-level statement. - A QueryStart or UtilityStart - at nesting depth 0 opens a new statement - bucket, labelled by that marker's own seq - and query_id. Gating on depth - 0 specifically keeps a nested start (SPI from a - SQL or PL function) from appearing to close the outer statement's - own bucket. + A top-level QueryStart always opens a new + statement bucket, labelled by that marker's own + seq and + query_id. + + + + + A top-level UtilityStart or + ExecStart opens a statement bucket too, unless + the nearest preceding marker among top-level + QueryStart, UtilityStart and + ExecStart, Idle, + TxnCommit and TxnAbort is a + top-level QueryStart or + UtilityStart: that statement is already open. + So executing a named prepared statement over the extended + protocol, which writes an ExecStart without a + QueryStart, gets a bucket of its own, while a + simple query's QueryStart and + ExecStart are one bucket. An Idle or a TxnAbort marker opens the synthetic <idle> bucket. - TxnAbort is treated the same as - Idle here on the reasoning that, from an - attribution standpoint, whatever follows an abort before the next - real statement is the same kind of gap as ordinary client think - time, rather than a third, separately named bucket. + Any wait recorded before the ring's very first bucket-opening + marker — for instance, because trace was enabled partway + through an already-running session — falls into the + synthetic <unattributed> bucket. - Any wait recorded before the ring's very first boundary marker of - either kind — for instance, because trace was enabled - partway through an already-running session — falls into the - synthetic <unattributed> bucket. + Pre-statement phase. A backend can wait after + a request has arrived but before the statement's start marker is + written: on plan cache locks while binding a prepared statement, or + on relation locks during parse analysis. If no other statement + opens between the nearest Idle, + TxnCommit or TxnAbort and a + statement-opening marker, the waits in between move to that + statement's bucket, with phase + pre. Waits of type Client + (ClientRead and the like) stay in + <idle>: that is idle time. + + + + + Failed request. The waits of a request that + fails before any statement starts (a lock_timeout + expiring while binding a prepared statement, for example) are those + after an Idle and before the following + TxnAbort or TxnCommit, with + no statement opened in between and a type other than + Client. They are reported in the synthetic + <no-statement> bucket. + + + + + Every other wait stays in the bucket opened by the latest marker + above, so the waits after ExecEnd or + TxnCommit but before the next + Idle (the commit WAL flush, for example) remain + with their statement. + + + + + + Known ambiguities of the rule: + + + + + + In an explicit transaction or a pipeline with no commit between two + statements, the waits between the end of one statement and the start + marker of the next stay with the earlier statement. + + + + + When the next request was already buffered, so that no + Idle was written, end-of-transaction work after + TxnCommit is counted as the next statement's + pre phase. + + + + + An error caught by a PL/pgSQL EXCEPTION block + inside a utility statement can leave the count of open utility + statements too high, because the matching + UtilityEnd is never written. Until the next + Idle or TxnAbort the + following statements are then taken for part of that utility + statement. + + + + + When several Parse messages are pipelined ahead of their Execute + messages, the first Execute follows the last Parse's + QueryStart and is attributed to it. diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list index a5ad5a85d36..6a14f217862 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -2465,10 +2465,14 @@ PushFunction PwetCaptureLevel PwetLWLockHash PwetLWLockHashEntry +PwetMarkerState PwetRegionHeader PwetSlot PwetStats PwetTimingEntry +PwetTraceRecord +PwetTraceRowFields +PwetTraceState PyCFunction PyMethodDef PyModuleDef -- 2.49.0