From 49f3ad513d71357c63869e89811620d360f15c3a Mon Sep 17 00:00:00 2001 From: Dmitry Fomin Date: Tue, 10 Nov 2026 10:59:02 +0100 Subject: [PATCH v15 9/9] pg_wait_event_tracing: transaction counters and interval report Count captured transaction completions per process slot: the commit, abort and prepare events of top-level transactions, when capture is on at that moment (so a SET LOCAL value counts), never in parallel workers. COMMIT PREPARED and ROLLBACK PREPARED are the resolving session's own committed transaction. The counters live in the lifetime ledger and only update counters; they publish no pending wait. Add pg_stat_reset_wait_event_totals(), superuser only. It never modifies a ledger: it scans all of them without a lock, then publishes the scan as a baseline, with its wall-clock times, and bumps the reset generation under a dedicated lightweight lock, retrying if another reset published meanwhile. Readers scan unlocked and subtract the baseline under a short shared lock, retrying if the generation moved; a negative result is an error. The cut is scan based, not instantaneous. Extend the info view with the generation, the reset scan times and the transaction counters, and add pg_wait_event_snapshot() (exact jsonb), pg_wait_event_diff() with ms_per_wait, waits_per_xact and ms_per_xact, and pg_wait_event_report() to the same 1.0--1.1 update script. Snapshots are validated for schema version, integer ranges, unique keys, incarnation, reset generation and non-overlapping order. Add tests for transaction counting, reset semantics including resets concurrent with emitters and readers, snapshots, diffs and reports, and document all of it. --- .../expected/pg_wait_event_tracing_totals.out | 247 +++++- .../pg_wait_event_tracing--1.0--1.1.sql | 292 ++++++- .../pg_wait_event_tracing.c | 726 ++++++++++++++++-- .../pg_wait_event_tracing.control | 2 +- .../sql/pg_wait_event_tracing_totals.sql | 127 +++ .../t/017_totals_ledger.pl | 8 +- doc/src/sgml/pgwaiteventtracing.sgml | 128 ++- src/test/modules/test_wait_totals/TwtUtil.pm | 76 ++ src/test/modules/test_wait_totals/meson.build | 3 + .../test_wait_totals/t/001_publication.pl | 5 + .../modules/test_wait_totals/t/002_exit.pl | 5 + .../test_wait_totals/t/003_capture_reset.pl | 5 + .../test_wait_totals/t/004_slots_servers.pl | 5 + .../test_wait_totals/t/005_dictionary.pl | 6 + .../test_wait_totals/t/006_coherence.pl | 5 + .../modules/test_wait_totals/t/007_restart.pl | 5 + .../test_wait_totals/t/008_transactions.pl | 162 ++++ .../modules/test_wait_totals/t/009_reset.pl | 313 ++++++++ .../modules/test_wait_totals/t/010_report.pl | 290 +++++++ 19 files changed, 2309 insertions(+), 101 deletions(-) create mode 100644 src/test/modules/test_wait_totals/TwtUtil.pm create mode 100644 src/test/modules/test_wait_totals/t/008_transactions.pl create mode 100644 src/test/modules/test_wait_totals/t/009_reset.pl create mode 100644 src/test/modules/test_wait_totals/t/010_report.pl diff --git a/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_totals.out b/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_totals.out index c4686b8b49c..6b9aa46e937 100644 --- a/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_totals.out +++ b/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_totals.out @@ -8,6 +8,9 @@ -- event makes exact assertions possible; here only things that hold whatever -- other tests did to this server are asserted. -- +-- CI configurations may force debug_parallel_query = regress; keep this +-- session's statements in this session. +SET debug_parallel_query = off; -- Version handling: 1.0 has no totals objects, the update adds them, and a -- fresh install of the default version has the same objects. DROP EXTENSION IF EXISTS pg_wait_event_tracing; @@ -73,8 +76,8 @@ SELECT attname, format_type(atttypid, atttypmod) AS type FROM pg_attribute WHERE attrelid = 'pg_stat_wait_event_totals_info'::regclass AND attnum > 0 ORDER BY attnum; - attname | type --------------------------+------------------ + attname | type +-------------------------+-------------------------- incarnation | text lwlock_overflow_calls | bigint lwlock_overflow_time_ms | double precision @@ -83,7 +86,13 @@ ORDER BY attnum; invalid_ledgers | bigint ledger_slots | integer capturing_backends | integer -(8 rows) + reset_generation | bigint + stats_reset | timestamp with time zone + reset_scan_start | timestamp with time zone + xact_commit | bigint + xact_abort | bigint + xact_prepare | bigint +(14 rows) -- One info row; the incarnation is 16 lower-case hex digits. SELECT count(*) AS info_rows FROM pg_stat_wait_event_totals_info; @@ -190,6 +199,238 @@ SELECT count(*) AS info_visible FROM pg_stat_wait_event_totals_info; 1 (1 row) +RESET ROLE; +-- Phase 2 functions: PUBLIC denied, pg_read_all_stats may read, only a +-- superuser may reset. +SELECT p.proname, + has_function_privilege('regress_pwet_plain', p.oid, 'EXECUTE') AS plain, + has_function_privilege('regress_pwet_stats', p.oid, 'EXECUTE') AS stats +FROM pg_proc p +WHERE p.proname IN ('pg_wait_event_snapshot', 'pg_wait_event_diff', + 'pg_wait_event_diff_check', 'pg_wait_event_report', + 'pg_stat_reset_wait_event_totals') +ORDER BY p.proname; + proname | plain | stats +---------------------------------+-------+------- + pg_stat_reset_wait_event_totals | f | f + pg_wait_event_diff | f | t + pg_wait_event_diff_check | f | t + pg_wait_event_report | f | t + pg_wait_event_snapshot | f | t +(5 rows) + +SET ROLE regress_pwet_plain; +SELECT pg_wait_event_snapshot(); +ERROR: permission denied for function pg_wait_event_snapshot +SELECT pg_stat_reset_wait_event_totals(); +ERROR: permission denied for function pg_stat_reset_wait_event_totals +RESET ROLE; +SET ROLE regress_pwet_stats; +SELECT jsonb_typeof(pg_wait_event_snapshot()) AS snapshot_type; + snapshot_type +--------------- + object +(1 row) + +SELECT pg_stat_reset_wait_event_totals(); +ERROR: permission denied for function pg_stat_reset_wait_event_totals RESET ROLE; DROP ROLE regress_pwet_plain; DROP ROLE regress_pwet_stats; +-- +-- Snapshot, diff and report (phase 2). +-- +SELECT array_agg(k ORDER BY k) AS snapshot_keys +FROM jsonb_object_keys(pg_wait_event_snapshot()) k; + snapshot_keys +-------------------------------------------------------------------------------------------------------------------------------------------- + {events,flat_overflow,incarnation,lwlock_overflow,reset_generation,scan_end,scan_start,schema_version,xact_abort,xact_commit,xact_prepare} +(1 row) + +SELECT pg_wait_event_snapshot()->'schema_version' AS schema_version, + jsonb_typeof(pg_wait_event_snapshot()->'events') AS events_type, + (pg_wait_event_snapshot()->>'incarnation') = (SELECT incarnation FROM pg_stat_wait_event_totals_info) AS same_incarnation; + schema_version | events_type | same_incarnation +----------------+-------------+------------------ + 1 | array | t +(1 row) + +-- Reset: the generation advances by one and the scan times appear. +SELECT reset_generation AS gen_before FROM pg_stat_wait_event_totals_info \gset +SELECT pg_stat_reset_wait_event_totals(); + pg_stat_reset_wait_event_totals +--------------------------------- + +(1 row) + +SELECT reset_generation = :gen_before + 1 AS generation_advanced, + stats_reset IS NOT NULL AS has_stats_reset, + reset_scan_start <= stats_reset AS scan_times_ordered, + xact_commit >= 0 AND xact_abort >= 0 AND xact_prepare >= 0 AS xact_columns +FROM pg_stat_wait_event_totals_info; + generation_advanced | has_stats_reset | scan_times_ordered | xact_columns +---------------------+-----------------+--------------------+-------------- + t | t | t | t +(1 row) + +-- Crafted snapshots. a: 10 commits, 2 aborts; b: 15 and 3, i.e. 6 transactions. +SELECT '{"schema_version":1,"incarnation":"00000000000000aa","reset_generation":0, + "scan_start":100,"scan_end":200,"xact_commit":10,"xact_abort":2,"xact_prepare":1, + "lwlock_overflow":{"calls":0,"total_ns":0},"flat_overflow":{"calls":0,"total_ns":0}, + "events":[{"event_key":117440513,"type":"Extension","name":"X","calls":4,"total_ns":4000000}, + {"event_key":83886080,"type":"Activity","name":"A","calls":5,"total_ns":1000000}, + {"event_key":100663296,"type":"Client","name":"ClientRead","calls":1,"total_ns":1000000}, + {"event_key":50331648,"type":"Lock","name":"relation","calls":7,"total_ns":7000000}]}'::jsonb AS a \gset +SELECT jsonb_set(jsonb_set(jsonb_set(jsonb_set(jsonb_set(jsonb_set(:'a'::jsonb, + '{scan_start}', '300'), '{scan_end}', '400'), + '{xact_commit}', '15'), '{xact_abort}', '3'), + '{lwlock_overflow}', '{"calls":3,"total_ns":3000000}'), + '{events}', '[{"event_key":117440513,"type":"Extension","name":"X","calls":10,"total_ns":10000000}, + {"event_key":117440514,"type":"Extension","name":"Y","calls":3,"total_ns":3000000}, + {"event_key":83886080,"type":"Activity","name":"A","calls":9,"total_ns":2000000}, + {"event_key":100663296,"type":"Client","name":"ClientRead","calls":4,"total_ns":4000000}, + {"event_key":50331648,"type":"Lock","name":"relation","calls":7,"total_ns":7000000}]') AS b \gset +-- waits_per_xact = waits / xacts, ms_per_xact = wait_time_ms / xacts, with +-- xacts = commit delta + abort delta = 6; interval_s from the scan midpoints. +SELECT * FROM pg_wait_event_diff(:'a', :'b'); + event_key | wait_event_type | wait_event | waits | wait_time_ms | ms_per_wait | waits_per_xact | ms_per_xact | interval_s | xacts +-----------+-----------------+------------+-------+--------------+-------------+----------------+-------------+------------+------- + -1 | LWLock | (overflow) | 3 | 3 | 1 | 0.5 | 0.5 | 0.0002 | 6 + 117440513 | Extension | X | 6 | 6 | 1 | 1 | 1 | 0.0002 | 6 + 117440514 | Extension | Y | 3 | 3 | 1 | 0.5 | 0.5 | 0.0002 | 6 +(3 rows) + +SELECT * FROM pg_wait_event_diff(:'a', :'b', true); + event_key | wait_event_type | wait_event | waits | wait_time_ms | ms_per_wait | waits_per_xact | ms_per_xact | interval_s | xacts +-----------+-----------------+------------+-------+--------------+-------------+--------------------+---------------------+------------+------- + -1 | LWLock | (overflow) | 3 | 3 | 1 | 0.5 | 0.5 | 0.0002 | 6 + 83886080 | Activity | A | 4 | 1 | 0.25 | 0.6666666666666666 | 0.16666666666666666 | 0.0002 | 6 + 100663296 | Client | ClientRead | 3 | 3 | 1 | 0.5 | 0.5 | 0.0002 | 6 + 117440513 | Extension | X | 6 | 6 | 1 | 1 | 1 | 0.0002 | 6 + 117440514 | Extension | Y | 3 | 3 | 1 | 0.5 | 0.5 | 0.0002 | 6 +(5 rows) + +-- A NULL include_idle is not true: idle rows are left out, like false. +SELECT event_key FROM pg_wait_event_diff(:'a', :'b', NULL); + event_key +----------- + -1 + 117440513 + 117440514 +(3 rows) + +-- Zero transactions: ratios per transaction are NULL. +SELECT event_key, ms_per_wait, waits_per_xact, ms_per_xact, xacts +FROM pg_wait_event_diff(:'a', jsonb_set(jsonb_set(:'b'::jsonb, '{xact_commit}', '10'), '{xact_abort}', '2')); + event_key | ms_per_wait | waits_per_xact | ms_per_xact | xacts +-----------+-------------+----------------+-------------+------- + -1 | 1 | | | 0 + 117440513 | 1 | | | 0 + 117440514 | 1 | | | 0 +(3 rows) + +-- Zero events and no change: no rows. +SELECT count(*) AS no_rows FROM pg_wait_event_diff( + jsonb_set(:'a'::jsonb, '{events}', '[]'), + jsonb_set(jsonb_set(:'b'::jsonb, '{events}', '[]'), '{lwlock_overflow}', '{"calls":0,"total_ns":0}')); + no_rows +--------- + 0 +(1 row) + +-- Errors. +\set VERBOSITY terse +SELECT * FROM pg_wait_event_diff(:'b', :'a'); +ERROR: the snapshots overlap or are in the wrong order (the second scan started before the first one ended) +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{scan_start}', '150')); +ERROR: the snapshots overlap or are in the wrong order (the second scan started before the first one ended) +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{incarnation}', '"00000000000000bb"')); +ERROR: the snapshots are from different server incarnations (00000000000000aa and 00000000000000bb) +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{reset_generation}', '1')); +ERROR: the totals were reset between the snapshots (reset_generation 0 and 1) +SELECT * FROM pg_wait_event_diff(jsonb_set(:'a'::jsonb, '{schema_version}', '2'), :'b'); +ERROR: the first snapshot has unsupported schema_version 2 +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,calls}', '1.5')); +ERROR: the second snapshot has 1 value(s) that are not integers in the bigint range +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,calls}', '-1')); +ERROR: the second snapshot has 1 value(s) that are not integers in the bigint range +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,calls}', '9223372036854775808')); +ERROR: the second snapshot has 1 value(s) that are not integers in the bigint range +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,calls}', '"7"')); +ERROR: the second snapshot has 1 value(s) that are not integers in the bigint range +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,event_key}', '4294967296')); +ERROR: the second snapshot has an event key outside the 32-bit range +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,event_key}', '-1')); +ERROR: the second snapshot has 1 value(s) that are not integers in the bigint range +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events}', + (:'b'::jsonb->'events') || (:'b'::jsonb->'events'->0))); +ERROR: the second snapshot has duplicate event keys +SELECT * FROM pg_wait_event_diff(:'a', :'b'::jsonb #- '{events,0,name}'); +ERROR: the second snapshot has a malformed event +SELECT * FROM pg_wait_event_diff(:'a', :'b'::jsonb - 'xact_abort'); +ERROR: the second argument is not a wait event snapshot +SELECT * FROM pg_wait_event_diff('[]', :'b'); +ERROR: the first argument is not a wait event snapshot +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events}', '[]')); +ERROR: event 50331648 of the first snapshot is missing from the second +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,4,calls}', '6')); +ERROR: the counters of event 50331648 decreased between the snapshots +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{xact_commit}', '9')); +ERROR: a transaction counter decreased between the snapshots +-- Report: argument validation (the sleep itself is exercised by the TAP tests). +SELECT * FROM pg_wait_event_report(0); +ERROR: seconds must be at least 1 +SELECT * FROM pg_wait_event_report(-5, true); +ERROR: seconds must be at least 1 +SELECT count(*) AS null_arg_rows FROM pg_wait_event_report(NULL); + null_arg_rows +--------------- + 0 +(1 row) + +SELECT count(*) AS null_idle_rows FROM pg_wait_event_report(1, NULL); + null_idle_rows +---------------- + 0 +(1 row) + +\set VERBOSITY default +-- The extension is not relocatable: its report functions call each other by +-- the extension schema, so they work from a schema that is not in the +-- search_path. +RESET ALL; +DROP EXTENSION pg_wait_event_tracing; +CREATE SCHEMA pwet_s; +CREATE EXTENSION pg_wait_event_tracing SCHEMA pwet_s; +SELECT extrelocatable FROM pg_extension WHERE extname = 'pg_wait_event_tracing'; + extrelocatable +---------------- + f +(1 row) + +SET search_path = pg_catalog; +-- the report's NOTICE carries the measured interval, which is never stable; +-- what a report returns is checked by the TAP tests +SET client_min_messages = warning; +SELECT count(*) IS NOT NULL AS report_runs_from_other_schema FROM pwet_s.pg_wait_event_report(1); + report_runs_from_other_schema +------------------------------- + t +(1 row) + +-- the rows of the crafted snapshots from above, through the other schema +SELECT event_key, waits, xacts FROM pwet_s.pg_wait_event_diff(:'a', :'b') ORDER BY event_key; + event_key | waits | xacts +-----------+-------+------- + -1 | 3 | 6 + 117440513 | 6 | 6 + 117440514 | 3 | 6 +(3 rows) + +RESET client_min_messages; +RESET search_path; +ALTER EXTENSION pg_wait_event_tracing SET SCHEMA public; +ERROR: extension "pg_wait_event_tracing" does not support SET SCHEMA +DROP EXTENSION pg_wait_event_tracing; +DROP SCHEMA pwet_s; +CREATE EXTENSION pg_wait_event_tracing; diff --git a/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0--1.1.sql b/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0--1.1.sql index a28c4908ff0..13a1cee7f2c 100644 --- a/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0--1.1.sql +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0--1.1.sql @@ -16,9 +16,11 @@ -- in a process) and -2 the flat overflow row (events outside the flat table); -- both keep calls and time. Both rows are always present. -- --- NOTE: version 1.1 is not final. The remaining objects of this version --- (transaction counters, reset, snapshot, diff and report) are added to this --- same script before it is released. +-- The totals count from the last pg_stat_reset_wait_event_totals() (a scan +-- based cut: see the documentation) or from server start. The snapshot, +-- diff and report functions give interval reports with per-wait and +-- per-transaction ratios; transactions are captured transaction completions +-- (commit and abort; prepare is counted apart). CREATE FUNCTION pg_stat_get_wait_event_totals( OUT wait_event_type text, OUT wait_event text, @@ -52,7 +54,13 @@ CREATE FUNCTION pg_stat_get_wait_event_totals_info( OUT flat_overflow_time_ms double precision, OUT invalid_ledgers bigint, OUT ledger_slots integer, - OUT capturing_backends integer) + OUT capturing_backends integer, + OUT reset_generation bigint, + OUT stats_reset timestamptz, + OUT reset_scan_start timestamptz, + OUT xact_commit bigint, + OUT xact_abort bigint, + OUT xact_prepare bigint) RETURNS SETOF record AS 'MODULE_PATHNAME', 'pg_stat_get_wait_event_totals_info' LANGUAGE C VOLATILE PARALLEL RESTRICTED; @@ -68,7 +76,281 @@ CREATE VIEW pg_stat_wait_event_totals_info AS t.flat_overflow_time_ms, t.invalid_ledgers, t.ledger_slots, - t.capturing_backends + t.capturing_backends, + t.reset_generation, + t.stats_reset, + t.reset_scan_start, + t.xact_commit, + t.xact_abort, + t.xact_prepare FROM pg_stat_get_wait_event_totals_info() t; REVOKE ALL ON pg_stat_wait_event_totals_info FROM PUBLIC; GRANT SELECT ON pg_stat_wait_event_totals_info TO pg_read_all_stats; + +-- Superuser only, like pg_stat_reset_wait_event_timing_all(). Does not touch +-- the per-backend statistics, and the per-backend resets never touch these. +CREATE FUNCTION pg_stat_reset_wait_event_totals() +RETURNS void +AS 'MODULE_PATHNAME', 'pg_stat_reset_wait_event_totals' +LANGUAGE C VOLATILE; +REVOKE EXECUTE ON FUNCTION pg_stat_reset_wait_event_totals() FROM PUBLIC; + +-- The totals as one jsonb document with exact integers. scan_start and +-- scan_end are wall-clock microseconds since 2000-01-01 00:00:00 UTC, taken +-- before and after the scan. +CREATE FUNCTION pg_wait_event_snapshot() +RETURNS jsonb +AS 'MODULE_PATHNAME', 'pg_wait_event_snapshot' +LANGUAGE C VOLATILE PARALLEL RESTRICTED; +REVOKE EXECUTE ON FUNCTION pg_wait_event_snapshot() FROM PUBLIC; +GRANT EXECUTE ON FUNCTION pg_wait_event_snapshot() TO pg_read_all_stats; + +-- Validate two snapshots for pg_wait_event_diff() and return the interval +-- length and the transactions between them. Interval length is the +-- difference of the scan midpoints (wall clock), in seconds. +CREATE FUNCTION pg_wait_event_diff_check(a jsonb, b jsonb, + OUT interval_s double precision, OUT xacts bigint) +LANGUAGE plpgsql +PARALLEL RESTRICTED +SET search_path = pg_catalog, pg_temp +AS $$ +DECLARE + s jsonb; + lbl text; + i int; + bad int; + dups int; + scalar_keys text[] := ARRAY['schema_version', 'reset_generation', + 'scan_start', 'scan_end', 'xact_commit', 'xact_abort', 'xact_prepare']; +BEGIN + FOR i IN 1..2 LOOP + s := CASE i WHEN 1 THEN a ELSE b END; + lbl := CASE i WHEN 1 THEN 'first' ELSE 'second' END; + + IF s IS NULL OR jsonb_typeof(s) <> 'object' + OR NOT (s ?& (scalar_keys || ARRAY['incarnation', 'lwlock_overflow', + 'flat_overflow', 'events'])) + OR jsonb_typeof(s->'incarnation') <> 'string' + OR jsonb_typeof(s->'events') <> 'array' + OR jsonb_typeof(s->'lwlock_overflow') <> 'object' + OR jsonb_typeof(s->'flat_overflow') <> 'object' + OR NOT ((s->'lwlock_overflow') ?& ARRAY['calls', 'total_ns']) + OR NOT ((s->'flat_overflow') ?& ARRAY['calls', 'total_ns']) THEN + RAISE EXCEPTION 'the % argument is not a wait event snapshot', lbl; + END IF; + + IF s->'schema_version' <> '1'::jsonb THEN + RAISE EXCEPTION 'the % snapshot has unsupported schema_version %', + lbl, s->'schema_version'; + END IF; + + IF EXISTS (SELECT 1 FROM jsonb_array_elements(s->'events') el + WHERE jsonb_typeof(el) <> 'object' + OR NOT (el ?& ARRAY['event_key', 'type', 'name', + 'calls', 'total_ns']) + OR jsonb_typeof(el->'type') <> 'string' + OR jsonb_typeof(el->'name') <> 'string') THEN + RAISE EXCEPTION 'the % snapshot has a malformed event', lbl; + END IF; + + -- Every counter must be an integer in 0 .. 2^63 - 1. + SELECT count(*) INTO bad FROM ( + SELECT value AS v FROM jsonb_each(s) WHERE key = ANY (scalar_keys) + UNION ALL SELECT value FROM jsonb_each(s->'lwlock_overflow') + UNION ALL SELECT value FROM jsonb_each(s->'flat_overflow') + UNION ALL SELECT e.value FROM jsonb_array_elements(s->'events') el, + jsonb_each(el) e WHERE e.key IN ('event_key', 'calls', 'total_ns') + ) q + WHERE jsonb_typeof(v) <> 'number' + OR (v #>> '{}')::numeric <> trunc((v #>> '{}')::numeric) + OR (v #>> '{}')::numeric NOT BETWEEN 0 AND 9223372036854775807; + IF bad > 0 THEN + RAISE EXCEPTION 'the % snapshot has % value(s) that are not integers in the bigint range', + lbl, bad; + END IF; + + -- Event keys are full wait event codes: integers in 0 .. 2^32 - 1. + IF EXISTS (SELECT 1 FROM jsonb_array_elements(s->'events') el + WHERE (el->>'event_key')::numeric NOT BETWEEN 0 AND 4294967295) THEN + RAISE EXCEPTION 'the % snapshot has an event key outside the 32-bit range', lbl; + END IF; + + SELECT count(*) INTO dups FROM ( + SELECT el->'event_key' FROM jsonb_array_elements(s->'events') el + GROUP BY 1 HAVING count(*) > 1) d; + IF dups > 0 THEN + RAISE EXCEPTION 'the % snapshot has duplicate event keys', lbl; + END IF; + END LOOP; + + IF a->>'incarnation' <> b->>'incarnation' THEN + RAISE EXCEPTION 'the snapshots are from different server incarnations (% and %)', + a->>'incarnation', b->>'incarnation'; + END IF; + IF a->'reset_generation' <> b->'reset_generation' THEN + RAISE EXCEPTION 'the totals were reset between the snapshots (reset_generation % and %)', + a->'reset_generation', b->'reset_generation'; + END IF; + IF (a->>'scan_end')::numeric < (a->>'scan_start')::numeric + OR (b->>'scan_end')::numeric < (b->>'scan_start')::numeric THEN + RAISE EXCEPTION 'a snapshot ends before it starts'; + END IF; + IF (b->>'scan_start')::numeric < (a->>'scan_end')::numeric THEN + RAISE EXCEPTION 'the snapshots overlap or are in the wrong order (the second scan started before the first one ended)'; + END IF; + + xacts := ((b->>'xact_commit')::numeric - (a->>'xact_commit')::numeric) + + ((b->>'xact_abort')::numeric - (a->>'xact_abort')::numeric); + IF (b->>'xact_commit')::numeric < (a->>'xact_commit')::numeric + OR (b->>'xact_abort')::numeric < (a->>'xact_abort')::numeric + OR (b->>'xact_prepare')::numeric < (a->>'xact_prepare')::numeric THEN + RAISE EXCEPTION 'a transaction counter decreased between the snapshots'; + END IF; + interval_s := (((b->>'scan_start')::numeric + (b->>'scan_end')::numeric) + - ((a->>'scan_start')::numeric + (a->>'scan_end')::numeric)) + / 2 / 1000000; +END; +$$; +REVOKE EXECUTE ON FUNCTION pg_wait_event_diff_check(jsonb, jsonb) FROM PUBLIC; +GRANT EXECUTE ON FUNCTION pg_wait_event_diff_check(jsonb, jsonb) TO pg_read_all_stats; + +-- What happened between two snapshots, per event. +-- waits completed waits in the interval +-- wait_time_ms their total time +-- ms_per_wait wait_time_ms / waits +-- waits_per_xact waits / xacts +-- ms_per_xact wait_time_ms / xacts +-- xacts captured transaction completions, commit + abort +-- (prepare is not counted), over all processes +-- Ratios are NULL when their denominator is zero. Rows with no change are +-- omitted. The two overflow rows (keys -1 and -2) are included. Unless +-- include_idle, the wait event type Activity and the Client event +-- ClientRead are left out; the transaction denominator is never filtered. +-- An event missing from the first snapshot counts from zero; one missing +-- from the second, or any counter that decreased, is an error. +CREATE FUNCTION pg_wait_event_diff(a jsonb, b jsonb, include_idle boolean DEFAULT false) +RETURNS TABLE ( + event_key bigint, + wait_event_type text, + wait_event text, + waits bigint, + wait_time_ms double precision, + ms_per_wait double precision, + waits_per_xact double precision, + ms_per_xact double precision, + interval_s double precision, + xacts bigint) +LANGUAGE plpgsql +PARALLEL RESTRICTED +SET search_path = pg_catalog, pg_temp +AS $$ +DECLARE + chk record; + r record; +BEGIN + SELECT * INTO chk FROM @extschema@.pg_wait_event_diff_check(a, b); + + FOR r IN + WITH ea AS ( + SELECT (el->>'event_key')::bigint AS k, el->>'type' AS t, el->>'name' AS n, + (el->>'calls')::numeric AS c, (el->>'total_ns')::numeric AS ns + FROM jsonb_array_elements(a->'events') el + UNION ALL SELECT -1, 'LWLock', '(overflow)', + (a->'lwlock_overflow'->>'calls')::numeric, + (a->'lwlock_overflow'->>'total_ns')::numeric + UNION ALL SELECT -2, '(overflow)', '(overflow)', + (a->'flat_overflow'->>'calls')::numeric, + (a->'flat_overflow'->>'total_ns')::numeric + ), eb AS ( + SELECT (el->>'event_key')::bigint AS k, el->>'type' AS t, el->>'name' AS n, + (el->>'calls')::numeric AS c, (el->>'total_ns')::numeric AS ns + FROM jsonb_array_elements(b->'events') el + UNION ALL SELECT -1, 'LWLock', '(overflow)', + (b->'lwlock_overflow'->>'calls')::numeric, + (b->'lwlock_overflow'->>'total_ns')::numeric + UNION ALL SELECT -2, '(overflow)', '(overflow)', + (b->'flat_overflow'->>'calls')::numeric, + (b->'flat_overflow'->>'total_ns')::numeric + ) + SELECT eb.k, eb.t, eb.n, eb.c - coalesce(ea.c, 0) AS dc, + eb.ns - coalesce(ea.ns, 0) AS dns, NULL::bigint AS missing + FROM eb LEFT JOIN ea USING (k) + UNION ALL + SELECT ea.k, ea.t, ea.n, 0, 0, ea.k + FROM ea WHERE ea.k NOT IN (SELECT k FROM eb) + ORDER BY 1 + LOOP + IF r.missing IS NOT NULL THEN + RAISE EXCEPTION 'event % of the first snapshot is missing from the second', r.missing; + END IF; + IF r.dc < 0 OR r.dns < 0 THEN + RAISE EXCEPTION 'the counters of event % decreased between the snapshots', r.k; + END IF; + CONTINUE WHEN r.dc = 0 AND r.dns = 0; + CONTINUE WHEN include_idle IS NOT TRUE + AND (r.t = 'Activity' OR (r.t = 'Client' AND r.n = 'ClientRead')); + + event_key := r.k; + wait_event_type := r.t; + wait_event := r.n; + waits := r.dc; + wait_time_ms := (r.dns / 1000000)::double precision; + ms_per_wait := CASE WHEN r.dc > 0 + THEN (r.dns / 1000000 / r.dc)::double precision END; + waits_per_xact := CASE WHEN chk.xacts > 0 + THEN (r.dc / chk.xacts)::double precision END; + ms_per_xact := CASE WHEN chk.xacts > 0 + THEN (r.dns / 1000000 / chk.xacts)::double precision END; + interval_s := chk.interval_s; + xacts := chk.xacts; + RETURN NEXT; + END LOOP; +END; +$$; +REVOKE EXECUTE ON FUNCTION pg_wait_event_diff(jsonb, jsonb, boolean) FROM PUBLIC; +GRANT EXECUTE ON FUNCTION pg_wait_event_diff(jsonb, jsonb, boolean) TO pg_read_all_stats; + +-- Snapshot, sleep, snapshot, diff. (The plpgsql functions here use a fixed +-- search_path and reach the extension's own functions through @extschema@, +-- which is why the extension is not relocatable.) Raises a NOTICE with the interval, the +-- transactions and the transactions per second; that is the only place a +-- result without rows shows them. Run it from a session with capture off, +-- or its own sleep is counted. +CREATE FUNCTION pg_wait_event_report(seconds integer DEFAULT 10, include_idle boolean DEFAULT false) +RETURNS TABLE ( + event_key bigint, + wait_event_type text, + wait_event text, + waits bigint, + wait_time_ms double precision, + ms_per_wait double precision, + waits_per_xact double precision, + ms_per_xact double precision, + interval_s double precision, + xacts bigint) +LANGUAGE plpgsql +STRICT +PARALLEL RESTRICTED +SET search_path = pg_catalog, pg_temp +AS $$ +DECLARE + s1 jsonb; + s2 jsonb; + chk record; +BEGIN + IF seconds < 1 THEN + RAISE EXCEPTION 'seconds must be at least 1'; + END IF; + s1 := @extschema@.pg_wait_event_snapshot(); + PERFORM pg_catalog.pg_sleep(seconds); + s2 := @extschema@.pg_wait_event_snapshot(); + SELECT * INTO chk FROM @extschema@.pg_wait_event_diff_check(s1, s2); + RAISE NOTICE 'interval % s, % transactions, % transactions per second', + round(chk.interval_s::numeric, 3), chk.xacts, + CASE WHEN chk.interval_s > 0 + THEN round((chk.xacts / chk.interval_s)::numeric, 2) END; + RETURN QUERY SELECT * FROM @extschema@.pg_wait_event_diff(s1, s2, include_idle); +END; +$$; +REVOKE EXECUTE ON FUNCTION pg_wait_event_report(integer, boolean) FROM PUBLIC; +GRANT EXECUTE ON FUNCTION pg_wait_event_report(integer, boolean) TO pg_read_all_stats; 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 241dcedd793..3fbd4eaff1d 100644 --- a/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c @@ -60,6 +60,7 @@ #include "postgres.h" #include "access/htup_details.h" +#include "access/parallel.h" #include "access/xact.h" #include "catalog/pg_authid.h" #include "catalog/pg_type_d.h" @@ -91,7 +92,10 @@ #include "utils/dsa.h" #include "utils/guc.h" #include "utils/injection_point.h" +#include "utils/jsonb.h" +#include "utils/numeric.h" #include "utils/pgstat_internal.h" +#include "utils/timestamp.h" #include "utils/tuplestore.h" #include "utils/wait_classes.h" #include "utils/wait_event.h" @@ -114,6 +118,8 @@ PG_FUNCTION_INFO_V1(pg_get_wait_event_trace); PG_FUNCTION_INFO_V1(pg_stat_clear_orphaned_wait_event_rings); PG_FUNCTION_INFO_V1(pg_stat_get_wait_event_totals); PG_FUNCTION_INFO_V1(pg_stat_get_wait_event_totals_info); +PG_FUNCTION_INFO_V1(pg_stat_reset_wait_event_totals); +PG_FUNCTION_INFO_V1(pg_wait_event_snapshot); PGDLLEXPORT void _PG_init(void); @@ -401,6 +407,7 @@ typedef struct PwetRegionHeader */ #define PWET_PGSTAT_KIND PGSTAT_KIND_EXPERIMENTAL #define PWET_TOTALS_HEADER_NAME "pg_wait_event_tracing totals header" +#define PWET_TOTALS_LOCK_NAME "pg_wait_event_tracing totals" #define PWET_LEDGERS_NAME "pg_wait_event_tracing ledgers" #define PWET_NUM_TRANCHE_IDS 65536 @@ -430,20 +437,21 @@ typedef struct PwetLedger uint32 num_used; /* dictionary cells in use */ PwetTotal lwlock_overflow; /* tranches that did not fit */ PwetTotal flat_overflow; /* events outside the flat table */ + uint64 xact_commit; /* captured transaction completions */ + uint64 xact_abort; + uint64 xact_prepare; PwetTotal flat[PWET_NUM_EVENTS]; PwetLedgerCell cells[FLEXIBLE_ARRAY_MEMBER]; /* hash_size cells */ } PwetLedger; -typedef struct PwetTotalsHeader -{ - uint64 incarnation; /* random, new at every shared memory init */ -} PwetTotalsHeader; - /* Sum over all ledgers; see pwet_totals_scan(). */ typedef struct PwetTotalsScan { PwetTotal lwlock_overflow; PwetTotal flat_overflow; + uint64 xact_commit; + uint64 xact_abort; + uint64 xact_prepare; int64 invalid_ledgers; bool sum_overflow; /* some sum exceeded what bigint can hold */ bool overflow_sum_overflow; /* ... one of the two overflow pairs */ @@ -451,6 +459,38 @@ typedef struct PwetTotalsScan PwetTotal tranche[PWET_NUM_TRANCHE_IDS]; } PwetTotalsScan; +/* + * Instance-wide control, protected (except incarnation, written once) by the + * totals lock: the reset generation, the wall-clock times of the scan that + * produced the baseline, and the baseline itself. The lock protects the + * baseline, never the ledgers. + */ +typedef struct PwetTotalsHeader +{ + uint64 incarnation; /* random, new at every shared memory init */ + uint64 reset_generation; + TimestampTz reset_scan_start; /* 0 until the first reset */ + TimestampTz reset_scan_end; + PwetTotalsScan baseline; +#ifdef USE_ASSERT_CHECKING + /* Test-only: suspend one reader between its scan and its generation check. */ + pg_atomic_uint32 test_arm; + pg_atomic_uint32 test_waiting; + pg_atomic_uint32 test_release; + pg_atomic_uint32 test_retries; +#endif +} PwetTotalsHeader; + +/* What a read of the totals knows besides the sums. */ +typedef struct PwetReadMeta +{ + uint64 generation; + TimestampTz scan_start; + TimestampTz scan_end; + TimestampTz reset_scan_start; + TimestampTz reset_scan_end; +} PwetReadMeta; + typedef struct PwetPgStatShared { uint32 unused; @@ -612,6 +652,7 @@ static uint32 pwet_last_reset_generation; * pwet_ledger_closed is set by the exit drain and never cleared. */ static PwetTotalsHeader *pwet_totals_header; +static LWLock *pwet_totals_lock; static char *pwet_ledgers; static Size pwet_ledger_bytes; static Size pwet_ledger_stride; @@ -1293,6 +1334,16 @@ pwet_totals_scan(PwetTotalsScan *scan) if (!pwet_total_sum(&scan->lwlock_overflow, ©->lwlock_overflow) || !pwet_total_sum(&scan->flat_overflow, ©->flat_overflow)) scan->sum_overflow = scan->overflow_sum_overflow = true; + if (copy->xact_commit > (uint64) PG_INT64_MAX - scan->xact_commit || + copy->xact_abort > (uint64) PG_INT64_MAX - scan->xact_abort || + copy->xact_prepare > (uint64) PG_INT64_MAX - scan->xact_prepare) + scan->sum_overflow = true; + else + { + scan->xact_commit += copy->xact_commit; + scan->xact_abort += copy->xact_abort; + scan->xact_prepare += copy->xact_prepare; + } for (i = 0; i < PWET_NUM_EVENTS; i++) if (copy->flat[i].calls != 0 && !pwet_total_sum(&scan->flat[i], ©->flat[i])) @@ -1312,6 +1363,80 @@ pwet_totals_scan(PwetTotalsScan *scan) pfree(copy); } +/* a -= b for one pair; false if it would go negative. */ +static bool +pwet_total_sub(PwetTotal *a, const PwetTotal *b) +{ + if (a->calls < b->calls || a->total_ns < b->total_ns) + return false; + a->calls -= b->calls; + a->total_ns -= b->total_ns; + return true; +} + +/* Subtract a baseline from a scan; false if anything would go negative. */ +static bool +pwet_totals_subtract(PwetTotalsScan *scan, const PwetTotalsScan *base) +{ + bool ok = true; + int i; + + ok &= pwet_total_sub(&scan->lwlock_overflow, &base->lwlock_overflow); + ok &= pwet_total_sub(&scan->flat_overflow, &base->flat_overflow); + if (scan->xact_commit < base->xact_commit || + scan->xact_abort < base->xact_abort || + scan->xact_prepare < base->xact_prepare) + ok = false; + else + { + scan->xact_commit -= base->xact_commit; + scan->xact_abort -= base->xact_abort; + scan->xact_prepare -= base->xact_prepare; + } + for (i = 0; i < PWET_NUM_EVENTS; i++) + ok &= pwet_total_sub(&scan->flat[i], &base->flat[i]); + for (i = 0; i < PWET_NUM_TRANCHE_IDS; i++) + ok &= pwet_total_sub(&scan->tranche[i], &base->tranche[i]); + return ok; +} + +/* + * Count one captured transaction completion in this process's ledger, inside + * the write bracket; a counter that would exceed bigint marks the ledger + * invalid, like the wait pairs. Not reachable from a wait-event hook. + */ +static void +pwet_ledger_count_xact(PwetLedger *l, XactEvent event) +{ + uint64 *counter; + + switch (event) + { + case XACT_EVENT_COMMIT: + counter = &l->xact_commit; + break; + case XACT_EVENT_ABORT: + counter = &l->xact_abort; + break; + case XACT_EVENT_PREPARE: + counter = &l->xact_prepare; + break; + default: + return; + } + + pwet_ledger_begin(l); + if (*counter >= (uint64) PG_INT64_MAX) + { + l->invalid = 1; + if (l->invalid_events < PG_UINT32_MAX) + l->invalid_events++; + } + else + (*counter)++; + pwet_ledger_end(l); +} + /* Initialize a freshly created control table: mark every slot empty. */ static void pwet_control_init(PwetSlot *slots) @@ -1395,6 +1520,7 @@ pwet_shmem_request(void) RequestAddinShmemSpace(pwet_control_size(PWET_NUM_SLOTS)); RequestNamedLWLockTranche(PWET_CONTROL_NAME, 1); + RequestNamedLWLockTranche(PWET_TOTALS_LOCK_NAME, 1); RequestAddinShmemSpace(sizeof(PwetRegionHeader)); RequestAddinShmemSpace(sizeof(PwetTotalsHeader)); RequestAddinShmemSpace(mul_size(PWET_NUM_SLOTS, @@ -1453,6 +1579,7 @@ pwet_shmem_startup(void) pwet_server_region = NULL; pwet_lock = &(GetNamedLWLockTranche(PWET_CONTROL_NAME))->lock; + pwet_totals_lock = &(GetNamedLWLockTranche(PWET_TOTALS_LOCK_NAME))->lock; pwet_ctl = (PwetSlot *) ShmemInitStruct(PWET_CONTROL_STRUCT_NAME, pwet_control_size(PWET_NUM_SLOTS), @@ -1483,7 +1610,14 @@ pwet_shmem_startup(void) ereport(ERROR, (errcode(ERRCODE_INTERNAL_ERROR), errmsg("could not generate a random incarnation for wait event totals"))); + memset(pwet_totals_header, 0, sizeof(PwetTotalsHeader)); pwet_totals_header->incarnation = incarnation; +#ifdef USE_ASSERT_CHECKING + pg_atomic_init_u32(&pwet_totals_header->test_arm, 0); + pg_atomic_init_u32(&pwet_totals_header->test_waiting, 0); + pg_atomic_init_u32(&pwet_totals_header->test_release, 0); + pg_atomic_init_u32(&pwet_totals_header->test_retries, 0); +#endif } pwet_ledgers = (char *) ShmemInitStruct(PWET_LEDGERS_NAME, @@ -2184,6 +2318,22 @@ pwet_marker_txn_abort(void) static void pwet_xact_callback(XactEvent event, void *arg) { + /* + * Count the transaction completion first, if capture is on right now. + * The callback runs before end-of-transaction GUC restoration, so the + * setting in effect is the transaction's own (a SET LOCAL one included). + * Parallel workers are skipped: they also run ordinary initialization + * transactions, and the leader counts the query's transaction. Only the + * counters change here; a pending wait is not flushed. + */ + if (pwet_capture != PWET_CAPTURE_OFF && !IsParallelWorker()) + { + PwetLedger *ledger = pwet_get_my_ledger(); + + if (ledger != NULL) + pwet_ledger_count_xact(ledger, event); + } + if (pwet_capture != PWET_CAPTURE_TRACE || pwet_my_trace == NULL) return; @@ -3882,6 +4032,14 @@ typedef struct PwetCustomName const char *name; } PwetCustomName; +/* Lazily built table of the registered custom event names. */ +typedef struct PwetNameContext +{ + PwetCustomName *custom; + int ncustom; + bool have_custom; +} PwetNameContext; + static int pwet_collect_custom_names(PwetCustomName **map) { @@ -3916,6 +4074,68 @@ pwet_collect_custom_names(PwetCustomName **map) return n; } +/* Type and name of an event code that has captured waits. */ +static void +pwet_event_names(uint32 info, PwetNameContext *ctx, const char **type, + const char **name) +{ + *type = pgstat_get_wait_event_type(info); + *name = NULL; + + /* + * The unnamed built-in Extension event is not in the custom-name table; + * core resolves it as "Extension". + */ + if (info == PG_WAIT_EXTENSION) + *name = "Extension"; + else if ((info & PWET_WAIT_EVENT_CLASS_MASK) == PG_WAIT_EXTENSION || + (info & PWET_WAIT_EVENT_CLASS_MASK) == PG_WAIT_INJECTIONPOINT) + { + int k; + + if (!ctx->have_custom) + { + ctx->ncustom = pwet_collect_custom_names(&ctx->custom); + ctx->have_custom = true; + } + for (k = 0; k < ctx->ncustom; k++) + if (ctx->custom[k].info == info) + *name = ctx->custom[k].name; + } + else + *name = pgstat_get_wait_event(info); + + if (*name == NULL) + *name = psprintf("unknown_%u", info & PWET_WAIT_EVENT_ID_MASK); +} + +/* + * Iterate over the events of a scan that have calls, in key order: flat + * events by index, then LWLock tranches by id. The callback gets the code. + */ +typedef void (*PwetEventVisitor) (uint32 info, const PwetTotal *t, void *arg); + +static void +pwet_visit_events(const PwetTotalsScan *scan, PwetEventVisitor visit, void *arg) +{ + int i; + int j; + int id; + + for (i = 0; i < PWET_DENSE_CLASSES; i++) + { + uint32 class_id = pwet_dense_to_classid[i]; + int base = pwet_class_offset[i]; + + for (j = 0; j < pwet_class_nevents[i]; j++) + if (scan->flat[base + j].calls != 0) + visit((class_id << 24) | (uint32) j, &scan->flat[base + j], arg); + } + for (id = 0; id < PWET_NUM_TRANCHE_IDS; id++) + if (scan->tranche[id].calls != 0) + visit(PG_WAIT_LWLOCK | (uint32) id, &scan->tranche[id], arg); +} + static void pwet_totals_put_row(ReturnSetInfo *rsinfo, const char *type, const char *name, int64 key, const PwetTotal *t) @@ -3936,31 +4156,112 @@ pwet_totals_put_row(ReturnSetInfo *rsinfo, const char *type, const char *name, tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls); } +typedef struct PwetRowsArg +{ + ReturnSetInfo *rsinfo; + PwetNameContext names; +} PwetRowsArg; + +static void +pwet_totals_row_visitor(uint32 info, const PwetTotal *t, void *arg) +{ + PwetRowsArg *ra = (PwetRowsArg *) arg; + const char *type; + const char *name; + + pwet_event_names(info, &ra->names, &type, &name); + pwet_totals_put_row(ra->rsinfo, type, name, (int64) info, t); +} + /* - * SQL function: pg_stat_get_wait_event_totals() + * The totals since the last reset: the sum over all ledgers minus the + * baseline the last reset published. * - * One row per event that has completed at least one captured wait since - * the server started, summed over all processes that ever ran, plus the - * two overflow rows (always present). ERRORs if any contributing ledger is - * invalid or a sum cannot be represented. + * Read the generation under a short shared lock, scan without the lock (the + * scan is interruptible and takes as long as it takes), then take the lock + * again: if the generation moved, a reset published a new baseline during + * the scan, so start over; otherwise subtract the baseline, which cannot + * change while the lock is held. The lock protects the baseline, not the + * coherence of the ledgers. scan_start/scan_end are wall-clock times around + * the scan that produced the result. *negative is set if a pair came out + * negative after subtraction, which only a bug could cause; callers decide + * whether that is an error. */ -Datum -pg_stat_get_wait_event_totals(PG_FUNCTION_ARGS) +#ifdef USE_ASSERT_CHECKING +/* + * Test-only: if armed, the next reader to get here waits (interruptibly, + * holding no lock) until released, so a test can publish a reset while a + * scan is in flight. + */ +static void +pwet_test_read_barrier(void) { - ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; - PwetTotalsScan *scan; - PwetCustomName *custom = NULL; - int ncustom = 0; - bool have_custom = false; - int i; - int j; - int id; + uint32 expected = 1; - InitMaterializedSRF(fcinfo, 0); + if (pg_atomic_compare_exchange_u32(&pwet_totals_header->test_arm, + &expected, 0)) + { + pg_atomic_write_u32(&pwet_totals_header->test_waiting, 1); + PG_TRY(); + { + while (pg_atomic_read_u32(&pwet_totals_header->test_release) == 0) + { + CHECK_FOR_INTERRUPTS(); + pg_usleep(1000); + } + } + PG_FINALLY(); + { + /* also when canceled: the flag must not stay set */ + pg_atomic_write_u32(&pwet_totals_header->test_waiting, 0); + } + PG_END_TRY(); + } +} +#endif - scan = palloc0(sizeof(PwetTotalsScan)); - pwet_totals_scan(scan); +static void +pwet_totals_read(PwetTotalsScan *scan, PwetReadMeta *meta, bool *negative) +{ + for (;;) + { + uint64 gen; + + LWLockAcquire(pwet_totals_lock, LW_SHARED); + gen = pwet_totals_header->reset_generation; + meta->reset_scan_start = pwet_totals_header->reset_scan_start; + meta->reset_scan_end = pwet_totals_header->reset_scan_end; + LWLockRelease(pwet_totals_lock); + + memset(scan, 0, sizeof(PwetTotalsScan)); + meta->scan_start = GetCurrentTimestamp(); + pwet_totals_scan(scan); + meta->scan_end = GetCurrentTimestamp(); +#ifdef USE_ASSERT_CHECKING + pwet_test_read_barrier(); +#endif + + LWLockAcquire(pwet_totals_lock, LW_SHARED); + if (pwet_totals_header->reset_generation == gen) + { + *negative = !scan->sum_overflow && + !pwet_totals_subtract(scan, &pwet_totals_header->baseline); + LWLockRelease(pwet_totals_lock); + meta->generation = gen; + return; + } + LWLockRelease(pwet_totals_lock); +#ifdef USE_ASSERT_CHECKING + pg_atomic_fetch_add_u32(&pwet_totals_header->test_retries, 1); +#endif + CHECK_FOR_INTERRUPTS(); + } +} +/* Raise the errors totals, snapshot and reset share. */ +static void +pwet_totals_check(const PwetTotalsScan *scan, bool negative) +{ if (scan->invalid_ledgers > 0) ereport(ERROR, (errcode(ERRCODE_DATA_CORRUPTED), @@ -3971,62 +4272,39 @@ pg_stat_get_wait_event_totals(PG_FUNCTION_ARGS) ereport(ERROR, (errcode(ERRCODE_NUMERIC_VALUE_OUT_OF_RANGE), errmsg("wait event totals exceed the bigint range"))); + if (negative) + ereport(ERROR, + (errcode(ERRCODE_DATA_CORRUPTED), + errmsg("wait event totals went below the reset baseline"), + errdetail("This is a bug: lifetime ledgers never decrease."))); +} - for (i = 0; i < PWET_DENSE_CLASSES; i++) - { - uint32 class_id = pwet_dense_to_classid[i]; - int base = pwet_class_offset[i]; - - for (j = 0; j < pwet_class_nevents[i]; j++) - { - PwetTotal *t = &scan->flat[base + j]; - uint32 info = (class_id << 24) | (uint32) j; - const char *name = NULL; - - if (t->calls == 0) - continue; - - /* - * The unnamed built-in Extension event is not in the custom-name - * table; core resolves it as "Extension". - */ - if (info == PG_WAIT_EXTENSION) - name = "Extension"; - else if ((info & PWET_WAIT_EVENT_CLASS_MASK) == PG_WAIT_EXTENSION || - (info & PWET_WAIT_EVENT_CLASS_MASK) == PG_WAIT_INJECTIONPOINT) - { - int k; - - if (!have_custom) - { - ncustom = pwet_collect_custom_names(&custom); - have_custom = true; - } - for (k = 0; k < ncustom; k++) - if (custom[k].info == info) - name = custom[k].name; - } - else - name = pgstat_get_wait_event(info); - - if (name == NULL) - name = psprintf("unknown_%u", info & PWET_WAIT_EVENT_ID_MASK); +/* + * SQL function: pg_stat_get_wait_event_totals() + * + * One row per event that has completed at least one captured wait since + * the last reset (or server start), summed over all processes that ever ran, + * plus the two overflow rows (always present). ERRORs if any contributing + * ledger is invalid or a sum cannot be represented. + */ +Datum +pg_stat_get_wait_event_totals(PG_FUNCTION_ARGS) +{ + ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + PwetTotalsScan *scan; + PwetReadMeta meta; + PwetRowsArg ra; + bool negative; - pwet_totals_put_row(rsinfo, pgstat_get_wait_event_type(info), - name, (int64) info, t); - } - } + InitMaterializedSRF(fcinfo, 0); - for (id = 0; id < PWET_NUM_TRANCHE_IDS; id++) - { - PwetTotal *t = &scan->tranche[id]; - uint32 info = PG_WAIT_LWLOCK | (uint32) id; + scan = palloc(sizeof(PwetTotalsScan)); + pwet_totals_read(scan, &meta, &negative); + pwet_totals_check(scan, negative); - if (t->calls == 0) - continue; - pwet_totals_put_row(rsinfo, "LWLock", pgstat_get_wait_event(info), - (int64) info, t); - } + memset(&ra, 0, sizeof(ra)); + ra.rsinfo = rsinfo; + pwet_visit_events(scan, pwet_totals_row_visitor, &ra); pwet_totals_put_row(rsinfo, "LWLock", "(overflow)", PWET_KEY_LWLOCK_OVERFLOW, &scan->lwlock_overflow); @@ -4079,25 +4357,31 @@ pwet_slot_owner_is_live(int slot) * One row of bookkeeping: the incarnation (random, new for every shared * memory initialization, so a change means the totals restarted from zero), * the overflow pairs, the number of invalid ledgers, the number of ledger - * slots, and the number of backends currently holding a collection payload - * (advisory: read without a lock; exited processes are not counted). Unlike the totals it never raises for - * invalid accounting, so the diagnostics stay readable; an overflow column - * whose sum cannot be a bigint is NULL. + * slots, the number of backends currently holding a collection payload + * (advisory: read without a lock; exited processes are not counted), the + * reset generation and the times of the last reset's scan, and the captured + * transaction completions. Unlike the totals it never raises for invalid + * accounting, so the diagnostics stay readable; a column whose sum cannot be + * represented, or that came out negative, is NULL. */ Datum pg_stat_get_wait_event_totals_info(PG_FUNCTION_ARGS) { ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; PwetTotalsScan *scan; - Datum values[8]; - bool nulls[8] = {0}; + PwetReadMeta meta; + Datum values[14]; + bool nulls[14] = {0}; int capturing = 0; + bool negative; + bool unusable; int i; InitMaterializedSRF(fcinfo, 0); - scan = palloc0(sizeof(PwetTotalsScan)); - pwet_totals_scan(scan); + scan = palloc(sizeof(PwetTotalsScan)); + pwet_totals_read(scan, &meta, &negative); + unusable = scan->sum_overflow || negative; for (i = 0; i < PWET_NUM_SLOTS; i++) if (pwet_slot_owner_is_live(i)) @@ -4105,7 +4389,7 @@ pg_stat_get_wait_event_totals_info(PG_FUNCTION_ARGS) values[0] = CStringGetTextDatum(psprintf("%016" PRIx64, pwet_totals_header->incarnation)); - if (scan->overflow_sum_overflow) + if (unusable) nulls[1] = nulls[2] = nulls[3] = nulls[4] = true; else { @@ -4119,12 +4403,206 @@ pg_stat_get_wait_event_totals_info(PG_FUNCTION_ARGS) values[5] = Int64GetDatum(scan->invalid_ledgers); values[6] = Int32GetDatum(PWET_NUM_SLOTS); values[7] = Int32GetDatum(capturing); + values[8] = Int64GetDatum((int64) meta.generation); + if (meta.reset_scan_end == 0) + nulls[9] = nulls[10] = true; + else + { + values[9] = TimestampTzGetDatum(meta.reset_scan_end); + values[10] = TimestampTzGetDatum(meta.reset_scan_start); + } + if (unusable) + nulls[11] = nulls[12] = nulls[13] = true; + else + { + values[11] = Int64GetDatum((int64) scan->xact_commit); + values[12] = Int64GetDatum((int64) scan->xact_abort); + values[13] = Int64GetDatum((int64) scan->xact_prepare); + } tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls); pfree(scan); PG_RETURN_VOID(); } +/* + * SQL function: pg_stat_reset_wait_event_totals() + * + * Superuser only. Lifetime ledgers are never modified. A reset scans all + * ledgers without the control lock into scratch, then takes the lock + * exclusively, checks that no other reset published meanwhile (else scans + * again), publishes the scan as the new baseline together with its + * wall-clock times, and bumps the generation. It is therefore a scan-based + * cut, not an instantaneous global one: a completion that had not been + * flushed into its ledger when the scan read that ledger is counted after + * the reset. Refuses to run while any ledger is invalid. + */ +Datum +pg_stat_reset_wait_event_totals(PG_FUNCTION_ARGS) +{ + PwetTotalsScan *scan; + + if (!superuser()) + ereport(ERROR, + (errcode(ERRCODE_INSUFFICIENT_PRIVILEGE), + errmsg("permission denied to reset wait event totals"), + errdetail("Only roles with the %s attribute may reset wait event totals.", + "SUPERUSER"))); + + scan = palloc(sizeof(PwetTotalsScan)); + for (;;) + { + uint64 gen; + TimestampTz start; + TimestampTz end; + + LWLockAcquire(pwet_totals_lock, LW_SHARED); + gen = pwet_totals_header->reset_generation; + LWLockRelease(pwet_totals_lock); + + memset(scan, 0, sizeof(PwetTotalsScan)); + start = GetCurrentTimestamp(); + pwet_totals_scan(scan); + end = GetCurrentTimestamp(); + + /* Invalid or unrepresentable accounting cannot be a baseline. */ + pwet_totals_check(scan, false); + + LWLockAcquire(pwet_totals_lock, LW_EXCLUSIVE); + if (pwet_totals_header->reset_generation == gen) + { + memcpy(&pwet_totals_header->baseline, scan, sizeof(PwetTotalsScan)); + pwet_totals_header->reset_scan_start = start; + pwet_totals_header->reset_scan_end = end; + pwet_totals_header->reset_generation = gen + 1; + LWLockRelease(pwet_totals_lock); + break; + } + LWLockRelease(pwet_totals_lock); + CHECK_FOR_INTERRUPTS(); + } + + pfree(scan); + PG_RETURN_VOID(); +} + +/* ---- snapshot ---- */ + +static void +pwet_json_key(JsonbInState *state, const char *key) +{ + JsonbValue k; + + k.type = jbvString; + k.val.string.val = pstrdup(key); + k.val.string.len = strlen(key); + pushJsonbValue(state, WJB_KEY, &k); +} + +static void +pwet_json_int(JsonbInState *state, const char *key, int64 v) +{ + JsonbValue val; + + pwet_json_key(state, key); + val.type = jbvNumeric; + val.val.numeric = int64_to_numeric(v); + pushJsonbValue(state, WJB_VALUE, &val); +} + +static void +pwet_json_str(JsonbInState *state, const char *key, const char *v) +{ + JsonbValue val; + + pwet_json_key(state, key); + val.type = jbvString; + val.val.string.val = pstrdup(v); + val.val.string.len = strlen(v); + pushJsonbValue(state, WJB_VALUE, &val); +} + +static void +pwet_json_pair(JsonbInState *state, const char *key, const PwetTotal *t) +{ + pwet_json_key(state, key); + pushJsonbValue(state, WJB_BEGIN_OBJECT, NULL); + pwet_json_int(state, "calls", (int64) t->calls); + pwet_json_int(state, "total_ns", (int64) t->total_ns); + pushJsonbValue(state, WJB_END_OBJECT, NULL); +} + +typedef struct PwetSnapshotArg +{ + JsonbInState *state; + PwetNameContext names; +} PwetSnapshotArg; + +static void +pwet_snapshot_visitor(uint32 info, const PwetTotal *t, void *arg) +{ + PwetSnapshotArg *sa = (PwetSnapshotArg *) arg; + const char *type; + const char *name; + + pwet_event_names(info, &sa->names, &type, &name); + pushJsonbValue(sa->state, WJB_BEGIN_OBJECT, NULL); + pwet_json_int(sa->state, "event_key", (int64) info); + pwet_json_str(sa->state, "type", type); + pwet_json_str(sa->state, "name", name); + pwet_json_int(sa->state, "calls", (int64) t->calls); + pwet_json_int(sa->state, "total_ns", (int64) t->total_ns); + pushJsonbValue(sa->state, WJB_END_OBJECT, NULL); +} + +/* + * SQL function: pg_wait_event_snapshot() RETURNS jsonb + * + * The totals since the last reset as one document with exact integers: + * schema_version, incarnation, reset_generation, scan_start and scan_end + * (wall-clock microseconds since 2000-01-01, taken before and after the + * scan), the transaction counters, the two overflow pairs and the events + * [{event_key, type, name, calls, total_ns}]. Valid with zero events. + * Errors like the totals view. + */ +Datum +pg_wait_event_snapshot(PG_FUNCTION_ARGS) +{ + PwetTotalsScan *scan = palloc(sizeof(PwetTotalsScan)); + PwetReadMeta meta; + bool negative; + JsonbInState state; + PwetSnapshotArg sa; + + pwet_totals_read(scan, &meta, &negative); + pwet_totals_check(scan, negative); + + memset(&state, 0, sizeof(state)); + pushJsonbValue(&state, WJB_BEGIN_OBJECT, NULL); + pwet_json_int(&state, "schema_version", 1); + pwet_json_str(&state, "incarnation", + psprintf("%016" PRIx64, pwet_totals_header->incarnation)); + pwet_json_int(&state, "reset_generation", (int64) meta.generation); + pwet_json_int(&state, "scan_start", (int64) meta.scan_start); + pwet_json_int(&state, "scan_end", (int64) meta.scan_end); + pwet_json_int(&state, "xact_commit", (int64) scan->xact_commit); + pwet_json_int(&state, "xact_abort", (int64) scan->xact_abort); + pwet_json_int(&state, "xact_prepare", (int64) scan->xact_prepare); + pwet_json_pair(&state, "lwlock_overflow", &scan->lwlock_overflow); + pwet_json_pair(&state, "flat_overflow", &scan->flat_overflow); + + pwet_json_key(&state, "events"); + pushJsonbValue(&state, WJB_BEGIN_ARRAY, NULL); + sa.state = &state; + memset(&sa.names, 0, sizeof(sa.names)); + pwet_visit_events(scan, pwet_snapshot_visitor, &sa); + pushJsonbValue(&state, WJB_END_ARRAY, NULL); + + pushJsonbValue(&state, WJB_END_OBJECT, NULL); + pfree(scan); + PG_RETURN_POINTER(JsonbValueToJsonb(state.result)); +} + /* * Flushes the pending wait, if any, before zeroing: the wait already * happened and, per the decision document, its recorded values must not @@ -5144,11 +5622,91 @@ pwet_test_waits(PG_FUNCTION_ARGS) PG_FUNCTION_INFO_V1(pwet_test_ledger_dictionary); PG_FUNCTION_INFO_V1(pwet_test_slot_counted); +PG_FUNCTION_INFO_V1(pwet_test_read_barrier_arm); +PG_FUNCTION_INFO_V1(pwet_test_read_barrier_waiting); +PG_FUNCTION_INFO_V1(pwet_test_read_barrier_release); +PG_FUNCTION_INFO_V1(pwet_test_read_retries); +PG_FUNCTION_INFO_V1(pwet_test_totals_absolute); PG_FUNCTION_INFO_V1(pwet_test_ledger_set); PG_FUNCTION_INFO_V1(pwet_test_ledger_changecount); PG_FUNCTION_INFO_V1(pwet_test_ledger_torn_read); PG_FUNCTION_INFO_V1(pwet_test_ledger_odd_read); +/* Arm the reader barrier: the next totals reader suspends after its scan. */ +Datum +pwet_test_read_barrier_arm(PG_FUNCTION_ARGS) +{ + pg_atomic_write_u32(&pwet_totals_header->test_release, 0); + pg_atomic_write_u32(&pwet_totals_header->test_waiting, 0); + pg_atomic_write_u32(&pwet_totals_header->test_arm, 1); + PG_RETURN_VOID(); +} + +Datum +pwet_test_read_barrier_waiting(PG_FUNCTION_ARGS) +{ + PG_RETURN_BOOL(pg_atomic_read_u32(&pwet_totals_header->test_waiting) != 0); +} + +Datum +pwet_test_read_barrier_release(PG_FUNCTION_ARGS) +{ + pg_atomic_write_u32(&pwet_totals_header->test_release, 1); + PG_RETURN_VOID(); +} + +/* How many times a reader found the generation moved and started over. */ +Datum +pwet_test_read_retries(PG_FUNCTION_ARGS) +{ + PG_RETURN_INT64((int64) pg_atomic_read_u32(&pwet_totals_header->test_retries)); +} + +/* + * pwet_test_totals_absolute(event_key bigint, OUT absolute bigint, OUT baseline bigint) + * + * The sum of all ledgers for an event (no baseline subtracted) and the + * baseline of the last reset, so a test can check conservation: absolute + * equals everything emitted, and the totals view shows absolute - baseline. + */ +Datum +pwet_test_totals_absolute(PG_FUNCTION_ARGS) +{ + uint32 key = (uint32) PG_GETARG_INT64(0); + TupleDesc tupdesc; + Datum values[2]; + bool nulls[2] = {0}; + PwetTotalsScan *scan = palloc0(sizeof(PwetTotalsScan)); + int idx = pwet_timing_index(key); + const PwetTotal *base; + const PwetTotal *cur; + int64 basecalls; + + if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE) + elog(ERROR, "return type must be a row type"); + pwet_totals_scan(scan); + PWET_TEST_CHECK(!scan->sum_overflow); + + LWLockAcquire(pwet_totals_lock, LW_SHARED); + if (idx == PWET_IDX_LWLOCK) + { + cur = &scan->tranche[key & PWET_WAIT_EVENT_ID_MASK]; + base = &pwet_totals_header->baseline.tranche[key & PWET_WAIT_EVENT_ID_MASK]; + } + else + { + PWET_TEST_CHECK(idx >= 0); + cur = &scan->flat[idx]; + base = &pwet_totals_header->baseline.flat[idx]; + } + basecalls = (int64) base->calls; + LWLockRelease(pwet_totals_lock); + + values[0] = Int64GetDatum((int64) cur->calls); + values[1] = Int64GetDatum(basecalls); + PG_RETURN_DATUM(HeapTupleGetDatum(heap_form_tuple(tupdesc, values, nulls))); +} + /* pwet_test_slot_counted(slot int) returns bool: would capturing_backends count it? */ Datum pwet_test_slot_counted(PG_FUNCTION_ARGS) diff --git a/contrib/pg_wait_event_tracing/pg_wait_event_tracing.control b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.control index 30b900785fc..114fe23863b 100644 --- a/contrib/pg_wait_event_tracing/pg_wait_event_tracing.control +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.control @@ -2,4 +2,4 @@ comment = 'statistics and trace collection for explicitly instrumented wait events' default_version = '1.1' module_pathname = '$libdir/pg_wait_event_tracing' -relocatable = true +relocatable = false diff --git a/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_totals.sql b/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_totals.sql index 89e306abed3..b203f552680 100644 --- a/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_totals.sql +++ b/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_totals.sql @@ -9,6 +9,10 @@ -- other tests did to this server are asserted. -- +-- CI configurations may force debug_parallel_query = regress; keep this +-- session's statements in this session. +SET debug_parallel_query = off; + -- Version handling: 1.0 has no totals objects, the update adds them, and a -- fresh install of the default version has the same objects. DROP EXTENSION IF EXISTS pg_wait_event_tracing; @@ -100,5 +104,128 @@ SELECT count(*) > 0 AS totals_visible FROM pg_stat_wait_event_totals; SELECT count(*) AS info_visible FROM pg_stat_wait_event_totals_info; RESET ROLE; +-- Phase 2 functions: PUBLIC denied, pg_read_all_stats may read, only a +-- superuser may reset. +SELECT p.proname, + has_function_privilege('regress_pwet_plain', p.oid, 'EXECUTE') AS plain, + has_function_privilege('regress_pwet_stats', p.oid, 'EXECUTE') AS stats +FROM pg_proc p +WHERE p.proname IN ('pg_wait_event_snapshot', 'pg_wait_event_diff', + 'pg_wait_event_diff_check', 'pg_wait_event_report', + 'pg_stat_reset_wait_event_totals') +ORDER BY p.proname; + +SET ROLE regress_pwet_plain; +SELECT pg_wait_event_snapshot(); +SELECT pg_stat_reset_wait_event_totals(); +RESET ROLE; +SET ROLE regress_pwet_stats; +SELECT jsonb_typeof(pg_wait_event_snapshot()) AS snapshot_type; +SELECT pg_stat_reset_wait_event_totals(); +RESET ROLE; + DROP ROLE regress_pwet_plain; DROP ROLE regress_pwet_stats; + +-- +-- Snapshot, diff and report (phase 2). +-- +SELECT array_agg(k ORDER BY k) AS snapshot_keys +FROM jsonb_object_keys(pg_wait_event_snapshot()) k; +SELECT pg_wait_event_snapshot()->'schema_version' AS schema_version, + jsonb_typeof(pg_wait_event_snapshot()->'events') AS events_type, + (pg_wait_event_snapshot()->>'incarnation') = (SELECT incarnation FROM pg_stat_wait_event_totals_info) AS same_incarnation; + +-- Reset: the generation advances by one and the scan times appear. +SELECT reset_generation AS gen_before FROM pg_stat_wait_event_totals_info \gset +SELECT pg_stat_reset_wait_event_totals(); +SELECT reset_generation = :gen_before + 1 AS generation_advanced, + stats_reset IS NOT NULL AS has_stats_reset, + reset_scan_start <= stats_reset AS scan_times_ordered, + xact_commit >= 0 AND xact_abort >= 0 AND xact_prepare >= 0 AS xact_columns +FROM pg_stat_wait_event_totals_info; + +-- Crafted snapshots. a: 10 commits, 2 aborts; b: 15 and 3, i.e. 6 transactions. +SELECT '{"schema_version":1,"incarnation":"00000000000000aa","reset_generation":0, + "scan_start":100,"scan_end":200,"xact_commit":10,"xact_abort":2,"xact_prepare":1, + "lwlock_overflow":{"calls":0,"total_ns":0},"flat_overflow":{"calls":0,"total_ns":0}, + "events":[{"event_key":117440513,"type":"Extension","name":"X","calls":4,"total_ns":4000000}, + {"event_key":83886080,"type":"Activity","name":"A","calls":5,"total_ns":1000000}, + {"event_key":100663296,"type":"Client","name":"ClientRead","calls":1,"total_ns":1000000}, + {"event_key":50331648,"type":"Lock","name":"relation","calls":7,"total_ns":7000000}]}'::jsonb AS a \gset +SELECT jsonb_set(jsonb_set(jsonb_set(jsonb_set(jsonb_set(jsonb_set(:'a'::jsonb, + '{scan_start}', '300'), '{scan_end}', '400'), + '{xact_commit}', '15'), '{xact_abort}', '3'), + '{lwlock_overflow}', '{"calls":3,"total_ns":3000000}'), + '{events}', '[{"event_key":117440513,"type":"Extension","name":"X","calls":10,"total_ns":10000000}, + {"event_key":117440514,"type":"Extension","name":"Y","calls":3,"total_ns":3000000}, + {"event_key":83886080,"type":"Activity","name":"A","calls":9,"total_ns":2000000}, + {"event_key":100663296,"type":"Client","name":"ClientRead","calls":4,"total_ns":4000000}, + {"event_key":50331648,"type":"Lock","name":"relation","calls":7,"total_ns":7000000}]') AS b \gset + +-- waits_per_xact = waits / xacts, ms_per_xact = wait_time_ms / xacts, with +-- xacts = commit delta + abort delta = 6; interval_s from the scan midpoints. +SELECT * FROM pg_wait_event_diff(:'a', :'b'); +SELECT * FROM pg_wait_event_diff(:'a', :'b', true); +-- A NULL include_idle is not true: idle rows are left out, like false. +SELECT event_key FROM pg_wait_event_diff(:'a', :'b', NULL); + +-- Zero transactions: ratios per transaction are NULL. +SELECT event_key, ms_per_wait, waits_per_xact, ms_per_xact, xacts +FROM pg_wait_event_diff(:'a', jsonb_set(jsonb_set(:'b'::jsonb, '{xact_commit}', '10'), '{xact_abort}', '2')); + +-- Zero events and no change: no rows. +SELECT count(*) AS no_rows FROM pg_wait_event_diff( + jsonb_set(:'a'::jsonb, '{events}', '[]'), + jsonb_set(jsonb_set(:'b'::jsonb, '{events}', '[]'), '{lwlock_overflow}', '{"calls":0,"total_ns":0}')); + +-- Errors. +\set VERBOSITY terse +SELECT * FROM pg_wait_event_diff(:'b', :'a'); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{scan_start}', '150')); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{incarnation}', '"00000000000000bb"')); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{reset_generation}', '1')); +SELECT * FROM pg_wait_event_diff(jsonb_set(:'a'::jsonb, '{schema_version}', '2'), :'b'); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,calls}', '1.5')); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,calls}', '-1')); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,calls}', '9223372036854775808')); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,calls}', '"7"')); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,event_key}', '4294967296')); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,0,event_key}', '-1')); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events}', + (:'b'::jsonb->'events') || (:'b'::jsonb->'events'->0))); +SELECT * FROM pg_wait_event_diff(:'a', :'b'::jsonb #- '{events,0,name}'); +SELECT * FROM pg_wait_event_diff(:'a', :'b'::jsonb - 'xact_abort'); +SELECT * FROM pg_wait_event_diff('[]', :'b'); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events}', '[]')); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{events,4,calls}', '6')); +SELECT * FROM pg_wait_event_diff(:'a', jsonb_set(:'b'::jsonb, '{xact_commit}', '9')); + +-- Report: argument validation (the sleep itself is exercised by the TAP tests). +SELECT * FROM pg_wait_event_report(0); +SELECT * FROM pg_wait_event_report(-5, true); +SELECT count(*) AS null_arg_rows FROM pg_wait_event_report(NULL); +SELECT count(*) AS null_idle_rows FROM pg_wait_event_report(1, NULL); +\set VERBOSITY default + +-- The extension is not relocatable: its report functions call each other by +-- the extension schema, so they work from a schema that is not in the +-- search_path. +RESET ALL; +DROP EXTENSION pg_wait_event_tracing; +CREATE SCHEMA pwet_s; +CREATE EXTENSION pg_wait_event_tracing SCHEMA pwet_s; +SELECT extrelocatable FROM pg_extension WHERE extname = 'pg_wait_event_tracing'; +SET search_path = pg_catalog; +-- the report's NOTICE carries the measured interval, which is never stable; +-- what a report returns is checked by the TAP tests +SET client_min_messages = warning; +SELECT count(*) IS NOT NULL AS report_runs_from_other_schema FROM pwet_s.pg_wait_event_report(1); +-- the rows of the crafted snapshots from above, through the other schema +SELECT event_key, waits, xacts FROM pwet_s.pg_wait_event_diff(:'a', :'b') ORDER BY event_key; +RESET client_min_messages; +RESET search_path; +ALTER EXTENSION pg_wait_event_tracing SET SCHEMA public; +DROP EXTENSION pg_wait_event_tracing; +DROP SCHEMA pwet_s; +CREATE EXTENSION pg_wait_event_tracing; diff --git a/contrib/pg_wait_event_tracing/t/017_totals_ledger.pl b/contrib/pg_wait_event_tracing/t/017_totals_ledger.pl index f4cdf2871d4..74075e4f192 100644 --- a/contrib/pg_wait_event_tracing/t/017_totals_ledger.pl +++ b/contrib/pg_wait_event_tracing/t/017_totals_ledger.pl @@ -14,7 +14,7 @@ # - counters crossing 2^32, changecount rollover; # - a counter that would exceed bigint makes the ledger invalid: totals # ERROR, the info view still shows it, a per-backend reset-all does not -# repair it; +# repair it, and snapshot and reset ERROR too; # - sums over ledgers that exceed bigint ERROR the totals. use strict; @@ -125,6 +125,12 @@ $s->query_safe('SELECT test_wait_totals_emit(1)'); ($ret, $out, $err) = $node->psql('postgres', 'SELECT * FROM pg_stat_wait_event_totals'); isnt($ret, 0, 'totals ERROR with an invalid ledger'); like($err, qr/lifetime ledger.*exceeded the bigint range/, 'clear message'); +foreach my $fn ('pg_wait_event_snapshot()', 'pg_stat_reset_wait_event_totals()') +{ + ($ret, $out, $err) = $node->psql('postgres', "SELECT $fn"); + isnt($ret, 0, "$fn ERRORs with an invalid ledger"); + like($err, qr/exceeded the bigint range/, "$fn: clear message"); +} is($node->safe_psql('postgres', 'SELECT invalid_ledgers FROM pg_stat_wait_event_totals_info'), '1', 'the info view still shows the invalid ledger'); $node->safe_psql('postgres', 'SELECT pg_stat_reset_wait_event_timing_all()'); diff --git a/doc/src/sgml/pgwaiteventtracing.sgml b/doc/src/sgml/pgwaiteventtracing.sgml index a2d0000c406..71675963c55 100644 --- a/doc/src/sgml/pgwaiteventtracing.sgml +++ b/doc/src/sgml/pgwaiteventtracing.sgml @@ -1718,10 +1718,9 @@ AFTER_STATEMENT --(QueryStart | UtilityStart)--> OPEN (no Idle emitted) live collecting backends and vanish when a backend exits, resets or stops collecting, the totals sum a lifetime ledger kept per process slot, so they include processes that have already exited. - Version 1.1 is not final: the transaction counters, reset, snapshot, diff - and report functions described in the second half of this section are - added to the same 1.0--1.1 update script before the - version is released. + The second half of this section describes transaction counters, reset, + and snapshot, diff and report functions, all part of the same + 1.0--1.1 update script. @@ -1753,13 +1752,21 @@ AFTER_STATEMENT --(QueryStart | UtilityStart)--> OPEN (no Idle emitted) flat_overflow_calls, flat_overflow_time_ms), invalid_ledgers, - ledger_slots and + ledger_slots, capturing_backends (advisory, read without a lock; exited processes are not counted: a server-side process that exits normally withdraws its claim on its slot. In the rare case that such a process fails during start-up before it has registered its exit cleanup and a later process reuses the same process id in the same slot, - that slot can still be counted). A counter that would exceed the bigint range marks + that slot can still be counted), + reset_generation, + stats_reset and + reset_scan_start (the wall-clock times + around the scan of the last reset; null before the first one) and the + captured transaction completions + xact_commit, + xact_abort and + xact_prepare. A counter that would exceed the bigint range marks its ledger invalid instead of wrapping; a reset cannot repair that, and the totals view raises an error while any ledger is invalid or a sum exceeds the range. The information view still shows the diagnostics @@ -1816,7 +1823,114 @@ AFTER_STATEMENT --(QueryStart | UtilityStart)--> OPEN (no Idle emitted) with max_connections of 1000. Reading the totals allocates about 1 MiB of scratch (a counter pair for each of the 65536 possible tranche ids) plus one ledger copy, and copies every slot's - ledger once; it holds no lock while doing so. + ledger once; it holds no lock while doing so. The reset baseline is one + more such 1 MiB structure, allocated once in shared memory together with + the reset control lock. + + + + + Transaction Counters + + xact_commit, + xact_abort and + xact_prepare count + captured transaction completions: the + transaction commit, abort and prepare events of top-level transactions + that completed while pg_wait_event_tracing.capture + was stats or trace in the + process. The setting is the one in effect when the transaction ends, so + a SET LOCAL value counts, for commit and abort alike, + and a transaction in which capture was switched on or off counts + according to the final setting. Subtransactions (savepoints) are not + counted. The transactions that initialize a connection are counted + when capture is enabled for it from the start. Parallel workers are + never counted (they also run ordinary transactions of their own); the + leader counts the query's transaction. + COMMIT PREPARED and ROLLBACK + PREPARED are the resolving session's own transaction, which + commits, and count as a commit there, not as the original prepared + transaction. Counting only updates counters; it does not publish a + pending wait. + + + + + Reset + + pg_stat_reset_wait_event_totals() (superuser only) + makes the views start from zero again. It does not modify any ledger: + it scans all of them without holding a lock, then publishes the scan as + a baseline under a dedicated lightweight lock, together with the + wall-clock times of the scan, and increments + reset_generation. The views subtract the + baseline. This is a scan-based cut, not an instantaneous global one: a + wait that completed before the reset but had not yet been published + into its ledger when the scan read that ledger (see above) is counted + after the reset. Resetting is refused while any ledger is invalid. + The per-backend reset functions never change the totals, and this reset + never touches the per-backend views. + + + + + Snapshots, Diffs and Reports + + pg_wait_event_snapshot() returns the totals as one + jsonb document with exact integers: + schema_version (1), incarnation, + reset_generation, scan_start and + scan_end (wall-clock microseconds since 2000-01-01 + UTC, read before and after the scan), the transaction counters, the two + overflow pairs and events, an array of + {event_key, type, name, calls, total_ns}. It is + valid with no events. + + + pg_wait_event_diff(a, b, include_idle) compares two + snapshots and returns, for each event that changed (the two overflow + rows included): event_key, + wait_event_type, + wait_event, waits, + wait_time_ms, + ms_per_wait (wait_time_ms / waits), + waits_per_xact (waits / xacts), + ms_per_xact (wait_time_ms / xacts), + interval_s and + xacts. xacts is + the increase of xact_commit plus + xact_abort between the snapshots, over all + processes (prepare is not counted); the ratios are null when their + denominator is zero. Because the denominator is captured commits plus + aborts, waits_per_xact and + ms_per_xact are not numerically comparable to + per-transaction figures that count committed transactions only. For example, 10 waits taking 5 ms in total during + 2 transactions give waits_per_xact 5, + ms_per_xact 2.5 and ms_per_wait + 0.5. interval_s is the wall-clock distance + of the scan midpoints. Rows with no change are omitted. Unless + include_idle is true, events of the wait event + type Activity and the Client event + ClientRead are left out; the transaction denominator + is never filtered. The function checks the schema version, that every + count is an integer in the bigint range, that event keys are + unique and within the unsigned 32-bit range, that both snapshots have the same incarnation and reset + generation, and that the second scan began after the first ended; an + event missing from the first snapshot counts from zero, one missing from + the second, or any decreasing counter, is an error. + + + pg_wait_event_report(seconds, include_idle) takes a + snapshot, sleeps, takes another and returns the diff, after a + NOTICE with the interval, the transactions and the + transactions per second (the only place a result without rows shows + them). seconds must be at least 1. Run it from a + session with capture off, otherwise the report's own sleep is counted. + pg_wait_event_diff_check(a, b) is the validation + step they share. The extension is not relocatable, because these + functions call each other by the extension's schema name. Updating an installed version 1.0 to 1.1 makes the + extension non-relocatable, so it stays in the schema it is installed in. All of these are readable by + pg_read_all_stats only. diff --git a/src/test/modules/test_wait_totals/TwtUtil.pm b/src/test/modules/test_wait_totals/TwtUtil.pm new file mode 100644 index 00000000000..4ead84db0ea --- /dev/null +++ b/src/test/modules/test_wait_totals/TwtUtil.pm @@ -0,0 +1,76 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Helpers shared by the test_wait_totals TAP tests. +# +# harden($node) re-blesses a PostgreSQL::Test::Cluster so that every +# synchronous psql call has an external timeout (a stuck reader or a lock +# deadlock then fails the test instead of hanging it), and so that +# poll_query_until() bounds each individual attempt, not only the number of +# attempts. BackgroundPsql sessions have their own timer. + +package TwtUtil; + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Utils (); +use Time::HiRes qw(usleep time); + +sub harden +{ + my ($node) = @_; + + bless $node, 'TwtUtil::Node'; + return $node; +} + +package TwtUtil::Node; + +use strict; +use warnings FATAL => 'all'; + +use parent -norequire, 'PostgreSQL::Test::Cluster'; +use Time::HiRes qw(usleep time); + +sub psql +{ + my ($self, $dbname, $sql, %params) = @_; + + $params{timeout} = $PostgreSQL::Test::Utils::timeout_default + unless defined $params{timeout}; + return $self->SUPER::psql($dbname, $sql, %params); +} + +sub poll_query_until +{ + my ($self, $dbname, $query, $expected) = @_; + + $expected = 't' unless defined $expected; + my $deadline = time() + $PostgreSQL::Test::Utils::timeout_default; + my $last = ''; + + while (time() < $deadline) + { + my ($stdout, $stderr, $timed_out) = ('', '', 0); + + # One attempt, itself bounded. + $self->SUPER::psql($dbname, $query, + stdout => \$stdout, stderr => \$stderr, + timeout => 10, timed_out => \$timed_out, + on_error_stop => 0); + chomp($stdout); + chomp($stderr); + $last = "stdout=$stdout stderr=$stderr timed_out=$timed_out"; + # A timed-out attempt is fatal: killing psql does not cancel its + # backend, which may be stuck, so retrying would only pile up + # sessions behind it. Dying tears the test (and the node) down now. + die "poll_query_until: an attempt timed out on: $query" if $timed_out; + return 1 if $stdout eq $expected && $stderr eq ''; + usleep(100_000); + } + + Test::More::diag("poll_query_until timed out: $query\nexpected: $expected\nlast: $last"); + return 0; +} + +1; diff --git a/src/test/modules/test_wait_totals/meson.build b/src/test/modules/test_wait_totals/meson.build index 04fc804d324..d1aa3e75e72 100644 --- a/src/test/modules/test_wait_totals/meson.build +++ b/src/test/modules/test_wait_totals/meson.build @@ -39,6 +39,9 @@ tests += { 't/005_dictionary.pl', 't/006_coherence.pl', 't/007_restart.pl', + 't/008_transactions.pl', + 't/009_reset.pl', + 't/010_report.pl', ], }, } diff --git a/src/test/modules/test_wait_totals/t/001_publication.pl b/src/test/modules/test_wait_totals/t/001_publication.pl index 987ffc7571c..63c1df4a3ea 100644 --- a/src/test/modules/test_wait_totals/t/001_publication.pl +++ b/src/test/modules/test_wait_totals/t/001_publication.pl @@ -17,12 +17,17 @@ use strict; use warnings FATAL => 'all'; +use FindBin; +use lib "$FindBin::RealBin/.."; + use PostgreSQL::Test::Cluster; +use TwtUtil; use PostgreSQL::Test::Utils; use Test::More; use Time::HiRes qw(usleep); my $node = PostgreSQL::Test::Cluster->new('main'); +TwtUtil::harden($node); $node->init; $node->append_conf( 'postgresql.conf', q( diff --git a/src/test/modules/test_wait_totals/t/002_exit.pl b/src/test/modules/test_wait_totals/t/002_exit.pl index 63ce2e12bac..29bb4134ffd 100644 --- a/src/test/modules/test_wait_totals/t/002_exit.pl +++ b/src/test/modules/test_wait_totals/t/002_exit.pl @@ -15,12 +15,17 @@ use strict; use warnings FATAL => 'all'; +use FindBin; +use lib "$FindBin::RealBin/.."; + use PostgreSQL::Test::Cluster; +use TwtUtil; use PostgreSQL::Test::Utils; use Test::More; use Time::HiRes qw(usleep); my $node = PostgreSQL::Test::Cluster->new('main'); +TwtUtil::harden($node); $node->init; $node->append_conf( 'postgresql.conf', q( diff --git a/src/test/modules/test_wait_totals/t/003_capture_reset.pl b/src/test/modules/test_wait_totals/t/003_capture_reset.pl index 25de1e740a2..786d268aa49 100644 --- a/src/test/modules/test_wait_totals/t/003_capture_reset.pl +++ b/src/test/modules/test_wait_totals/t/003_capture_reset.pl @@ -17,12 +17,17 @@ use strict; use warnings FATAL => 'all'; +use FindBin; +use lib "$FindBin::RealBin/.."; + use PostgreSQL::Test::Cluster; +use TwtUtil; use PostgreSQL::Test::Utils; use Test::More; use Time::HiRes qw(usleep); my $node = PostgreSQL::Test::Cluster->new('main'); +TwtUtil::harden($node); $node->init; $node->append_conf( 'postgresql.conf', q( diff --git a/src/test/modules/test_wait_totals/t/004_slots_servers.pl b/src/test/modules/test_wait_totals/t/004_slots_servers.pl index 235e77cc23f..46abc8402c4 100644 --- a/src/test/modules/test_wait_totals/t/004_slots_servers.pl +++ b/src/test/modules/test_wait_totals/t/004_slots_servers.pl @@ -17,12 +17,17 @@ use strict; use warnings FATAL => 'all'; +use FindBin; +use lib "$FindBin::RealBin/.."; + use PostgreSQL::Test::Cluster; +use TwtUtil; use PostgreSQL::Test::Utils; use Test::More; use Time::HiRes qw(usleep); my $node = PostgreSQL::Test::Cluster->new('main'); +TwtUtil::harden($node); $node->init; $node->append_conf( 'postgresql.conf', q( diff --git a/src/test/modules/test_wait_totals/t/005_dictionary.pl b/src/test/modules/test_wait_totals/t/005_dictionary.pl index 1583f3675dd..69693156c27 100644 --- a/src/test/modules/test_wait_totals/t/005_dictionary.pl +++ b/src/test/modules/test_wait_totals/t/005_dictionary.pl @@ -15,12 +15,17 @@ use strict; use warnings FATAL => 'all'; +use FindBin; +use lib "$FindBin::RealBin/.."; + use PostgreSQL::Test::Cluster; +use TwtUtil; use PostgreSQL::Test::Utils; use Test::More; use Time::HiRes qw(usleep); my $node = PostgreSQL::Test::Cluster->new('main'); +TwtUtil::harden($node); $node->init; $node->append_conf( 'postgresql.conf', q( @@ -97,6 +102,7 @@ pass('a contended wait on a named test tranche is found and counted'); # --------------------------------------------------------------------- $node->stop; $node = PostgreSQL::Test::Cluster->new('fill'); +TwtUtil::harden($node); $node->init; $node->append_conf( 'postgresql.conf', q( diff --git a/src/test/modules/test_wait_totals/t/006_coherence.pl b/src/test/modules/test_wait_totals/t/006_coherence.pl index ad391fd9b03..b98acbdddad 100644 --- a/src/test/modules/test_wait_totals/t/006_coherence.pl +++ b/src/test/modules/test_wait_totals/t/006_coherence.pl @@ -18,11 +18,16 @@ use strict; use warnings FATAL => 'all'; +use FindBin; +use lib "$FindBin::RealBin/.."; + use PostgreSQL::Test::Cluster; +use TwtUtil; use PostgreSQL::Test::Utils; use Test::More; my $node = PostgreSQL::Test::Cluster->new('main'); +TwtUtil::harden($node); $node->init; $node->append_conf( 'postgresql.conf', q( diff --git a/src/test/modules/test_wait_totals/t/007_restart.pl b/src/test/modules/test_wait_totals/t/007_restart.pl index 09e023debbe..442fc64eda4 100644 --- a/src/test/modules/test_wait_totals/t/007_restart.pl +++ b/src/test/modules/test_wait_totals/t/007_restart.pl @@ -11,11 +11,16 @@ use strict; use warnings FATAL => 'all'; +use FindBin; +use lib "$FindBin::RealBin/.."; + use PostgreSQL::Test::Cluster; +use TwtUtil; use PostgreSQL::Test::Utils; use Test::More; my $node = PostgreSQL::Test::Cluster->new('main'); +TwtUtil::harden($node); $node->init; $node->append_conf( 'postgresql.conf', q( diff --git a/src/test/modules/test_wait_totals/t/008_transactions.pl b/src/test/modules/test_wait_totals/t/008_transactions.pl new file mode 100644 index 00000000000..4f55af6f244 --- /dev/null +++ b/src/test/modules/test_wait_totals/t/008_transactions.pl @@ -0,0 +1,162 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Instance totals of pg_wait_event_tracing: captured transaction completions +# (xact_commit, xact_abort, xact_prepare). Capture is off cluster-wide, so +# the only transactions counted are those of the one session each case runs +# (it turns capture on itself), and every delta is exact. A case is one +# fresh connection running one script; the counters are read by this +# observer, whose capture is off, before and after. +# +# Counting follows the callback: COMMIT, ABORT and PREPARE events of the +# top-level transaction, when capture is on at that moment (a SET LOCAL +# value is still in effect then); subtransactions are not counted; COMMIT +# PREPARED and ROLLBACK PREPARED run their own transaction in the resolving +# session, which commits; parallel workers are never counted. + +use strict; +use warnings FATAL => 'all'; + +use FindBin; +use lib "$FindBin::RealBin/.."; + +use PostgreSQL::Test::Cluster; +use TwtUtil; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('main'); +TwtUtil::harden($node); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +autovacuum = off +max_prepared_transactions = 5 +max_worker_processes = 16 +max_parallel_workers = 8 +)); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing'); +$node->safe_psql('postgres', 'CREATE EXTENSION test_wait_totals'); + +sub counters +{ + return $node->safe_psql('postgres', + 'SELECT xact_commit || \',\' || xact_abort || \',\' || xact_prepare + FROM pg_stat_wait_event_totals_info'); +} + +my $ON = 'SET pg_wait_event_tracing.capture = stats;'; + +# [label, script, expected "commit,abort,prepare" delta] +my @cases = ( + [ 'autocommit statement', "$ON SELECT 1;", '2,0,0' ], + [ 'explicit commit', "$ON BEGIN; SELECT 1; COMMIT;", '2,0,0' ], + [ 'read-only transaction', "$ON BEGIN READ ONLY; SELECT 1; COMMIT;", '2,0,0' ], + [ 'explicit rollback', "$ON BEGIN; SELECT 1; ROLLBACK;", '1,1,0' ], + [ 'error in autocommit statement', "$ON SELECT 1/0;", '1,1,0' ], + [ 'error in a transaction block, then ROLLBACK', + "$ON BEGIN; SELECT 1/0; ROLLBACK;", '1,1,0' ], + [ 'savepoint rollback is not counted, the commit is', + "$ON BEGIN; SAVEPOINT s; SELECT 1/0; ROLLBACK TO s; COMMIT;", '2,0,0' ], + [ 'PREPARE counts as a prepare; COMMIT PREPARED as the resolving commit', + "$ON BEGIN; SELECT 1; PREPARE TRANSACTION 'pwet_t1'; COMMIT PREPARED 'pwet_t1';", + '2,0,1' ], + [ 'ROLLBACK PREPARED is the resolving session\'s own committed transaction', + "$ON BEGIN; PREPARE TRANSACTION 'pwet_t2'; ROLLBACK PREPARED 'pwet_t2';", + '2,0,1' ], + [ 'SET LOCAL capture on: commit counted', + 'BEGIN; SET LOCAL pg_wait_event_tracing.capture = stats; SELECT 1; COMMIT;', + '1,0,0' ], + [ 'SET LOCAL capture on: abort counted', + 'BEGIN; SET LOCAL pg_wait_event_tracing.capture = stats; SELECT 1/0; ROLLBACK;', + '0,1,0' ], + [ 'SET LOCAL capture off: commit not counted', + "$ON BEGIN; SET LOCAL pg_wait_event_tracing.capture = off; SELECT 1; COMMIT;", + '1,0,0' ], + [ 'SET LOCAL capture off: abort not counted', + "$ON BEGIN; SET LOCAL pg_wait_event_tracing.capture = off; SELECT 1/0; ROLLBACK;", + '1,0,0' ], + [ 'capture turned on inside the transaction: its commit counts', + 'BEGIN; SET pg_wait_event_tracing.capture = stats; SELECT 1; COMMIT;', + '1,0,0' ], + [ 'capture turned off inside the transaction: its commit does not count', + "$ON BEGIN; SET pg_wait_event_tracing.capture = off; COMMIT;", + '1,0,0' ], + [ 'trace level counts as well', + 'SET pg_wait_event_tracing.capture = trace; SELECT 1;', + '2,0,0' ], + [ 'capture off counts nothing', 'SELECT 1; BEGIN; SELECT 1; ROLLBACK;', '0,0,0' ], +); + +foreach my $c (@cases) +{ + my ($label, $script, $want) = @$c; + my $before = counters(); + $node->psql('postgres', $script, on_error_stop => 0); + my @b = split /,/, $before; + my @a = split /,/, counters(); + my $got = join(',', map { $a[$_] - $b[$_] } 0 .. 2); + is($got, $want, $label); +} + +# Parallel query. A role setting turns capture on for the connection from +# its very start, and parallel workers connect as the same role, so their +# own initialization transactions would be counted too if they were not +# skipped. The same script runs once with parallel workers and once without +# (max_parallel_workers_per_gather = 0): the deltas must be equal, i.e. +# workers add nothing, and the test shows that the workers really ran the +# emitter (the leader does not participate, so every row ran in a worker). +$node->safe_psql('postgres', 'CREATE TABLE ptab AS SELECT g FROM generate_series(1, 4000) g'); +$node->safe_psql('postgres', + q(CREATE ROLE pwet_cap SUPERUSER LOGIN; + ALTER ROLE pwet_cap SET pg_wait_event_tracing.capture = stats;)); +sub parallel_run +{ + my ($workers) = @_; + my $before = counters(); + my $out; + $node->psql( + 'postgres', qq( +SET debug_parallel_query = off; +SET parallel_setup_cost = 0; +SET parallel_tuple_cost = 0; +SET min_parallel_table_scan_size = 0; +SET max_parallel_workers_per_gather = $workers; +SET parallel_leader_participation = off; +SELECT sum(test_wait_totals_emit_row(1)) FROM ptab; +), stdout => \$out, extra_params => [ '-U', 'pwet_cap' ]); + my @b = split /,/, $before; + my @a = split /,/, counters(); + return ($out, join(',', map { $a[$_] - $b[$_] } 0 .. 2)); +} +my ($out_par, $delta_par) = parallel_run(2); +my ($out_seq, $delta_seq) = parallel_run(0); +like($out_par, qr/\b4000\b/, 'parallel query: every row ran in a worker'); +unlike($out_seq, qr/\b4000\b/, 'control without workers: none did'); +is($delta_par, $delta_seq, + 'parallel workers add nothing to the counters (delta equals the no-worker run)'); +cmp_ok((split /,/, $delta_par)[0], '>=', 7, + 'and the leader\'s init, SET and query transactions were counted'); + +# Connection-initialization transactions count when capture is enabled for +# the connection from the start, and not otherwise. +{ + my $before = counters(); + $node->psql('postgres', 'SELECT 1'); + is(counters(), $before, 'init transactions of a capture-off connection: none'); + + my @b = split /,/, counters(); + { + local $ENV{PGOPTIONS} = '-c pg_wait_event_tracing.capture=stats'; + $node->psql('postgres', 'SELECT 1'); + } + my @a = split /,/, counters(); + cmp_ok($a[0] - $b[0], '>=', 2, + 'connection with capture on from the start: init commit(s) plus the statement'); + is($a[1] - $b[1], 0, 'no aborts'); +} + +$node->stop; +done_testing(); diff --git a/src/test/modules/test_wait_totals/t/009_reset.pl b/src/test/modules/test_wait_totals/t/009_reset.pl new file mode 100644 index 00000000000..68842dd0eb1 --- /dev/null +++ b/src/test/modules/test_wait_totals/t/009_reset.pl @@ -0,0 +1,313 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Instance totals of pg_wait_event_tracing: pg_stat_reset_wait_event_totals(). +# A reset never modifies a ledger; it scans all of them and publishes the sum +# as a baseline that readers subtract, so it is a scan-based cut, not an +# instantaneous global one. Capture is off cluster-wide and sessions turn it +# on themselves, so assertions are on the dedicated event only. +# +# - totals of the dedicated event restart from zero, the generation +# advances, the reset scan times appear; +# - a completion that was made before the reset but not yet published when +# the scan read its ledger is counted after the reset (exact, with the +# emitter held in its CPU stretch); +# - per-backend resets do not touch the totals, and the totals' reset does +# not touch the per-backend view; +# - resets concurrent with emitters and snapshot readers: no error, and +# within one generation the counts never decrease; +# - a diff across a reset is an error. + +use strict; +use warnings FATAL => 'all'; + +use FindBin; +use lib "$FindBin::RealBin/.."; + +use PostgreSQL::Test::Cluster; +use TwtUtil; +use PostgreSQL::Test::Utils; +use Test::More; +use Time::HiRes qw(usleep); + +my $node = PostgreSQL::Test::Cluster->new('main'); +TwtUtil::harden($node); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +autovacuum = off +)); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing'); +$node->safe_psql('postgres', 'CREATE EXTENSION test_wait_totals'); + +sub calls +{ + return $node->safe_psql('postgres', + "SELECT coalesce(sum(calls), 0) FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'"); +} + +sub wait_calls +{ + my ($want, $what) = @_; + $node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = $want FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die "$what: calls never reached $want (now " . calls() . ')'; +} + +sub generation +{ + return $node->safe_psql('postgres', + 'SELECT reset_generation FROM pg_stat_wait_event_totals_info'); +} + +# --------------------------------------------------------------------- +# Basic reset. +# --------------------------------------------------------------------- +is($node->safe_psql('postgres', + 'SELECT stats_reset IS NULL AND reset_scan_start IS NULL + FROM pg_stat_wait_event_totals_info'), + 't', 'no reset yet: no reset times'); +my $gen0 = generation(); + +my $w = $node->background_psql('postgres'); +$w->query_safe('SET pg_wait_event_tracing.capture = stats'); +my $wpid = $w->query_safe('SELECT pg_backend_pid()'); +$w->query_safe('SELECT test_wait_totals_emit(5)'); +wait_calls(5, 'before reset'); + +$node->safe_psql('postgres', 'SELECT pg_stat_reset_wait_event_totals()'); +is(generation(), $gen0 + 1, 'the generation advanced by one'); +is(calls(), '0', 'the totals of the dedicated event restarted from zero'); +is($node->safe_psql('postgres', + 'SELECT stats_reset IS NOT NULL AND reset_scan_start <= stats_reset + FROM pg_stat_wait_event_totals_info'), + 't', 'the reset scan times are published'); + +$w->query_safe('SELECT test_wait_totals_emit(3)'); +wait_calls(3, 'after reset'); +is(calls(), '3', 'counting continues from zero after the reset'); + +# --------------------------------------------------------------------- +# Scan semantics: a completion made before the reset but still pending when +# the scan reads its ledger is counted after the reset. +# --------------------------------------------------------------------- +$node->safe_psql('postgres', 'SELECT test_wait_totals_gate_reset()'); +$w->query_until(qr/started/, + "\\echo started\nSELECT test_wait_totals_emit_hold(4);\n"); +$node->poll_query_until('postgres', 'SELECT test_wait_totals_holding()') + or die 'the emitter never reached its CPU stretch'; +is(calls(), '6', 'three of the four are published while the emitter holds'); +$node->safe_psql('postgres', 'SELECT pg_stat_reset_wait_event_totals()'); +is(calls(), '0', 'reset while the emitter holds'); +$node->safe_psql('postgres', 'SELECT test_wait_totals_release()'); +$w->query_safe('SELECT 1'); +wait_calls(1, 'pending completion after the reset'); +is(calls(), '1', + 'the pending completion is counted after the reset (scan-based cut)'); + +# --------------------------------------------------------------------- +# Independence from the per-backend resets, both ways. +# --------------------------------------------------------------------- +my $legacy = sub { + return $node->safe_psql('postgres', + "SELECT coalesce(sum(calls), 0) FROM pg_stat_wait_event_timing + WHERE pid = $wpid AND wait_event = 'TestWaitTotals'"); +}; +$w->query_safe('SELECT test_wait_totals_emit(2)'); +wait_calls(3, 'before the per-backend resets'); +my $g = generation(); +$w->query_safe('SELECT pg_stat_reset_wait_event_timing()'); +$node->safe_psql('postgres', 'SELECT pg_stat_reset_wait_event_timing_all()'); +$w->query_safe('SELECT 1'); +is(calls(), '3', 'per-backend resets do not change the totals'); +is(generation(), $g, 'per-backend resets do not change the generation'); + +$w->query_safe('SELECT test_wait_totals_emit(2)'); +$w->query_safe('SELECT 1'); +my $legacy_before = $legacy->(); +$node->safe_psql('postgres', 'SELECT pg_stat_reset_wait_event_totals()'); +is($legacy->(), $legacy_before, 'the totals reset does not touch the per-backend view'); +cmp_ok($legacy_before, '>', 0, 'and the per-backend view has something to keep'); +$w->quit; + +# --------------------------------------------------------------------- +# A controlled schedule across reset boundaries, with exact counts. Every +# emission so far (5 + 3 + 4 + 2 + 2 = 16) and below is tracked in $prior; +# completions held pending at a reset are counted after it. +# --------------------------------------------------------------------- +my $prior = 16; +{ + my $s = $node->background_psql('postgres'); + $s->query_safe('SET pg_wait_event_tracing.capture = stats'); + $node->safe_psql('postgres', 'SELECT test_wait_totals_gate_reset()'); + + $s->query_until(qr/started/, "\\echo started\nSELECT test_wait_totals_emit_hold(3);\n"); + $node->poll_query_until('postgres', 'SELECT test_wait_totals_holding()') + or die 'schedule 1: the emitter never reached its CPU stretch'; + $node->safe_psql('postgres', 'SELECT pg_stat_reset_wait_event_totals()'); + is(calls(), '0', 'schedule: zero right after the first reset'); + $node->safe_psql('postgres', 'SELECT test_wait_totals_release()'); + $s->query_safe('SELECT 1'); + wait_calls(1, 'schedule: pending completion after the first reset'); + $prior += 3; + + $s->query_safe('SELECT test_wait_totals_emit(5)'); + $s->query_safe('SELECT 1'); + wait_calls(6, 'schedule: five more'); + $prior += 5; + + $node->safe_psql('postgres', 'SELECT test_wait_totals_gate_reset()'); + $s->query_until(qr/started/, "\\echo started\nSELECT test_wait_totals_emit_hold(2);\n"); + $node->poll_query_until('postgres', 'SELECT test_wait_totals_holding()') + or die 'schedule 2: the emitter never reached its CPU stretch'; + is(calls(), '7', 'schedule: one of the two is published while it holds'); + $node->safe_psql('postgres', 'SELECT pg_stat_reset_wait_event_totals()'); + is(calls(), '0', 'schedule: zero right after the second reset'); + $node->safe_psql('postgres', 'SELECT test_wait_totals_release()'); + $s->query_safe('SELECT 1'); + wait_calls(1, 'schedule: pending completion after the second reset'); + $prior += 2; + $s->quit; +} + +# Assert-build only: a reader suspended between its scan and its generation +# check while a reset publishes must notice it, start over and return the new +# generation; and the lifetime ledgers conserve everything emitted. +my $cassert = check_pg_config('#define USE_ASSERT_CHECKING 1'); +if ($cassert) +{ + $node->safe_psql('postgres', q( +CREATE FUNCTION pwet_test_read_barrier_arm() RETURNS void + AS 'pg_wait_event_tracing', 'pwet_test_read_barrier_arm' LANGUAGE C; +CREATE FUNCTION pwet_test_read_barrier_waiting() RETURNS bool + AS 'pg_wait_event_tracing', 'pwet_test_read_barrier_waiting' LANGUAGE C; +CREATE FUNCTION pwet_test_read_barrier_release() RETURNS void + AS 'pg_wait_event_tracing', 'pwet_test_read_barrier_release' LANGUAGE C; +CREATE FUNCTION pwet_test_read_retries() RETURNS bigint + AS 'pg_wait_event_tracing', 'pwet_test_read_retries' LANGUAGE C; +CREATE FUNCTION pwet_test_totals_absolute(bigint, OUT absolute bigint, OUT baseline bigint) + AS 'pg_wait_event_tracing', 'pwet_test_totals_absolute' LANGUAGE C; +)); + my $retries0 = $node->safe_psql('postgres', 'SELECT pwet_test_read_retries()'); + my $gen_before = generation(); + $node->safe_psql('postgres', 'SELECT pwet_test_read_barrier_arm()'); + my $r = $node->background_psql('postgres'); + $r->query_until(qr/reading/, q(\echo reading +CREATE TEMP TABLE sn AS SELECT pg_wait_event_snapshot() AS s; +)); + $node->poll_query_until('postgres', 'SELECT pwet_test_read_barrier_waiting()') + or die 'the reader never reached the barrier'; + $node->safe_psql('postgres', 'SELECT pg_stat_reset_wait_event_totals()'); + $node->safe_psql('postgres', 'SELECT pwet_test_read_barrier_release()'); + $r->query_safe('SELECT 1'); + is($r->query_safe(q(SELECT s->>'reset_generation' FROM sn)), $gen_before + 1, + 'a reader suspended during a reset returns the new generation'); + is($node->safe_psql('postgres', 'SELECT pwet_test_read_retries()'), $retries0 + 1, + 'because it noticed the move and started over'); + $r->quit; +} + +# --------------------------------------------------------------------- +# A diff across a reset is an error. +# --------------------------------------------------------------------- +{ + my $a = $node->safe_psql('postgres', 'SELECT pg_wait_event_snapshot()'); + $node->safe_psql('postgres', 'SELECT pg_stat_reset_wait_event_totals()'); + my $b = $node->safe_psql('postgres', 'SELECT pg_wait_event_snapshot()'); + my ($ret, $out, $err) = $node->psql('postgres', + "SELECT * FROM pg_wait_event_diff(\$pwet\$$a\$pwet\$::jsonb, \$pwet\$$b\$pwet\$::jsonb)"); + isnt($ret, 0, 'diff across a reset fails'); + like($err, qr/reset between the snapshots/, 'with the reset message'); +} + +# --------------------------------------------------------------------- +# Resets concurrent with emitters and readers. Writers run until told to +# stop; the resetter and the reader each wait for writer progress between +# their steps, so every step really happens while the writers run. +# --------------------------------------------------------------------- +my $resets = 30; +my $nsamples = 200; +$node->safe_psql('postgres', 'SELECT test_wait_totals_gate_reset()'); +my $gen_start = generation(); + +my @writers; +for my $i (1 .. 2) +{ + my $s = $node->background_psql('postgres'); + $s->query_safe('SET pg_wait_event_tracing.capture = stats'); + $s->query_until(qr/started/, + "\\echo started\nSELECT test_wait_totals_emit_until_stopped(1);\n"); + push @writers, $s; +} + +my $resetter = $node->background_psql('postgres'); +$resetter->query_safe("SELECT test_wait_totals_wait_writers(2)"); +$resetter->query_until(qr/resetting/, qq(\\echo resetting +DO \$\$ +DECLARE p bigint := 0; +BEGIN + FOR i IN 1..$resets LOOP + p := test_wait_totals_wait_progress(p); + PERFORM pg_stat_reset_wait_event_totals(); + END LOOP; +END \$\$; +)); + +my $reader = $node->background_psql('postgres'); +$reader->query_safe("SELECT test_wait_totals_wait_writers(2)"); +$reader->query_safe(qq( +CREATE TEMP TABLE snap (i int, gen bigint, calls bigint); +DO \$\$ +DECLARE + p bigint := 0; + s jsonb; +BEGIN + FOR i IN 1..$nsamples LOOP + p := test_wait_totals_wait_progress(p); + s := pg_wait_event_snapshot(); + INSERT INTO snap + SELECT i, (s->>'reset_generation')::bigint, + coalesce((SELECT (e->>'calls')::bigint + FROM jsonb_array_elements(s->'events') e + WHERE e->>'name' = 'TestWaitTotals'), 0); + END LOOP; +END \$\$; +)); +$resetter->query_safe('SELECT 1'); # joins the reset loop; fails on any ERROR + +is($reader->query_safe('SELECT count(*) FROM snap'), $nsamples, + 'the reader took all its samples without an error'); +is($reader->query_safe( + 'SELECT count(*) FROM (SELECT gen, calls, + lag(gen) OVER (ORDER BY i) AS pg, lag(calls) OVER (ORDER BY i) AS pc + FROM snap) x + WHERE gen < pg OR (gen = pg AND calls < pc)'), + '0', 'generation never goes back and counts never decrease within a generation'); +$reader->quit; + +$node->safe_psql('postgres', 'SELECT test_wait_totals_stop()'); +my $emitted = $prior; +foreach my $s (@writers) +{ + my ($n) = split /\n/, $s->query_safe('SELECT 1'); + $emitted += $n; + $s->quit; +} +$resetter->quit; +is(generation(), $gen_start + $resets, "all $resets resets were applied"); +cmp_ok(calls(), '<=', $emitted, 'the totals never exceed what was emitted'); +if ($cassert) +{ + my $key = $node->safe_psql('postgres', 'SELECT test_wait_totals_event_key()'); + my ($abs, $base) = split /\|/, $node->safe_psql('postgres', + "SELECT absolute, baseline FROM pwet_test_totals_absolute($key)"); + is($abs, $emitted, "conservation: the ledgers hold exactly what was emitted ($emitted)"); + is(calls(), $abs - $base, 'and the view shows the ledgers minus the last baseline'); +} + +$node->stop; +done_testing(); diff --git a/src/test/modules/test_wait_totals/t/010_report.pl b/src/test/modules/test_wait_totals/t/010_report.pl new file mode 100644 index 00000000000..679c8fd66af --- /dev/null +++ b/src/test/modules/test_wait_totals/t/010_report.pl @@ -0,0 +1,290 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Instance totals of pg_wait_event_tracing: snapshots, diffs and the report +# on a live server. Crafted-document validation (schema version, integer +# ranges, unique keys, ordering, incarnation, generation, argument checks and +# permissions) is in the module's regress test; here real snapshots and the +# dedicated event give exact numbers. Capture is off cluster-wide; the one +# worker session turns it on, so the only transactions counted are its own. +# +# - ratios: 10 waits in 2 transactions give waits_per_xact 5 and the +# matching ms ratios; +# - zero denominator: with the emitter held inside its transaction, the +# transaction count of the interval is zero and the ratios are NULL; +# - include_idle: Activity and Client/ClientRead rows only when asked for, +# the transaction denominator unchanged; +# - an event missing from the second snapshot is an error, one missing from +# the first counts from zero; +# - the report: the NOTICE of an idle interval (the interval is checked +# against a lower bound only), the real pg_sleep path being cancelable, and +# argument errors. What a report contains is the diff of two snapshots, +# which the checks above exercise deterministically; no test depends on +# activity landing inside a report's sleep. + +use strict; +use warnings FATAL => 'all'; + +use FindBin; +use lib "$FindBin::RealBin/.."; + +use PostgreSQL::Test::Cluster; +use TwtUtil; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('main'); +TwtUtil::harden($node); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +autovacuum = off +)); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing'); +$node->safe_psql('postgres', 'CREATE EXTENSION test_wait_totals'); + +# One long-lived observer session does all the queries of this test, instead +# of a short-lived psql per query: on macOS /usr/bin/perl 5.34 can crash in its +# signal handler when a SIGCHLD arrives on a foreign thread, and every psql +# child that exits is such a signal. +my $obs = $node->background_psql('postgres', on_error_stop => 0); +$obs->set_query_timer_restart(); # the timer bounds each query, not the session + +sub oq +{ + my ($sql) = @_; + $obs->{stderr} = ''; + return $obs->query_safe($sql, verbose => 0); +} + +# Run a statement that may fail or notice: (stdout, stderr). +sub oerr +{ + my ($sql) = @_; + $obs->{stderr} = ''; + my $out = $obs->query($sql, verbose => 0); + my $err = $obs->{stderr}; + $obs->{stderr} = ''; + return ($out, $err); +} + +# Poll with a query on the observer; the default expected value is 't'. +sub opoll +{ + my ($sql, $want) = @_; + $want //= 't'; + my $deadline = time() + $PostgreSQL::Test::Utils::timeout_default; + my $last = ''; + while (time() < $deadline) + { + $last = oq($sql); + return 1 if $last eq $want; + select(undef, undef, undef, 0.1); + } + diag("opoll timed out: $sql\nlast: $last"); + return 0; +} + +sub snapshot { return oq('SELECT pg_wait_event_snapshot()'); } + +sub lit { my ($j) = @_; return "\$pwet\$$j\$pwet\$::jsonb"; } + +sub diff +{ + my ($a, $b, $idle, $cols) = @_; + $idle //= 'false'; + $cols //= '*'; + return oq( + "SELECT $cols FROM pg_wait_event_diff(" . lit($a) . ', ' . lit($b) . ", $idle) d + WHERE wait_event = 'TestWaitTotals' OR event_key IN (83886080, 100663296) + ORDER BY event_key"); +} + +# --------------------------------------------------------------------- +# The report with nothing happening: no rows, but the NOTICE has the +# interval and the transactions. The interval is only bounded from below. +# --------------------------------------------------------------------- +{ + my ($stdout, $stderr) = oerr('SELECT count(*) FROM pg_wait_event_report(1)'); + is($stdout, '0', 'report of an idle server has no rows'); + like($stderr, + qr/NOTICE: interval (\d+\.\d+) s, 0 transactions, 0\.00 transactions per second/, + 'but its NOTICE has the interval and the transactions'); + my ($interval) = $stderr =~ /interval (\d+\.\d+) s/; + cmp_ok($interval, '>=', 1, 'the reported interval is at least the requested second'); +} + +# --------------------------------------------------------------------- +# The real pg_sleep path is cancelable. +# --------------------------------------------------------------------- +{ + # on_error_stop off: the session survives the cancellation error, so it + # is synchronized with a plain query instead of a vanished psql. + my $b = $node->background_psql('postgres', on_error_stop => 0); + $b->set_query_timer_restart(); + my $bpid = $b->query_safe('SELECT pg_backend_pid()', verbose => 0); + $b->query_until(qr/reporting/, "\\echo reporting\nSELECT * FROM pg_wait_event_report(600);\n"); + opoll("SELECT wait_event = 'PgSleep' FROM pg_stat_activity WHERE pid = $bpid") + or die 'the report never started sleeping'; + my $off = -s $node->logfile; + oq("SELECT pg_cancel_backend($bpid)"); + # The cancellation error itself, for that statement, in the server log + # and on the session. + $node->wait_for_log( + qr/ERROR: canceling statement due to user request\n.*?STATEMENT: SELECT \* FROM pg_wait_event_report\(600\)/s, + $off); + my $one = $b->query('SELECT 1', verbose => 0); + my $berr = $b->{stderr}; + $b->{stderr} = ''; + is($one, '1', 'the canceled session is still usable'); + like($berr, qr/canceling statement due to user request/, + 'a report sleeping in pg_sleep is canceled with the cancellation error'); + $b->quit; +} + +# Argument errors. +{ + my ($out, $err) = oerr('SELECT * FROM pg_wait_event_report(0)'); + like($err, qr/ERROR: seconds must be at least 1/, 'seconds < 1 is rejected with an ERROR'); +} + +# --------------------------------------------------------------------- +# Ratios. +# --------------------------------------------------------------------- +my $w = $node->background_psql('postgres'); +$w->set_query_timer_restart(); +$w->query_safe('SET pg_wait_event_tracing.capture = stats'); +$w->query_safe('SELECT test_wait_totals_event_key()'); + +my $s_a = snapshot(); +$w->query_safe('SELECT test_wait_totals_emit(4, 50)'); +$w->query_safe('SELECT test_wait_totals_emit(6, 50)'); +opoll( + "SELECT coalesce(sum(calls), 0) = 10 FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die 'the emissions were never published'; +my $s_b = snapshot(); + +is(diff($s_a, $s_b, 'false', + 'waits, xacts, waits_per_xact, abs(ms_per_xact * xacts - wait_time_ms) < 1e-9, ' + . 'abs(ms_per_wait * waits - wait_time_ms) < 1e-9, interval_s > 0, wait_time_ms > 0'), + '10|2|5|t|t|t|t', + '10 waits in 2 transactions: waits_per_xact 5, ms ratios consistent'); + +# --------------------------------------------------------------------- +# idle filter. +# --------------------------------------------------------------------- +my $s_c = snapshot(); +$w->query_safe('SELECT test_wait_totals_emit_event(83886080, 2)'); # Activity +$w->query_safe('SELECT test_wait_totals_emit_event(100663296, 3)'); # Client:ClientRead +$w->query_safe('SELECT test_wait_totals_emit(1)'); +opoll( + "SELECT coalesce(sum(calls), 0) = 11 FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die 'the emissions were never published'; +my $s_d = snapshot(); +is(diff($s_c, $s_d, 'false', 'wait_event'), 'TestWaitTotals', + 'include_idle = false: Activity and ClientRead are left out'); +like(diff($s_c, $s_d, 'true', 'event_key'), qr/^83886080\n100663296\n/, + 'include_idle = true: they are there'); +is((split /\n/, diff($s_c, $s_d, 'false', 'xacts'))[0], + (split /\n/, diff($s_c, $s_d, 'true', 'xacts'))[0], + 'the transaction denominator is not filtered'); +like(diff($s_c, $s_d, 'true', 'waits'), qr/^2\n/, + 'the Activity row has the emitted 2 waits (and the others follow)'); + +# --------------------------------------------------------------------- +# Missing events. +# --------------------------------------------------------------------- +my $later = oq( + "SELECT jsonb_set(jsonb_set(jsonb_set(" . lit($s_d) . ", '{events}', '[]'), + '{scan_start}', to_jsonb((" . lit($s_d) . "->>'scan_end')::numeric + 1)), + '{scan_end}', to_jsonb((" . lit($s_d) . "->>'scan_end')::numeric + 2))"); +my ($out, $err) = oerr('SELECT * FROM pg_wait_event_diff(' . lit($s_d) . ', ' . lit($later) . ')'); +like($err, qr/ERROR: event \d+ of the first snapshot is missing from the second/, + 'an event missing from the second snapshot is an ERROR'); + +# Missing from the first counts from zero: s_a had no dedicated event row. +unlike($s_a, qr/TestWaitTotals/, 'the first snapshot has no dedicated event'); +is(diff($s_a, $s_b, 'false', 'waits'), '10', 'an event only in the second counts from zero'); + +# --------------------------------------------------------------------- +# Zero denominator: the emitter is held inside its transaction, so three +# completions are published while no transaction completed in the interval. +# --------------------------------------------------------------------- +oq( 'SELECT test_wait_totals_gate_reset()'); +my $s_e = snapshot(); +$w->query_until(qr/started/, + "\\echo started\nSELECT test_wait_totals_emit_hold(4);\n"); +opoll( 'SELECT test_wait_totals_holding()') + or die 'the emitter never reached its CPU stretch'; +my $s_f = snapshot(); +is(diff($s_e, $s_f, 'false', + 'waits, xacts, waits_per_xact IS NULL, ms_per_xact IS NULL, ms_per_wait IS NOT NULL'), + '3|0|t|t|t', 'no transaction in the interval: the per-transaction ratios are NULL'); +oq( 'SELECT test_wait_totals_release()'); +$w->query_safe('SELECT 1'); +$w->quit; + +# --------------------------------------------------------------------- +# A report with rows, deterministically (assert builds): the first snapshot +# of the report is suspended right after its scan, activity is produced and +# published while it is suspended, then the report continues. So the +# activity is certainly between the two snapshots, with no sleep window to +# hit. Also checks that include_idle is forwarded to the diff. +# --------------------------------------------------------------------- +if (check_pg_config('#define USE_ASSERT_CHECKING 1')) +{ + oq( q( +CREATE FUNCTION pwet_test_read_barrier_arm() RETURNS void + AS 'pg_wait_event_tracing', 'pwet_test_read_barrier_arm' LANGUAGE C; +CREATE FUNCTION pwet_test_read_barrier_waiting() RETURNS bool + AS 'pg_wait_event_tracing', 'pwet_test_read_barrier_waiting' LANGUAGE C; +CREATE FUNCTION pwet_test_read_barrier_release() RETURNS void + AS 'pg_wait_event_tracing', 'pwet_test_read_barrier_release' LANGUAGE C; +)); + my $act = $node->background_psql('postgres'); + $act->set_query_timer_restart(); + $act->query_safe('SET pg_wait_event_tracing.capture = stats'); + $act->query_safe('SELECT test_wait_totals_event_key()'); + + foreach my $idle ('false', 'true') + { + my $base = oq( + "SELECT coalesce(sum(calls), 0) FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'"); + oq( 'SELECT pwet_test_read_barrier_arm()'); + my $rb = $node->background_psql('postgres'); + $rb->set_query_timer_restart(); + $rb->query_safe('SET client_min_messages = warning'); # the NOTICE is tested above + $rb->query_until(qr/reporting/, qq(\\echo reporting +CREATE TEMP TABLE rep AS SELECT * FROM pg_wait_event_report(1, $idle); +)); + opoll( 'SELECT pwet_test_read_barrier_waiting()') + or die 'the report never reached its first snapshot barrier'; + + # The report holds its first scan; this activity comes after it. + $act->query_safe('SELECT test_wait_totals_emit(7)'); + $act->query_safe('SELECT test_wait_totals_emit_event(83886080, 2)'); # Activity + opoll( + "SELECT coalesce(sum(calls), 0) = $base + 7 FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die 'the activity was never published'; + oq( 'SELECT pwet_test_read_barrier_release()'); + $rb->query_safe('SELECT 1'); # the report is over + + is($rb->query_safe(q(SELECT waits || ',' || xacts FROM rep WHERE wait_event = 'TestWaitTotals')), + '7,2', "report (include_idle = $idle): the 7 waits of 2 transactions, between its snapshots"); + is($rb->query_safe(q(SELECT count(*) FROM rep WHERE event_key = 83886080)), + ($idle eq 'true' ? '1' : '0'), + "report (include_idle = $idle): the Activity row is " . ($idle eq 'true' ? 'there' : 'left out')); + $rb->quit; + } + $act->quit; +} + +$obs->quit; +$node->stop; +done_testing(); -- 2.49.0