From 382f87e07f8ae0d5d9f318b19bc2d5de9e07c176 Mon Sep 17 00:00:00 2001 From: Dmitry Fomin Date: Fri, 18 Sep 2026 13:51:19 +0200 Subject: [PATCH v11 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: each statement's interval runs from its start marker to the earliest of the next Idle, the next start, or a TxnAbort, with waits preceding a ring's first marker attributed 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. 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 | 255 +++ contrib/pg_wait_event_tracing/meson.build | 6 + .../pg_wait_event_tracing--1.0.sql | 156 ++ .../pg_wait_event_tracing.c | 1705 +++++++++++++++-- .../sql/pg_wait_event_tracing_trace.sql | 186 ++ .../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 +++ src/tools/pgindent/typedefs.list | 4 + 13 files changed, 3146 insertions(+), 132 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 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..dc14a3fc055 --- /dev/null +++ b/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_trace.out @@ -0,0 +1,255 @@ +-- +-- 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) + +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..fef28bccc8a 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,13 @@ 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', ], }, } 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..92a1fd34e3e 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,162 @@ 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), per plan +-- sec 5.3's rule: a statement's interval runs from its QueryStart (or +-- UtilityStart) marker to the earliest of the next Idle, the next +-- QueryStart/UtilityStart at depth 0, or TxnAbort; waits inside are +-- summed per wait event. TxnAbort is treated the same as Idle for +-- bucketing (both open the synthetic '' bucket): the plan says +-- TxnAbort ends the current statement's interval but does not name a +-- bucket for whatever follows before the next real activity, and +-- treating it as "now idle" avoids inventing an undocumented third +-- bucket for what is, from an attribution standpoint, the same kind of +-- gap. Waits before the ring's first marker of any kind are +-- ''. Depth-0 gating on QueryStart/UtilityStart matters +-- because post_parse_analyze (and, much more rarely, ProcessUtility) can +-- itself fire from inside an already-open outer statement (SPI calls +-- from a SQL/PL function); only a top-level start closes the +-- previous top-level statement's interval. +-- +-- 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 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 * FROM pg_get_wait_event_trace(procnumber) +), +marked AS ( + SELECT + seq, + wait_event_type, + wait_event, + duration_us, + query_id, + (wait_event_type = 'Query' + AND wait_event IN ('QueryStart', 'UtilityStart') + AND depth = 0) AS is_stmt_open, + (wait_event_type = 'Query' + AND wait_event IN ('Idle', 'TxnAbort')) AS is_idle_open + FROM trace +), +bucketed AS ( + SELECT + m.*, + count(*) FILTER (WHERE is_stmt_open OR is_idle_open) + OVER (ORDER BY seq ROWS BETWEEN UNBOUNDED PRECEDING AND CURRENT ROW) + AS bucket_group + FROM marked m +), +bucket_labels AS ( + SELECT + bucket_group, + CASE WHEN is_stmt_open THEN seq END AS statement_seq, + CASE WHEN is_stmt_open THEN query_id END AS bucket_query_id, + is_idle_open + FROM bucketed + WHERE is_stmt_open OR is_idle_open +) +SELECT + CASE + WHEN b.bucket_group = 0 THEN '' + WHEN bl.is_idle_open THEN '' + ELSE bl.statement_seq::text + END AS bucket, + bl.statement_seq, + bl.bucket_query_id AS query_id, + b.wait_event_type, + b.wait_event, + count(*) AS calls, + sum(b.duration_us) AS total_time_us +FROM bucketed b +LEFT JOIN bucket_labels bl USING (bucket_group) +WHERE b.wait_event_type <> 'Query' +GROUP BY b.bucket_group, bl.statement_seq, bl.bucket_query_id, bl.is_idle_open, + b.wait_event_type, b.wait_event +ORDER BY min(b.seq), b.wait_event_type, b.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..7f8917a4432 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,366 @@ 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. pg_wait_event_trace_by_statement()'s attribution rule keys its + * "next start" boundary on depth 0 specifically so a nested QueryStart + * does not appear to close the outer statement's interval. + */ +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. + * 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 +1742,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 +1783,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 +1892,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 +1904,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 +1930,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 +1975,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 +2007,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 +2052,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 +2209,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 +2381,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 +2486,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 +2548,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 +2578,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 +3262,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 +3768,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 +3798,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..592e0c36d73 --- /dev/null +++ b/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_trace.sql @@ -0,0 +1,186 @@ +-- +-- 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'; + +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/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