From d35872952f439859f4fcde3ee8fccb167fa4ee80 Mon Sep 17 00:00:00 2001 From: Dmitry Fomin Date: Tue, 10 Nov 2026 09:55:47 +0100 Subject: [PATCH v15 8/9] pg_wait_event_tracing: instance totals views Add extension version 1.1 (update script 1.0--1.1; the version stays open until the remaining objects of the series are added to the same script) with pg_stat_wait_event_totals, which sums all lifetime ledgers, occupied slots or not, including processes that already exited, and pg_stat_wait_event_totals_info with the incarnation, the overflow pairs and the ledger diagnostics. Events are identified by the full wait_event_info code; the two overflow rows use the reserved keys -1 and -2. A ledger is read as a block copy accepted only if its seqlock count was even and unchanged around the copy, with no lock held and interrupts checked between retries. Totals raise an error while a ledger is invalid or a sum exceeds bigint; the info view still shows the diagnostics. Names of custom events are resolved only through the registered-name table, never through the resolver that errors for an unknown id. Document collection, the publication rule, exit behaviour, coverage and memory. Add regression tests for installation, upgrade, view shape, privileges and the incarnation, TAP tests for counting, publication, exit drain, capture changes, resets, slot reuse, server processes, parallel workers, the dictionary, concurrent reads and restarts, and deterministic seqlock, range and invalid-ledger tests. --- contrib/pg_wait_event_tracing/Makefile | 7 +- .../expected/pg_wait_event_tracing_totals.out | 195 ++++++ contrib/pg_wait_event_tracing/meson.build | 3 + .../pg_wait_event_tracing--1.0--1.1.sql | 74 ++ .../pg_wait_event_tracing.c | 660 ++++++++++++++++++ .../pg_wait_event_tracing.control | 2 +- .../sql/pg_wait_event_tracing_totals.sql | 104 +++ .../t/017_totals_ledger.pl | 155 ++++ doc/src/sgml/pgwaiteventtracing.sgml | 118 +++- src/test/modules/test_wait_totals/Makefile | 4 + src/test/modules/test_wait_totals/meson.build | 11 + .../test_wait_totals/t/001_publication.pl | 162 +++++ .../modules/test_wait_totals/t/002_exit.pl | 161 +++++ .../test_wait_totals/t/003_capture_reset.pl | 176 +++++ .../test_wait_totals/t/004_slots_servers.pl | 129 ++++ .../test_wait_totals/t/005_dictionary.pl | 191 +++++ .../test_wait_totals/t/006_coherence.pl | 117 ++++ .../modules/test_wait_totals/t/007_restart.pl | 104 +++ 18 files changed, 2368 insertions(+), 5 deletions(-) create mode 100644 contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_totals.out create mode 100644 contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0--1.1.sql create mode 100644 contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_totals.sql create mode 100644 contrib/pg_wait_event_tracing/t/017_totals_ledger.pl create mode 100644 src/test/modules/test_wait_totals/t/001_publication.pl create mode 100644 src/test/modules/test_wait_totals/t/002_exit.pl create mode 100644 src/test/modules/test_wait_totals/t/003_capture_reset.pl create mode 100644 src/test/modules/test_wait_totals/t/004_slots_servers.pl create mode 100644 src/test/modules/test_wait_totals/t/005_dictionary.pl create mode 100644 src/test/modules/test_wait_totals/t/006_coherence.pl create mode 100644 src/test/modules/test_wait_totals/t/007_restart.pl diff --git a/contrib/pg_wait_event_tracing/Makefile b/contrib/pg_wait_event_tracing/Makefile index ef8522ebea6..738fc33018e 100644 --- a/contrib/pg_wait_event_tracing/Makefile +++ b/contrib/pg_wait_event_tracing/Makefile @@ -6,10 +6,11 @@ OBJS = \ pg_wait_event_tracing.o EXTENSION = pg_wait_event_tracing -DATA = pg_wait_event_tracing--1.0.sql +DATA = pg_wait_event_tracing--1.0.sql pg_wait_event_tracing--1.0--1.1.sql PGFILEDESC = "pg_wait_event_tracing - statistics and trace collection for explicitly instrumented wait events" -REGRESS = pg_wait_event_tracing pg_wait_event_tracing_trace +REGRESS = pg_wait_event_tracing pg_wait_event_tracing_trace \ + pg_wait_event_tracing_totals REGRESS_OPTS = --temp-config $(top_srcdir)/contrib/pg_wait_event_tracing/pg_wait_event_tracing.conf # The tests need the module preloaded, which typical installcheck users @@ -17,7 +18,7 @@ REGRESS_OPTS = --temp-config $(top_srcdir)/contrib/pg_wait_event_tracing/pg_wait NO_INSTALLCHECK = 1 TAP_TESTS = 1 -EXTRA_INSTALL = src/test/modules/injection_points +EXTRA_INSTALL = src/test/modules/injection_points src/test/modules/test_wait_totals export enable_injection_points ifdef USE_PGXS 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 new file mode 100644 index 00000000000..c4686b8b49c --- /dev/null +++ b/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing_totals.out @@ -0,0 +1,195 @@ +-- +-- PG_WAIT_EVENT_TRACING_TOTALS +-- +-- Extension version 1.1: the instance-wide totals views. Installation and +-- upgrade, the shape of the views, the reserved overflow keys, the +-- incarnation format and the privileges. Counting itself is exercised by +-- the TAP tests of src/test/modules/test_wait_totals, where a dedicated wait +-- event makes exact assertions possible; here only things that hold whatever +-- other tests did to this server are asserted. +-- +-- 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; +CREATE EXTENSION pg_wait_event_tracing VERSION '1.0'; +SELECT extversion FROM pg_extension WHERE extname = 'pg_wait_event_tracing'; + extversion +------------ + 1.0 +(1 row) + +SELECT count(*) AS totals_objects_in_1_0 +FROM pg_proc WHERE proname LIKE 'pg_stat_get_wait_event_totals%'; + totals_objects_in_1_0 +----------------------- + 0 +(1 row) + +ALTER EXTENSION pg_wait_event_tracing UPDATE TO '1.1'; +SELECT extversion FROM pg_extension WHERE extname = 'pg_wait_event_tracing'; + extversion +------------ + 1.1 +(1 row) + +SELECT count(*) AS totals_objects_after_update +FROM pg_proc WHERE proname LIKE 'pg_stat_get_wait_event_totals%'; + totals_objects_after_update +----------------------------- + 2 +(1 row) + +DROP EXTENSION pg_wait_event_tracing; +CREATE EXTENSION pg_wait_event_tracing; +SELECT extversion FROM pg_extension WHERE extname = 'pg_wait_event_tracing'; + extversion +------------ + 1.1 +(1 row) + +SELECT count(*) AS totals_objects_fresh +FROM pg_proc WHERE proname LIKE 'pg_stat_get_wait_event_totals%'; + totals_objects_fresh +---------------------- + 2 +(1 row) + +-- Columns of the two views. +SELECT attname, format_type(atttypid, atttypmod) AS type +FROM pg_attribute +WHERE attrelid = 'pg_stat_wait_event_totals'::regclass AND attnum > 0 +ORDER BY attnum; + attname | type +-----------------+------------------ + wait_event_type | text + wait_event | text + event_key | bigint + calls | bigint + total_time_ms | double precision + avg_time_us | double precision +(6 rows) + +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 +-------------------------+------------------ + incarnation | text + lwlock_overflow_calls | bigint + lwlock_overflow_time_ms | double precision + flat_overflow_calls | bigint + flat_overflow_time_ms | double precision + invalid_ledgers | bigint + ledger_slots | integer + capturing_backends | integer +(8 rows) + +-- One info row; the incarnation is 16 lower-case hex digits. +SELECT count(*) AS info_rows FROM pg_stat_wait_event_totals_info; + info_rows +----------- + 1 +(1 row) + +SELECT incarnation ~ '^[0-9a-f]{16}$' AS incarnation_format, + invalid_ledgers, + ledger_slots > 0 AS has_slots, + capturing_backends >= 0 AS has_capturing +FROM pg_stat_wait_event_totals_info; + incarnation_format | invalid_ledgers | has_slots | has_capturing +--------------------+-----------------+-----------+--------------- + t | 0 | t | t +(1 row) + +-- The incarnation does not change while the server runs. +SELECT incarnation AS incarnation_before FROM pg_stat_wait_event_totals_info \gset +SELECT incarnation = :'incarnation_before' AS incarnation_stable +FROM pg_stat_wait_event_totals_info; + incarnation_stable +-------------------- + t +(1 row) + +-- The two overflow rows exist with their reserved keys, and no other row has +-- a negative key; every other key is a full wait event code, which carries +-- the wait event class in its top byte. +SELECT event_key, wait_event_type, wait_event, calls >= 0 AS calls_ok +FROM pg_stat_wait_event_totals +WHERE event_key < 0 +ORDER BY event_key; + event_key | wait_event_type | wait_event | calls_ok +-----------+-----------------+------------+---------- + -2 | (overflow) | (overflow) | t + -1 | LWLock | (overflow) | t +(2 rows) + +SELECT count(*) AS bad_keys +FROM pg_stat_wait_event_totals +WHERE event_key >= 0 AND (event_key >= 4294967296 OR event_key < 16777216); + bad_keys +---------- + 0 +(1 row) + +SELECT count(*) AS duplicate_keys +FROM (SELECT event_key FROM pg_stat_wait_event_totals + GROUP BY event_key HAVING count(*) > 1) d; + duplicate_keys +---------------- + 0 +(1 row) + +-- Counters are never negative, and the average is NULL exactly when there +-- are no calls. +SELECT count(*) AS bad_rows +FROM pg_stat_wait_event_totals +WHERE calls < 0 OR total_time_ms < 0 OR (calls = 0) <> (avg_time_us IS NULL); + bad_rows +---------- + 0 +(1 row) + +-- Privileges: not readable by PUBLIC, neither the views nor the functions +-- behind them; readable with pg_read_all_stats. +CREATE ROLE regress_pwet_plain; +CREATE ROLE regress_pwet_stats IN ROLE pg_read_all_stats; +SELECT has_function_privilege('regress_pwet_plain', + 'pg_stat_get_wait_event_totals()', 'EXECUTE') AS plain_totals_fn, + has_function_privilege('regress_pwet_plain', + 'pg_stat_get_wait_event_totals_info()', 'EXECUTE') AS plain_info_fn, + has_function_privilege('regress_pwet_stats', + 'pg_stat_get_wait_event_totals()', 'EXECUTE') AS stats_totals_fn, + has_function_privilege('regress_pwet_stats', + 'pg_stat_get_wait_event_totals_info()', 'EXECUTE') AS stats_info_fn; + plain_totals_fn | plain_info_fn | stats_totals_fn | stats_info_fn +-----------------+---------------+-----------------+--------------- + f | f | t | t +(1 row) + +SET ROLE regress_pwet_plain; +SELECT count(*) FROM pg_stat_wait_event_totals; +ERROR: permission denied for view pg_stat_wait_event_totals +SELECT count(*) FROM pg_stat_wait_event_totals_info; +ERROR: permission denied for view pg_stat_wait_event_totals_info +SELECT count(*) FROM pg_stat_get_wait_event_totals(); +ERROR: permission denied for function pg_stat_get_wait_event_totals +SELECT count(*) FROM pg_stat_get_wait_event_totals_info(); +ERROR: permission denied for function pg_stat_get_wait_event_totals_info +RESET ROLE; +SET ROLE regress_pwet_stats; +SELECT count(*) > 0 AS totals_visible FROM pg_stat_wait_event_totals; + totals_visible +---------------- + t +(1 row) + +SELECT count(*) AS info_visible FROM pg_stat_wait_event_totals_info; + info_visible +-------------- + 1 +(1 row) + +RESET ROLE; +DROP ROLE regress_pwet_plain; +DROP ROLE regress_pwet_stats; diff --git a/contrib/pg_wait_event_tracing/meson.build b/contrib/pg_wait_event_tracing/meson.build index e8c97def432..f897c0e2976 100644 --- a/contrib/pg_wait_event_tracing/meson.build +++ b/contrib/pg_wait_event_tracing/meson.build @@ -18,6 +18,7 @@ contrib_targets += pg_wait_event_tracing install_data( 'pg_wait_event_tracing--1.0.sql', + 'pg_wait_event_tracing--1.0--1.1.sql', 'pg_wait_event_tracing.control', kwargs: contrib_data_args, ) @@ -30,6 +31,7 @@ tests += { 'sql': [ 'pg_wait_event_tracing', 'pg_wait_event_tracing_trace', + 'pg_wait_event_tracing_totals', ], 'regress_args': ['--temp-config', files('pg_wait_event_tracing.conf')], # Needs shared_preload_libraries, which typical runningcheck users do @@ -57,6 +59,7 @@ tests += { 't/014_by_statement_pre.pl', 't/015_by_statement_pgbench.pl', 't/016_by_statement_oracle.pl', + 't/017_totals_ledger.pl', ], }, } 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 new file mode 100644 index 00000000000..a28c4908ff0 --- /dev/null +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0--1.1.sql @@ -0,0 +1,74 @@ +/* contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0--1.1.sql */ + +-- complain if script is sourced in psql, rather than via ALTER EXTENSION +\echo Use "ALTER EXTENSION pg_wait_event_tracing UPDATE TO '1.1'" to load this file. \quit + +-- Instance-wide cumulative wait totals. Unlike pg_stat_wait_event_timing, +-- which has one row set per live collecting backend and forgets a backend +-- when it exits, resets or stops collecting, these totals sum a lifetime +-- ledger kept per process slot, so they include processes that have already +-- exited. They start from zero at every server start (including a crash +-- restart); the incarnation in the info view changes when they do. +-- +-- event_key is the full 32-bit wait event code (the class in the top byte). +-- Two reserved negative keys stand for events that did not fit: -1 is the +-- LWLock overflow row (tranches beyond pg_wait_event_tracing.max_tranches +-- 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. +CREATE FUNCTION pg_stat_get_wait_event_totals( + OUT wait_event_type text, + OUT wait_event text, + OUT event_key bigint, + OUT calls bigint, + OUT total_time_ms double precision, + OUT avg_time_us double precision) +RETURNS SETOF record +AS 'MODULE_PATHNAME', 'pg_stat_get_wait_event_totals' +LANGUAGE C VOLATILE PARALLEL RESTRICTED; +REVOKE EXECUTE ON FUNCTION pg_stat_get_wait_event_totals() FROM PUBLIC; +GRANT EXECUTE ON FUNCTION pg_stat_get_wait_event_totals() TO pg_read_all_stats; + +CREATE VIEW pg_stat_wait_event_totals AS + SELECT + t.wait_event_type, + t.wait_event, + t.event_key, + t.calls, + t.total_time_ms, + t.avg_time_us + FROM pg_stat_get_wait_event_totals() t; +REVOKE ALL ON pg_stat_wait_event_totals FROM PUBLIC; +GRANT SELECT ON pg_stat_wait_event_totals TO pg_read_all_stats; + +CREATE FUNCTION pg_stat_get_wait_event_totals_info( + OUT incarnation text, + OUT lwlock_overflow_calls bigint, + OUT lwlock_overflow_time_ms double precision, + OUT flat_overflow_calls bigint, + OUT flat_overflow_time_ms double precision, + OUT invalid_ledgers bigint, + OUT ledger_slots integer, + OUT capturing_backends integer) +RETURNS SETOF record +AS 'MODULE_PATHNAME', 'pg_stat_get_wait_event_totals_info' +LANGUAGE C VOLATILE PARALLEL RESTRICTED; +REVOKE EXECUTE ON FUNCTION pg_stat_get_wait_event_totals_info() FROM PUBLIC; +GRANT EXECUTE ON FUNCTION pg_stat_get_wait_event_totals_info() TO pg_read_all_stats; + +CREATE VIEW pg_stat_wait_event_totals_info AS + SELECT + t.incarnation, + t.lwlock_overflow_calls, + t.lwlock_overflow_time_ms, + t.flat_overflow_calls, + t.flat_overflow_time_ms, + t.invalid_ledgers, + t.ledger_slots, + t.capturing_backends + 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; 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 05960ac11bf..241dcedd793 100644 --- a/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c @@ -59,6 +59,7 @@ */ #include "postgres.h" +#include "access/htup_details.h" #include "access/xact.h" #include "catalog/pg_authid.h" #include "catalog/pg_type_d.h" @@ -111,6 +112,8 @@ PG_FUNCTION_INFO_V1(pg_wait_event_tracing_hooks_installed); PG_FUNCTION_INFO_V1(pg_get_backend_wait_event_trace); PG_FUNCTION_INFO_V1(pg_get_wait_event_trace); PG_FUNCTION_INFO_V1(pg_stat_clear_orphaned_wait_event_rings); +PG_FUNCTION_INFO_V1(pg_stat_get_wait_event_totals); +PG_FUNCTION_INFO_V1(pg_stat_get_wait_event_totals_info); PGDLLEXPORT void _PG_init(void); @@ -399,6 +402,11 @@ typedef struct PwetRegionHeader #define PWET_PGSTAT_KIND PGSTAT_KIND_EXPERIMENTAL #define PWET_TOTALS_HEADER_NAME "pg_wait_event_tracing totals header" #define PWET_LEDGERS_NAME "pg_wait_event_tracing ledgers" +#define PWET_NUM_TRANCHE_IDS 65536 + +/* Reserved event_key values of the two overflow rows (no real key is < 0). */ +#define PWET_KEY_LWLOCK_OVERFLOW (-1) +#define PWET_KEY_FLAT_OVERFLOW (-2) typedef struct PwetTotal { @@ -431,6 +439,18 @@ 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; + int64 invalid_ledgers; + bool sum_overflow; /* some sum exceeded what bigint can hold */ + bool overflow_sum_overflow; /* ... one of the two overflow pairs */ + PwetTotal flat[PWET_NUM_EVENTS]; + PwetTotal tranche[PWET_NUM_TRANCHE_IDS]; +} PwetTotalsScan; + typedef struct PwetPgStatShared { uint32 unused; @@ -1179,6 +1199,119 @@ pwet_get_my_ledger(void) return pwet_my_ledger; } +#ifdef USE_ASSERT_CHECKING +/* Test-only hooks of the ledger reader; see pwet_ledger_read(). */ +static void (*pwet_test_ledger_copy_hook) (PwetLedger *src); +static void (*pwet_test_ledger_retry_hook) (PwetLedger *src, int retries); +static int pwet_test_ledger_retries; +#endif + +/* + * Copy one ledger into dst under the seqlock: accept the copy only if + * changecount was even before it and unchanged after it. The reader holds + * no lock and checks for interrupts between retries, so a stalled writer + * cannot make it uncancellable. + */ +static void +pwet_ledger_read(PwetLedger *src, PwetLedger *dst) +{ + int retries = 0; + + for (;;) + { + uint32 cc = pg_atomic_read_u32(&src->changecount); + + if ((cc & 1) == 0) + { + pg_read_barrier(); + memcpy(dst, src, pwet_ledger_bytes); +#ifdef USE_ASSERT_CHECKING + if (pwet_test_ledger_copy_hook != NULL) + pwet_test_ledger_copy_hook(src); +#endif + pg_read_barrier(); + if (pg_atomic_read_u32(&src->changecount) == cc) + return; + } + + retries++; +#ifdef USE_ASSERT_CHECKING + pwet_test_ledger_retries++; + if (pwet_test_ledger_retry_hook != NULL) + pwet_test_ledger_retry_hook(src, retries); +#endif + CHECK_FOR_INTERRUPTS(); + if (retries > 100) + pg_usleep(100); + } +} + +/* Add b to a; return false if the sum cannot be a bigint. */ +static bool +pwet_total_sum(PwetTotal *a, const PwetTotal *b) +{ + if (a->calls > (uint64) PG_INT64_MAX - b->calls || + a->total_ns > (uint64) PG_INT64_MAX - b->total_ns) + return false; + a->calls += b->calls; + a->total_ns += b->total_ns; + return true; +} + +/* + * Sum every slot's ledger, occupied or not, into *scan (zeroed by the + * caller). Each ledger is read as an accepted copy, never from live + * contents. An invalid ledger is counted in invalid_ledgers (its values are + * still summed so the diagnostics stay visible); a sum that would exceed + * bigint sets sum_overflow and is left out. Scratch is allocated in the + * caller's memory context. + */ +static void +pwet_totals_scan(PwetTotalsScan *scan) +{ + PwetLedger *copy; + int slot; + + if (pwet_ledgers == NULL) + ereport(ERROR, + (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE), + errmsg("pg_wait_event_tracing instance totals are not available"))); + + copy = palloc(pwet_ledger_bytes); + for (slot = 0; slot < PWET_NUM_SLOTS; slot++) + { + int i; + + /* Own pending completion first, so a session sees its own waits. */ + if (slot == MyProcNumber) + pwet_flush_pending(); + + pwet_ledger_read(pwet_ledger_at(slot), copy); + + if (copy->invalid) + scan->invalid_ledgers++; + 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; + for (i = 0; i < PWET_NUM_EVENTS; i++) + if (copy->flat[i].calls != 0 && + !pwet_total_sum(&scan->flat[i], ©->flat[i])) + scan->sum_overflow = true; + for (i = 0; i < pwet_ledger_hash_size; i++) + { + PwetLedgerCell *cell = ©->cells[i]; + + if (cell->tranche_plus1 == 0 || cell->total.calls == 0) + continue; + if (cell->tranche_plus1 > PWET_NUM_TRANCHE_IDS || + !pwet_total_sum(&scan->tranche[cell->tranche_plus1 - 1], + &cell->total)) + scan->sum_overflow = true; + } + } + pfree(copy); +} + /* Initialize a freshly created control table: mark every slot empty. */ static void pwet_control_init(PwetSlot *slots) @@ -3725,6 +3858,273 @@ pg_stat_get_wait_event_timing_overflow(PG_FUNCTION_ARGS) PG_RETURN_VOID(); } +/* + * Instance totals: SQL surface. + * + * event_key is the full 32-bit wait_event_info code (class in the top byte, + * event or LWLock tranche id below), so it is never negative; the two + * overflow rows use the reserved keys -1 (LWLock tranches that did not fit + * the dictionary) and -2 (events outside the flat table), which no wait + * event can have. Events that did not fit are merged into these rows, with + * both count and time, never dropped. + * + * Names are resolved only for keys known to resolve. Built-in classes never + * raise an error in the resolvers. A LWLock tranche id enters a ledger only + * from a completed wait on a lock of that tranche, and tranche registrations + * are never removed, so it resolves as well. A custom (Extension or + * InjectionPoint) event id is resolved only through the table of names + * currently registered; the resolver that takes an id raises an error for an + * unknown one, so an id missing from that table gets a placeholder name. + */ +typedef struct PwetCustomName +{ + uint32 info; + const char *name; +} PwetCustomName; + +static int +pwet_collect_custom_names(PwetCustomName **map) +{ + static const uint32 classes[] = {PG_WAIT_EXTENSION, PG_WAIT_INJECTIONPOINT}; + PwetCustomName *result = NULL; + int n = 0; + int c; + + for (c = 0; c < lengthof(classes); c++) + { + int count; + char **names = GetWaitEventCustomNames(classes[c], &count); + int k; + + if (count == 0) + continue; + result = result == NULL ? + palloc_array(PwetCustomName, n + count) : + repalloc_array(result, PwetCustomName, n + count); + for (k = 0; k < count; k++) + { + /* The name exists, so this finds it and never allocates an id. */ + result[n].info = classes[c] == PG_WAIT_EXTENSION ? + WaitEventExtensionNew(names[k]) : + WaitEventInjectionPointNew(names[k]); + result[n].name = names[k]; + n++; + } + } + + *map = result; + return n; +} + +static void +pwet_totals_put_row(ReturnSetInfo *rsinfo, const char *type, const char *name, + int64 key, const PwetTotal *t) +{ + Datum values[6]; + bool nulls[6] = {0}; + + values[0] = CStringGetTextDatum(type); + values[1] = CStringGetTextDatum(name); + values[2] = Int64GetDatum(key); + values[3] = Int64GetDatum((int64) t->calls); + values[4] = Float8GetDatum((double) t->total_ns / 1000000.0); + if (t->calls > 0) + values[5] = Float8GetDatum((double) t->total_ns / (double) t->calls / + 1000.0); + else + nulls[5] = true; + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls); +} + +/* + * SQL function: pg_stat_get_wait_event_totals() + * + * 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. + */ +Datum +pg_stat_get_wait_event_totals(PG_FUNCTION_ARGS) +{ + ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + PwetTotalsScan *scan; + PwetCustomName *custom = NULL; + int ncustom = 0; + bool have_custom = false; + int i; + int j; + int id; + + InitMaterializedSRF(fcinfo, 0); + + scan = palloc0(sizeof(PwetTotalsScan)); + pwet_totals_scan(scan); + + if (scan->invalid_ledgers > 0) + ereport(ERROR, + (errcode(ERRCODE_DATA_CORRUPTED), + errmsg("wait event totals are invalid: %lld lifetime ledger(s) exceeded the bigint range", + (long long) scan->invalid_ledgers), + errhint("See pg_stat_wait_event_totals_info; the totals are valid again only after a server restart."))); + if (scan->sum_overflow) + ereport(ERROR, + (errcode(ERRCODE_NUMERIC_VALUE_OUT_OF_RANGE), + errmsg("wait event totals exceed the bigint range"))); + + 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); + + pwet_totals_put_row(rsinfo, pgstat_get_wait_event_type(info), + name, (int64) info, t); + } + } + + for (id = 0; id < PWET_NUM_TRANCHE_IDS; id++) + { + PwetTotal *t = &scan->tranche[id]; + uint32 info = PG_WAIT_LWLOCK | (uint32) id; + + if (t->calls == 0) + continue; + pwet_totals_put_row(rsinfo, "LWLock", pgstat_get_wait_event(info), + (int64) info, t); + } + + pwet_totals_put_row(rsinfo, "LWLock", "(overflow)", + PWET_KEY_LWLOCK_OVERFLOW, &scan->lwlock_overflow); + pwet_totals_put_row(rsinfo, "(overflow)", "(overflow)", + PWET_KEY_FLAT_OVERFLOW, &scan->flat_overflow); + + pfree(scan); + PG_RETURN_VOID(); +} + +/* + * Does slot i hold a collection payload whose owner is the live process of + * that ProcNumber? As in the per-backend readers, the owner token is + * checked against the backend-status entry (or, for a process without one, + * against the PGPROC). A fixed-slot process withdraws its token in + * pwet_exit_drain() at an orderly exit, so a token that is still there + * belongs to a live process (an abrupt death restarts the cluster); a payload + * itself is never freed and is reinitialized by the next claimant. The + * count is advisory. One rare case can still count a slot wrongly: a + * fixed-slot process that claims its slot and then fails during start-up, + * before its exit callback is registered, leaves the token behind, and a + * later process that reuses the same PID in the same slot is taken for its + * predecessor until it claims the slot itself. + */ +static bool +pwet_slot_owner_is_live(int slot) +{ + PgBackendStatus *beentry = pgstat_get_beentry_by_proc_number(slot); + int pid = pwet_ctl[slot].owner_pid; + + if (pid == 0) + return false; + if (beentry != NULL) + return beentry->st_procpid == pid && + beentry->st_proc_start_timestamp == pwet_ctl[slot].owner_start; + + /* + * No backend-status entry: a worker without a database connection has + * none. Then the slot's PGPROC must still be held by the owner's pid. + * The pid alone could be reused by a successor of the slot, so this + * relies on the token being withdrawn by pwet_exit_drain() before the + * PGPROC is released: a token still present belongs to a live process. + */ + return GetPGProcByNumber(slot)->pid == pid; +} + +/* + * SQL function: pg_stat_get_wait_event_totals_info() + * + * 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. + */ +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}; + int capturing = 0; + int i; + + InitMaterializedSRF(fcinfo, 0); + + scan = palloc0(sizeof(PwetTotalsScan)); + pwet_totals_scan(scan); + + for (i = 0; i < PWET_NUM_SLOTS; i++) + if (pwet_slot_owner_is_live(i)) + capturing++; + + values[0] = CStringGetTextDatum(psprintf("%016" PRIx64, + pwet_totals_header->incarnation)); + if (scan->overflow_sum_overflow) + nulls[1] = nulls[2] = nulls[3] = nulls[4] = true; + else + { + values[1] = Int64GetDatum((int64) scan->lwlock_overflow.calls); + values[2] = Float8GetDatum((double) scan->lwlock_overflow.total_ns / + 1000000.0); + values[3] = Int64GetDatum((int64) scan->flat_overflow.calls); + values[4] = Float8GetDatum((double) scan->flat_overflow.total_ns / + 1000000.0); + } + values[5] = Int64GetDatum(scan->invalid_ledgers); + values[6] = Int32GetDatum(PWET_NUM_SLOTS); + values[7] = Int32GetDatum(capturing); + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls); + + pfree(scan); + PG_RETURN_VOID(); +} + /* * Flushes the pending wait, if any, before zeroing: the wait already * happened and, per the decision document, its recorded values must not @@ -4742,4 +5142,264 @@ pwet_test_waits(PG_FUNCTION_ARGS) PG_RETURN_VOID(); } +PG_FUNCTION_INFO_V1(pwet_test_ledger_dictionary); +PG_FUNCTION_INFO_V1(pwet_test_slot_counted); +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); + +/* pwet_test_slot_counted(slot int) returns bool: would capturing_backends count it? */ +Datum +pwet_test_slot_counted(PG_FUNCTION_ARGS) +{ + int slot = PG_GETARG_INT32(0); + + PWET_TEST_CHECK(slot >= 0 && slot < PWET_NUM_SLOTS); + pwet_flush_pending(); + PG_RETURN_BOOL(pwet_slot_owner_is_live(slot)); +} + +/* + * pwet_test_ledger_dictionary() returns void + * + * The ledger dictionary on a private ledger (needs max_tranches = 16, so + * hash_size is 32): keys base + 32 * k share one home cell, so the 16 + * admitted keys form a cluster that wraps around the end of the cell array. + * With the table full every admitted key must still be found with its + * count, a further key must go to the overflow pair with count and time and + * get no cell, and admitted keys must not move. + */ +Datum +pwet_test_ledger_dictionary(PG_FUNCTION_ARGS) +{ + PwetLedger *l = palloc0(pwet_ledger_size(pwet_max_tranches)); + int home; + int k; + int wrapped = 0; + int pos[16]; + + PWET_TEST_CHECK(pwet_max_tranches == 16 && pwet_ledger_hash_size == 32); + pg_atomic_init_u32(&l->changecount, 0); + + for (k = 0; k < 16; k++) + pwet_ledger_add(l, PG_WAIT_LWLOCK | (1 + 32 * k), 10 + k); + PWET_TEST_CHECK(l->num_used == 16); + + home = (uint32) 1 * 2654435761U & 31; + for (k = 0; k < 16; k++) + { + bool insert; + PwetLedgerCell *cell = pwet_ledger_find_cell(l, 1 + 32 * k, &insert); + + PWET_TEST_CHECK(cell != NULL && !insert); + PWET_TEST_CHECK(cell->total.calls == 1 && + cell->total.total_ns == (uint64) (10 + k)); + pos[k] = cell - l->cells; + if (pos[k] < home) + wrapped++; + } + PWET_TEST_CHECK(wrapped > 0); + + /* The table is full: one more tranche overflows, with count and time. */ + for (k = 0; k < 3; k++) + pwet_ledger_add(l, PG_WAIT_LWLOCK | (1 + 32 * 16), 100); + PWET_TEST_CHECK(l->num_used == 16); + PWET_TEST_CHECK(l->lwlock_overflow.calls == 3 && + l->lwlock_overflow.total_ns == 300); + { + bool insert; + + PWET_TEST_CHECK(pwet_ledger_find_cell(l, 1 + 32 * 16, &insert) == NULL); + } + + /* Admitted keys are still found, did not move, and keep counting. */ + for (k = 0; k < 16; k++) + { + bool insert; + PwetLedgerCell *cell; + + pwet_ledger_add(l, PG_WAIT_LWLOCK | (1 + 32 * k), 1); + cell = pwet_ledger_find_cell(l, 1 + 32 * k, &insert); + PWET_TEST_CHECK(cell != NULL && !insert && cell - l->cells == pos[k]); + PWET_TEST_CHECK(cell->total.calls == 2 && + cell->total.total_ns == (uint64) (11 + k)); + } + PWET_TEST_CHECK(l->lwlock_overflow.calls == 3); + PWET_TEST_CHECK(l->invalid == 0); + + PG_RETURN_VOID(); +} + +/* + * pwet_test_ledger_set(event_key bigint, calls bigint, total_ns bigint) + * + * Set this process's ledger pair of the event (or of an overflow pair: key + * -1 is the LWLock one, -2 the flat one) to the given values, inside the + * write bracket, to reach counter ranges no test could reach by emitting. + */ +Datum +pwet_test_ledger_set(PG_FUNCTION_ARGS) +{ + int64 key = PG_GETARG_INT64(0); + int64 calls = PG_GETARG_INT64(1); + int64 total_ns = PG_GETARG_INT64(2); + PwetLedger *l; + PwetTotal *pair; + PwetLedgerCell *cell = NULL; + bool insert = false; + + pwet_flush_pending(); + l = pwet_get_my_ledger(); + PWET_TEST_CHECK(l != NULL); + + if (key == PWET_KEY_LWLOCK_OVERFLOW) + pair = &l->lwlock_overflow; + else if (key == PWET_KEY_FLAT_OVERFLOW) + pair = &l->flat_overflow; + else + pair = pwet_ledger_target(l, (uint32) key, &cell, &insert); + PWET_TEST_CHECK(!(pair == &l->lwlock_overflow && key >= 0) || + ((uint32) key & PWET_WAIT_EVENT_CLASS_MASK) == PG_WAIT_LWLOCK); + + pwet_ledger_begin(l); + if (insert) + { + cell->tranche_plus1 = ((uint32) key & PWET_WAIT_EVENT_ID_MASK) + 1; + l->num_used++; + } + pair->calls = (uint64) calls; + pair->total_ns = (uint64) total_ns; + pwet_ledger_end(l); + + PG_RETURN_VOID(); +} + +/* + * pwet_test_ledger_changecount(slot int, value bigint) returns bigint + * + * Return the changecount of a slot's ledger; if value >= 0, also store it + * (a stand-in for a writer stalled mid-update when odd, or a counter close + * to wraparound when set on one's own slot). + */ +Datum +pwet_test_ledger_changecount(PG_FUNCTION_ARGS) +{ + int slot = PG_GETARG_INT32(0); + int64 value = PG_GETARG_INT64(1); + PwetLedger *l; + uint32 old; + + PWET_TEST_CHECK(slot >= 0 && slot < PWET_NUM_SLOTS); + pwet_flush_pending(); + l = pwet_ledger_at(slot); + old = pg_atomic_read_u32(&l->changecount); + if (value >= 0) + pg_atomic_write_u32(&l->changecount, (uint32) value); + + PG_RETURN_INT64((int64) old); +} + +static uint32 pwet_test_hook_event; +static int pwet_test_hook_release_at; +static uint32 pwet_test_hook_release_value; + +/* Copy hook: one complete writer bracket lands inside the reader's copy. */ +static void +pwet_test_hook_torn(PwetLedger *src) +{ + pwet_test_ledger_copy_hook = NULL; + pwet_ledger_add(src, pwet_test_hook_event, 1000); +} + +/* Retry hook: the stalled writer finishes at retry number release_at. */ +static void +pwet_test_hook_release(PwetLedger *src, int retries) +{ + if (retries == pwet_test_hook_release_at) + pg_atomic_write_u32(&src->changecount, pwet_test_hook_release_value); +} + +static Datum +pwet_test_read_result(FunctionCallInfo fcinfo, PwetLedger *copy, + uint32 event, int retries) +{ + TupleDesc tupdesc; + Datum values[2]; + bool nulls[2] = {0}; + PwetLedgerCell *cell = NULL; + bool insert; + PwetTotal *pair; + + if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE) + elog(ERROR, "return type must be a row type"); + pair = pwet_ledger_target(copy, event, &cell, &insert); + values[0] = Int32GetDatum(retries); + values[1] = Int64GetDatum((int64) pair->calls); + return HeapTupleGetDatum(heap_form_tuple(tupdesc, values, nulls)); +} + +/* + * pwet_test_ledger_torn_read(event_key bigint, OUT retries int, OUT calls bigint) + * + * Read this process's own ledger while a complete writer bracket lands + * between the reader's copy and its closing changecount check: the copy + * must be rejected and retried exactly once, and the accepted copy must show + * the extra call. + */ +Datum +pwet_test_ledger_torn_read(PG_FUNCTION_ARGS) +{ + uint32 event = (uint32) PG_GETARG_INT64(0); + PwetLedger *copy = palloc(pwet_ledger_bytes); + int before; + + pwet_flush_pending(); + pwet_test_hook_event = event; + pwet_test_ledger_copy_hook = pwet_test_hook_torn; + before = pwet_test_ledger_retries; + pwet_ledger_read(pwet_get_my_ledger(), copy); + pwet_test_ledger_copy_hook = NULL; + + return pwet_test_read_result(fcinfo, copy, event, + pwet_test_ledger_retries - before); +} + +/* + * pwet_test_ledger_odd_read(event_key bigint, release_at int, + * OUT retries int, OUT calls bigint) + * + * Make this process's own changecount odd, as if a writer were stalled + * inside the bracket, and read the ledger: the reader must keep retrying + * until the writer finishes, which the retry hook does at retry number + * release_at. + */ +Datum +pwet_test_ledger_odd_read(PG_FUNCTION_ARGS) +{ + uint32 event = (uint32) PG_GETARG_INT64(0); + int release_at = PG_GETARG_INT32(1); + PwetLedger *l; + PwetLedger *copy = palloc(pwet_ledger_bytes); + uint32 cc; + int before; + + pwet_flush_pending(); + l = pwet_get_my_ledger(); + cc = pg_atomic_read_u32(&l->changecount); + PWET_TEST_CHECK((cc & 1) == 0); + pg_atomic_write_u32(&l->changecount, cc + 1); + + pwet_test_hook_release_at = release_at; + pwet_test_hook_release_value = cc + 2; + pwet_test_ledger_retry_hook = pwet_test_hook_release; + before = pwet_test_ledger_retries; + pwet_ledger_read(l, copy); + pwet_test_ledger_retry_hook = NULL; + + PWET_TEST_CHECK((pg_atomic_read_u32(&l->changecount) & 1) == 0); + return pwet_test_read_result(fcinfo, copy, event, + pwet_test_ledger_retries - before); +} + #endif /* USE_ASSERT_CHECKING */ 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 fbf09c0bcff..30b900785fc 100644 --- a/contrib/pg_wait_event_tracing/pg_wait_event_tracing.control +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.control @@ -1,5 +1,5 @@ # pg_wait_event_tracing extension comment = 'statistics and trace collection for explicitly instrumented wait events' -default_version = '1.0' +default_version = '1.1' module_pathname = '$libdir/pg_wait_event_tracing' relocatable = true 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 new file mode 100644 index 00000000000..89e306abed3 --- /dev/null +++ b/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing_totals.sql @@ -0,0 +1,104 @@ +-- +-- PG_WAIT_EVENT_TRACING_TOTALS +-- +-- Extension version 1.1: the instance-wide totals views. Installation and +-- upgrade, the shape of the views, the reserved overflow keys, the +-- incarnation format and the privileges. Counting itself is exercised by +-- the TAP tests of src/test/modules/test_wait_totals, where a dedicated wait +-- event makes exact assertions possible; here only things that hold whatever +-- other tests did to this server are asserted. +-- + +-- 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; +CREATE EXTENSION pg_wait_event_tracing VERSION '1.0'; +SELECT extversion FROM pg_extension WHERE extname = 'pg_wait_event_tracing'; +SELECT count(*) AS totals_objects_in_1_0 +FROM pg_proc WHERE proname LIKE 'pg_stat_get_wait_event_totals%'; + +ALTER EXTENSION pg_wait_event_tracing UPDATE TO '1.1'; +SELECT extversion FROM pg_extension WHERE extname = 'pg_wait_event_tracing'; +SELECT count(*) AS totals_objects_after_update +FROM pg_proc WHERE proname LIKE 'pg_stat_get_wait_event_totals%'; + +DROP EXTENSION pg_wait_event_tracing; +CREATE EXTENSION pg_wait_event_tracing; +SELECT extversion FROM pg_extension WHERE extname = 'pg_wait_event_tracing'; +SELECT count(*) AS totals_objects_fresh +FROM pg_proc WHERE proname LIKE 'pg_stat_get_wait_event_totals%'; + +-- Columns of the two views. +SELECT attname, format_type(atttypid, atttypmod) AS type +FROM pg_attribute +WHERE attrelid = 'pg_stat_wait_event_totals'::regclass AND attnum > 0 +ORDER BY attnum; + +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; + +-- One info row; the incarnation is 16 lower-case hex digits. +SELECT count(*) AS info_rows FROM pg_stat_wait_event_totals_info; +SELECT incarnation ~ '^[0-9a-f]{16}$' AS incarnation_format, + invalid_ledgers, + ledger_slots > 0 AS has_slots, + capturing_backends >= 0 AS has_capturing +FROM pg_stat_wait_event_totals_info; + +-- The incarnation does not change while the server runs. +SELECT incarnation AS incarnation_before FROM pg_stat_wait_event_totals_info \gset +SELECT incarnation = :'incarnation_before' AS incarnation_stable +FROM pg_stat_wait_event_totals_info; + +-- The two overflow rows exist with their reserved keys, and no other row has +-- a negative key; every other key is a full wait event code, which carries +-- the wait event class in its top byte. +SELECT event_key, wait_event_type, wait_event, calls >= 0 AS calls_ok +FROM pg_stat_wait_event_totals +WHERE event_key < 0 +ORDER BY event_key; + +SELECT count(*) AS bad_keys +FROM pg_stat_wait_event_totals +WHERE event_key >= 0 AND (event_key >= 4294967296 OR event_key < 16777216); + +SELECT count(*) AS duplicate_keys +FROM (SELECT event_key FROM pg_stat_wait_event_totals + GROUP BY event_key HAVING count(*) > 1) d; + +-- Counters are never negative, and the average is NULL exactly when there +-- are no calls. +SELECT count(*) AS bad_rows +FROM pg_stat_wait_event_totals +WHERE calls < 0 OR total_time_ms < 0 OR (calls = 0) <> (avg_time_us IS NULL); + +-- Privileges: not readable by PUBLIC, neither the views nor the functions +-- behind them; readable with pg_read_all_stats. +CREATE ROLE regress_pwet_plain; +CREATE ROLE regress_pwet_stats IN ROLE pg_read_all_stats; + +SELECT has_function_privilege('regress_pwet_plain', + 'pg_stat_get_wait_event_totals()', 'EXECUTE') AS plain_totals_fn, + has_function_privilege('regress_pwet_plain', + 'pg_stat_get_wait_event_totals_info()', 'EXECUTE') AS plain_info_fn, + has_function_privilege('regress_pwet_stats', + 'pg_stat_get_wait_event_totals()', 'EXECUTE') AS stats_totals_fn, + has_function_privilege('regress_pwet_stats', + 'pg_stat_get_wait_event_totals_info()', 'EXECUTE') AS stats_info_fn; + +SET ROLE regress_pwet_plain; +SELECT count(*) FROM pg_stat_wait_event_totals; +SELECT count(*) FROM pg_stat_wait_event_totals_info; +SELECT count(*) FROM pg_stat_get_wait_event_totals(); +SELECT count(*) FROM pg_stat_get_wait_event_totals_info(); +RESET ROLE; + +SET ROLE regress_pwet_stats; +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; + +DROP ROLE regress_pwet_plain; +DROP ROLE regress_pwet_stats; diff --git a/contrib/pg_wait_event_tracing/t/017_totals_ledger.pl b/contrib/pg_wait_event_tracing/t/017_totals_ledger.pl new file mode 100644 index 00000000000..f4cdf2871d4 --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/017_totals_ledger.pl @@ -0,0 +1,155 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: the lifetime ledger and its seqlock reader, checked +# deterministically through assert-build-only entry points (declared here, +# never in the installed script; skipped on builds without assertions). No +# production hook is blocked or instrumented; timing is never asserted. +# +# - dictionary: 16 colliding keys admitted, all still found when full, one +# more goes to overflow with count and time, nothing moves; +# - a complete writer bracket landing inside the reader's copy makes the +# reader reject and retry the copy exactly once; +# - an odd changecount makes the reader retry until the writer finishes; +# - a writer stalled for good (odd count) cannot make a reader uncancellable; +# - 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; +# - sums over ledgers that exceed bigint ERROR the totals. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +plan skip_all => 'test entry points exist only in assert-enabled builds' + unless check_pg_config('#define USE_ASSERT_CHECKING 1'); + +sub new_node +{ + my ($name) = @_; + my $node = PostgreSQL::Test::Cluster->new($name); + $node->init; + $node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +pg_wait_event_tracing.capture = 'stats' +pg_wait_event_tracing.max_tranches = 16 +debug_parallel_query = off +)); + $node->start; + $node->safe_psql( + 'postgres', q( +CREATE EXTENSION pg_wait_event_tracing; +CREATE EXTENSION test_wait_totals; +CREATE FUNCTION pwet_test_ledger_dictionary() RETURNS void + AS 'pg_wait_event_tracing', 'pwet_test_ledger_dictionary' LANGUAGE C; +CREATE FUNCTION pwet_test_ledger_set(bigint, bigint, bigint) RETURNS void + AS 'pg_wait_event_tracing', 'pwet_test_ledger_set' LANGUAGE C; +CREATE FUNCTION pwet_test_ledger_changecount(int, bigint) RETURNS bigint + AS 'pg_wait_event_tracing', 'pwet_test_ledger_changecount' LANGUAGE C; +CREATE FUNCTION pwet_test_ledger_torn_read(bigint, OUT retries int, OUT calls bigint) + AS 'pg_wait_event_tracing', 'pwet_test_ledger_torn_read' LANGUAGE C; +CREATE FUNCTION pwet_test_ledger_odd_read(bigint, int, OUT retries int, OUT calls bigint) + AS 'pg_wait_event_tracing', 'pwet_test_ledger_odd_read' LANGUAGE C; +)); + return $node; +} + +my $node = new_node('main'); +my $TOTAL = "SELECT coalesce(sum(calls), 0) FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'"; + +my ($ret, $out, $err) = $node->psql('postgres', 'SELECT pwet_test_ledger_dictionary()'); +is($ret, 0, 'ledger dictionary: collisions, full table, overflow') or diag $err; + +my $s = $node->background_psql('postgres'); +my $key = $s->query_safe('SELECT test_wait_totals_event_key()'); + +# Torn copy: one complete writer bracket lands inside the copy. +$s->query_safe('SELECT test_wait_totals_emit(4)'); +is($s->query_safe($TOTAL), '4', 'four calls before the torn read'); +is($s->query_safe("SELECT retries || ',' || calls FROM pwet_test_ledger_torn_read($key)"), + '1,5', 'torn copy rejected once; the accepted copy has the extra call'); + +# Odd count: the reader retries until the stalled writer finishes. +is($s->query_safe("SELECT retries || ',' || calls FROM pwet_test_ledger_odd_read($key, 7)"), + '7,5', 'odd changecount: reader retried until the writer finished'); + +# A writer stalled for good: a spare slot's count stays odd. The reader +# retries but stays cancellable. +my $spare = $node->safe_psql('postgres', + 'SELECT ledger_slots - 1 FROM pg_stat_wait_event_totals_info'); +my $cc = $node->safe_psql('postgres', + "SELECT pwet_test_ledger_changecount($spare, -1)"); +is($cc % 2, 0, 'spare slot count is even'); +$node->safe_psql('postgres', + "SELECT pwet_test_ledger_changecount($spare, " . ($cc + 1) . ")"); +# The external timeout makes a reader that lost its interrupt check fail +# fast instead of hanging; the ledger is restored before anything else. +my $timed_out = 0; +my ($r2, $o2, $e2) = $node->psql('postgres', + "SET statement_timeout = 500; SELECT count(*) FROM pg_stat_wait_event_totals", + timeout => 30, timed_out => \$timed_out); +$node->safe_psql('postgres', + "SELECT pwet_test_ledger_changecount($spare, " . ($cc + 2) . ")"); +ok(!$timed_out, 'the reader of a stalled ledger returns instead of hanging'); +isnt($r2, 0, 'reader of a stalled ledger fails'); +like($e2, qr/statement timeout/, 'it was cancelled by statement_timeout'); +is($node->safe_psql('postgres', 'SELECT count(*) > 0 FROM pg_stat_wait_event_totals'), + 't', 'reads work again once the writer finished'); + +# Counters crossing 2^32. +$s->query_safe("SELECT pwet_test_ledger_set($key, 4294967290, 4294967290000)"); +$s->query_safe('SELECT test_wait_totals_emit(10)'); +is($s->query_safe($TOTAL), '4294967300', 'calls cross 2^32 exactly'); +cmp_ok($s->query_safe( + "SELECT total_time_ms FROM pg_stat_wait_event_totals WHERE wait_event = 'TestWaitTotals'"), + '>', 4294967.29, 'total time crosses 2^32 ns-units too'); + +# changecount rollover. +$s->query_safe('SELECT pwet_test_ledger_set(' . $key . ', 0, 0)'); +my $mypn = $s->query_safe('SELECT test_wait_totals_procnumber()'); +$s->query_safe("SELECT pwet_test_ledger_changecount($mypn, 4294967292)"); +$s->query_safe('SELECT test_wait_totals_emit(6)'); +is($s->query_safe($TOTAL), '6', 'totals right across the rollover'); +my $after = $s->query_safe("SELECT pwet_test_ledger_changecount($mypn, -1)"); +cmp_ok($after, '<', 100, "changecount wrapped around (now $after)"); +is($after % 2, 0, 'changecount even after rollover'); + +# Invalid ledger: a counter would exceed bigint. +$s->query_safe("SELECT pwet_test_ledger_set($key, 9223372036854775807, 0)"); +$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'); +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()'); +$s->query_safe('SELECT pg_stat_reset_wait_event_timing()'); +is($node->safe_psql('postgres', 'SELECT invalid_ledgers FROM pg_stat_wait_event_totals_info'), + '1', 'reset cannot repair an invalid ledger'); +($ret) = $node->psql('postgres', 'SELECT * FROM pg_stat_wait_event_totals'); +isnt($ret, 0, 'totals still ERROR after the resets'); +$s->quit; +$node->stop; + +# Sums over ledgers exceeding bigint. +$node = new_node('sum'); +foreach my $i (1, 2) +{ + $node->safe_psql('postgres', + 'SELECT pwet_test_ledger_set(-1, 4611686018427387904, 5)'); +} +($ret, $out, $err) = $node->psql('postgres', 'SELECT * FROM pg_stat_wait_event_totals'); +isnt($ret, 0, 'sum over ledgers beyond bigint: totals ERROR'); +like($err, qr/exceed the bigint range/, 'sum overflow message'); +is($node->safe_psql('postgres', + 'SELECT lwlock_overflow_calls IS NULL AND invalid_ledgers = 0 + FROM pg_stat_wait_event_totals_info'), + 't', 'info shows NULL for the overflowing sum and no invalid ledger'); +$node->stop; + +done_testing(); diff --git a/doc/src/sgml/pgwaiteventtracing.sgml b/doc/src/sgml/pgwaiteventtracing.sgml index 40559ad4e11..a2d0000c406 100644 --- a/doc/src/sgml/pgwaiteventtracing.sgml +++ b/doc/src/sgml/pgwaiteventtracing.sgml @@ -978,7 +978,11 @@ shared_preload_libraries = 'pg_wait_event_tracing' — it is called out here only because it is new: an orderly exit's own cleanup flushes any still-pending wait first, so this narrow loss window is specific to an abrupt kill, and affects at - most the single most recently completed wait. + most the single most recently completed wait. Server-side processes that + record through the fixed-slot region and never attach a payload are + covered by an exit callback registered at process start that adds + their last pending wait to the lifetime ledger (see + ). @@ -1705,6 +1709,118 @@ AFTER_STATEMENT --(QueryStart | UtilityStart)--> OPEN (no Idle emitted) + + Instance Totals and Interval Reports + + + Extension version 1.1 adds instance-wide cumulative totals. Unlike + pg_stat_wait_event_timing, whose rows belong to + 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. + + + + Views + + pg_stat_wait_event_totals has one row for every + event with at least one completed captured wait: + wait_event_type, + wait_event, + event_key (the full 32-bit wait event code, + the class in the top byte; for LWLocks the code carries the tranche id), + calls, total_time_ms + and avg_time_us. Two rows are always present + and use reserved keys: -1 collects LWLock tranches + that did not fit a process's dictionary (see + ) and + -2 collects events outside the flat event table. They + keep both count and time; events that did not fit are merged there, + never dropped. A custom event whose name cannot be resolved gets a + placeholder name. + + + pg_stat_wait_event_totals_info has one row: + incarnation (16 hexadecimal digits, random, + new whenever shared memory is created, so a change means the totals + restarted from zero), the overflow pairs + (lwlock_overflow_calls, + lwlock_overflow_time_ms, + flat_overflow_calls, + flat_overflow_time_ms), + invalid_ledgers, + ledger_slots and + 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 + 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 + (an overflow column whose sum cannot be represented is null). Both + views and their functions are readable by + pg_read_all_stats only. + + + + + What Is Counted and When It Appears + + The totals count completed waits that were captured, that is, completed + while pg_wait_event_tracing.capture was + stats or trace in the waiting + process and a collection payload existed for it, summed over all slots, + occupied or not. They are independent of the per-backend view: a + per-backend reset, a capture change or a slot being reused never + changes them. Every wait completes into a single pending record, and a + pending record reaches the ledger when the process next begins a timed + wait or hits another flush point (a capture change, a reset, a read of + the totals by the same session, process exit). Hence after N + consecutive waits with nothing in between, N-1 are visible to other + sessions and one remains private; ending a statement does not publish it + in stats mode, while the executor end does in + trace mode. A process computing for a long stretch + without any wait delays publication without bound. + + + On an orderly exit the last completed wait is added to the ledger by an + exit callback registered at process start, in every process that runs + BaseInit: client backends and WAL senders, + autovacuum launcher and workers, background and parallel workers, and + the checkpointer, background writer, WAL writer, startup process, WAL + receiver, archiver, WAL summarizer and I/O workers. The postmaster and + the logger are not covered. An abrupt death can still lose the last + pending wait of that process. A crash restart reinitializes shared + memory, so all totals, and the incarnation, start over. + + + + + Memory + + One ledger per possible process slot is allocated unconditionally. A + ledger holds a pair of counters for each flat event, a dictionary of + pg_wait_event_tracing.max_tranches tranches and the + overflow pairs; with the default max_tranches of 192 + it takes 21376 bytes including cache line alignment. The number of slots + is max_connections + autovacuum_worker_slots + + max_worker_processes + max_wal_senders + 2 + 38 (workers and + auxiliary processes included): 174 slots, 3.5 MiB, with the default + max_connections of 100, and 1074 slots, 21.9 MiB, + 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. + + + + Overhead diff --git a/src/test/modules/test_wait_totals/Makefile b/src/test/modules/test_wait_totals/Makefile index a75dac715c2..1fd8e86fc0c 100644 --- a/src/test/modules/test_wait_totals/Makefile +++ b/src/test/modules/test_wait_totals/Makefile @@ -11,6 +11,10 @@ DATA = test_wait_totals--1.0.sql REGRESS = test_wait_totals +# The TAP tests preload pg_wait_event_tracing from contrib. +EXTRA_INSTALL = contrib/pg_wait_event_tracing +TAP_TESTS = 1 + ifdef USE_PGXS PG_CONFIG = pg_config PGXS := $(shell $(PG_CONFIG) --pgxs) diff --git a/src/test/modules/test_wait_totals/meson.build b/src/test/modules/test_wait_totals/meson.build index bfc84a75610..04fc804d324 100644 --- a/src/test/modules/test_wait_totals/meson.build +++ b/src/test/modules/test_wait_totals/meson.build @@ -30,4 +30,15 @@ tests += { 'test_wait_totals', ], }, + 'tap': { + 'tests': [ + 't/001_publication.pl', + 't/002_exit.pl', + 't/003_capture_reset.pl', + 't/004_slots_servers.pl', + 't/005_dictionary.pl', + 't/006_coherence.pl', + 't/007_restart.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 new file mode 100644 index 00000000000..987ffc7571c --- /dev/null +++ b/src/test/modules/test_wait_totals/t/001_publication.pl @@ -0,0 +1,162 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Instance totals of pg_wait_event_tracing: counting and the publication +# rule. Every assertion is about conservation of one dedicated wait event +# (TestWaitTotals, emitted by test_wait_totals), not about "all totals": +# with cluster-wide capture, startup and background waits keep adding to +# every other event. +# +# 1. Basic: N emitted waits become N calls with a positive total time, once +# the emitting backend has returned to a timed wait. +# 2. Publication rule: a completed wait is added to the ledger when the next +# timed wait begins (or another explicit flush happens). After N +# consecutive emissions with no flush in between, N-1 are published and +# one remains private; a statement end in stats mode does not flush, the +# executor end in trace mode does. A later timed wait publishes the rest. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; +use Time::HiRes qw(usleep); + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +pg_wait_event_tracing.capture = 'stats' +debug_parallel_query = 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 time_ms +{ + return $node->safe_psql('postgres', + "SELECT coalesce(sum(total_time_ms), 0) FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'"); +} + +# Keep the value constant for a moment: "exactly N" must still hold later. +sub stays +{ + my ($want, $what) = @_; + usleep(500_000); + is(calls(), $want, $what); +} + +# --------------------------------------------------------------------- +# 1. Basic. +# --------------------------------------------------------------------- +is(calls(), '0', 'dedicated event starts at zero'); + +my $a = $node->background_psql('postgres'); +$a->query_safe('SELECT test_wait_totals_emit(10, 20)'); +$node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = 10 FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die 'N emissions did not become N calls'; +stays('10', 'calls delta is exactly N'); +cmp_ok(time_ms(), '>', 0, 'total time is positive'); +cmp_ok( + $node->safe_psql( + 'postgres', + "SELECT avg_time_us FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'"), + '>=', 20, 'average time is at least the spin time'); +$a->quit; + +# --------------------------------------------------------------------- +# 2. Publication rule, observed from another session while the emitter is +# inside its CPU stretch. The emitter holds there until released, and +# tells us when it is there, so the observation provably happens inside +# the stretch, whatever the scheduling. +# --------------------------------------------------------------------- +# $mode: capture level of the emitting session; $stmt: what it runs; +# $expect: calls visible while it holds, for N = 5 emissions. +sub publication_case +{ + my ($mode, $stmt, $expect, $label) = @_; + my $base = calls(); + my $s = $node->background_psql('postgres'); + + $s->query_safe("SET pg_wait_event_tracing.capture = $mode"); + + # Warm up the statement text with the gate open, so that the measured + # run does not hit catalog reads (a timed IO wait would flush the + # pending completion). + $node->safe_psql('postgres', 'SELECT test_wait_totals_gate_reset()'); + $node->safe_psql('postgres', 'SELECT test_wait_totals_release()'); + $s->query_safe($stmt); + $node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = $base + 5 FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die "$label: warm-up not published"; + $base += 5; + + $node->safe_psql('postgres', 'SELECT test_wait_totals_gate_reset()'); + $s->query_until(qr/started/, "\\echo started\n$stmt\n"); + $node->poll_query_until('postgres', 'SELECT test_wait_totals_holding()') + or die "$label: the emitter never reached its CPU stretch"; + + # One read, while the emitter is known to be inside the stretch. + is(calls(), $base + $expect, + "$label: $expect published while the backend is in its CPU stretch"); + + $node->safe_psql('postgres', 'SELECT test_wait_totals_release()'); + # Ending the statement returns the backend to a timed wait, which + # publishes the one that remained private. + $s->query_safe('SELECT 1'); + $node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = $base + 5 FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die "$label: the private completion was never published"; + stays($base + 5, "$label: all 5 published after the next timed wait"); + $s->quit; +} + +publication_case('stats', + 'SELECT test_wait_totals_emit_hold(5);', + 4, 'stats, one call'); +publication_case('trace', + 'SELECT test_wait_totals_emit_hold(5);', + 4, 'trace, one call'); +# psql sends "a \; b" as one query string, so no timed wait (ClientRead) +# separates the two statements. The first ends before the second holds. +publication_case('stats', + 'SELECT test_wait_totals_emit(5) \; SELECT test_wait_totals_emit_hold(0);', + 4, 'stats, statement end does not flush'); +publication_case('trace', + 'SELECT test_wait_totals_emit(5) \; SELECT test_wait_totals_emit_hold(0);', + 5, 'trace, statement markers flush'); + +# --------------------------------------------------------------------- +# Names: the unnamed built-in Extension event is "Extension"; an event id +# that nothing registered gets a placeholder name, never an error. +# --------------------------------------------------------------------- +my $ext = 117440512; # PG_WAIT_EXTENSION, 0x07000000 +$node->safe_psql('postgres', "SELECT test_wait_totals_emit_event($ext, 2)"); +$node->safe_psql('postgres', "SELECT test_wait_totals_emit_event($ext + 120, 1)"); +$node->poll_query_until('postgres', + "SELECT count(*) = 2 FROM pg_stat_wait_event_totals + WHERE (event_key = $ext AND wait_event = 'Extension' AND calls = 2) + OR (event_key = $ext + 120 AND wait_event = 'unknown_120' AND calls = 1)") + or die 'Extension / placeholder names are wrong: ' + . $node->safe_psql('postgres', + "SELECT string_agg(event_key || ':' || wait_event, ',') FROM pg_stat_wait_event_totals + WHERE wait_event_type = 'Extension'"); +pass('built-in Extension event and an unregistered id are named'); + +$node->stop; +done_testing(); diff --git a/src/test/modules/test_wait_totals/t/002_exit.pl b/src/test/modules/test_wait_totals/t/002_exit.pl new file mode 100644 index 00000000000..63ce2e12bac --- /dev/null +++ b/src/test/modules/test_wait_totals/t/002_exit.pl @@ -0,0 +1,161 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Instance totals of pg_wait_event_tracing: a completed wait that is still +# pending when its process exits reaches the totals. Disconnecting after a +# successful SQL result would only test an already-flushed wait, so the cases +# here make sure the last completion really is pending at exit: +# +# - a background worker emits N waits and exits without returning to +# any wait or to SQL (a server-side process that records through the +# reserved fixed-slot region and never attaches anything); +# - a client backend is terminated while it burns CPU after N emissions +# (the FATAL exit path); +# - an idle disconnect, as smoke coverage only. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; +use Time::HiRes qw(usleep); + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +pg_wait_event_tracing.capture = 'stats' +debug_parallel_query = 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_for_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() . ")"; +} + +# --------------------------------------------------------------------- +# Background worker: emit N, exit. The call returns after the worker has +# exited, so the count must be exact right away, without polling. +# --------------------------------------------------------------------- +my $a = $node->background_psql('postgres'); +$a->query_safe('SELECT test_wait_totals_event_key()'); # register the name + + +$a->query_safe('SELECT test_wait_totals_bgworker(7)'); +is(calls(), '7', 'bgworker: all 7 completions counted, the last one included'); + +$a->query_safe('SELECT test_wait_totals_bgworker(1)'); +is(calls(), '8', 'bgworker: a single completion, pending at exit, counted'); + +# A fixed-slot worker withdraws its owner token at an orderly exit (before its +# PGPROC is released), so an exited worker is not a capturing backend. +# The population of the instance-wide count is not controllable, so the test +# looks at the worker's own slot through an assert-build test entry point +# that applies the same liveness rule as capturing_backends. +SKIP: +{ + skip 'test entry point exists only in assert-enabled builds', 5 + unless check_pg_config('#define USE_ASSERT_CHECKING 1'); + + $node->safe_psql('postgres', + q(CREATE FUNCTION pwet_test_slot_counted(int) RETURNS bool + AS 'pg_wait_event_tracing', 'pwet_test_slot_counted' LANGUAGE C)); + my $wslot = $a->query_safe('SELECT test_wait_totals_bgworker_procnumber()'); + cmp_ok($wslot, '>=', 0, "the worker ran in slot $wslot"); + is($a->query_safe("SELECT pwet_test_slot_counted($wslot)"), 'f', + 'an exited fixed-slot worker is not a capturing backend'); + + # A worker without a database connection has no backend-status entry; it + # is still a capturing backend while it is alive, and not after it exits. + $node->safe_psql('postgres', 'SELECT test_wait_totals_gate_reset()'); + $a->query_safe('SELECT test_wait_totals_bgworker_hold(3)'); + $node->poll_query_until('postgres', 'SELECT test_wait_totals_holding()') + or die 'the held worker never reached its loop'; + my $hslot = $a->query_safe('SELECT test_wait_totals_bgworker_procnumber()'); + is($a->query_safe("SELECT pwet_test_slot_counted($hslot)"), 't', + 'a live fixed-slot worker without a backend-status entry is counted'); + $node->safe_psql('postgres', 'SELECT test_wait_totals_release()'); + $node->poll_query_until('postgres', + "SELECT NOT pwet_test_slot_counted($hslot)") + or die 'the worker is still counted after it exited'; + pass('and it is not counted after it exited'); + is($a->query_safe('SELECT pwet_test_slot_counted(test_wait_totals_procnumber())'), + 't', 'a live capturing backend is'); +} + +my $before_zero = calls(); +$a->query_safe('SELECT test_wait_totals_bgworker(0)'); +is(calls(), $before_zero, 'bgworker: emitting nothing counts nothing'); +$a->quit; + +# --------------------------------------------------------------------- +# Client backend terminated while burning CPU after N emissions: N-1 are +# published, the last is pending, and the FATAL exit must drain it. +# --------------------------------------------------------------------- +my $base = calls(); +my $s = $node->background_psql('postgres'); +my $pid = $s->query_safe('SELECT pg_backend_pid()'); +$node->safe_psql('postgres', 'SELECT test_wait_totals_gate_reset()'); +$s->query_until(qr/started/, + "\\echo started\nSELECT test_wait_totals_emit_hold(6);\n"); +$node->poll_query_until('postgres', 'SELECT test_wait_totals_holding()') + or die 'the emitter never reached its CPU stretch'; +is(calls(), $base + 5, + 'terminate: exactly N-1 published while the backend is in its CPU stretch'); + +$node->safe_psql('postgres', "SELECT pg_terminate_backend($pid)"); +wait_for_calls($base + 6, 'terminate: the pending completion drained at exit'); +usleep(500_000); +is(calls(), $base + 6, 'terminate: exactly N after termination, none twice'); +eval { $s->quit }; + +# --------------------------------------------------------------------- +# The producer is cancelable: a huge emission (each pair spinning a full +# second) ends with the cancellation error soon after the cancel. +# --------------------------------------------------------------------- +{ + my $c = $node->background_psql('postgres'); + my $cpid = $c->query_safe('SELECT pg_backend_pid()'); + $c->query_until(qr/emitting/, "\\echo emitting\nSELECT test_wait_totals_emit(1000000000, 1000000);\n"); + $node->poll_query_until('postgres', + "SELECT state = 'active' FROM pg_stat_activity WHERE pid = $cpid") + or die 'the emission never started'; + my $off = -s $node->logfile; + $node->safe_psql('postgres', "SELECT pg_cancel_backend($cpid)"); + $node->wait_for_log( + qr/ERROR: canceling statement due to user request\n.*?STATEMENT: SELECT test_wait_totals_emit\(1000000000, 1000000\)/s, + $off); + pass('a huge emission is canceled with the cancellation error'); + # psql exits on the error, so the backend is gone or idle; not running. + $node->poll_query_until('postgres', + "SELECT NOT EXISTS (SELECT 1 FROM pg_stat_activity WHERE pid = $cpid AND state = 'active')") + or die 'the canceled emission is still running'; + pass('and it is no longer running'); + eval { $c->quit }; +} + +# --------------------------------------------------------------------- +# Idle disconnect: smoke only (the completion is flushed long before). +# --------------------------------------------------------------------- +$base = calls(); +$node->safe_psql('postgres', 'SELECT test_wait_totals_emit(3)'); +wait_for_calls($base + 3, 'idle disconnect'); +is(calls(), $base + 3, 'idle disconnect: all 3 counted'); + +$node->stop; +done_testing(); 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 new file mode 100644 index 00000000000..25de1e740a2 --- /dev/null +++ b/src/test/modules/test_wait_totals/t/003_capture_reset.pl @@ -0,0 +1,176 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Instance totals of pg_wait_event_tracing across capture-level changes and +# per-backend resets. The totals of the dedicated event are a lifetime +# record: every completed wait made while capture was on is counted exactly +# once, whatever happens to the per-backend payload afterwards. +# +# 4. All six transitions between off, stats and trace, repeated, with +# emissions in between: the total never decreases and equals the number of +# emissions made while capture was on. Emissions while off count +# nothing; a completion still pending when capture is switched is flushed +# by the assign hook and counted. +# 5. Own, remote and reset-all resets with a completion pending: the instance +# total keeps every completion exactly once, while the per-backend view +# resets as it always did. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; +use Time::HiRes qw(usleep); + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +)); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing'); +$node->safe_psql('postgres', 'CREATE EXTENSION test_wait_totals'); + +my $TOTAL = "SELECT coalesce(sum(calls), 0) FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'"; + +sub calls +{ + return $node->safe_psql('postgres', $TOTAL); +} + +# The producer's temporary capture change must keep the scope of the setting +# it found: a SET LOCAL stays local and the session value comes back. +is($node->safe_psql('postgres', + q(SET pg_wait_event_tracing.capture = off; + BEGIN; + SET LOCAL pg_wait_event_tracing.capture = trace; + SELECT test_wait_totals_emit_with_capture('stats', ARRAY[]::int[], 0); + SHOW pg_wait_event_tracing.capture; + COMMIT; + SHOW pg_wait_event_tracing.capture;)) =~ s/^\n//mgr, + "trace\noff", + 'emit_with_capture keeps a SET LOCAL local and the session value after COMMIT'); + +# --------------------------------------------------------------------- +# 4. Capture transitions. One session reads its own totals, which flush its +# own pending completion first, so the count is exact at every step. +# --------------------------------------------------------------------- +my $s = $node->background_psql('postgres'); +sub mine { return $s->query_safe($TOTAL); } + +my $expected = 0; +my $prev = 0; +my $mode = 'off'; +my @steps = qw(stats trace off trace stats off stats trace off); +push @steps, @steps; # the six directions, twice over + +foreach my $next (@steps) +{ + $s->query_safe("SET pg_wait_event_tracing.capture = $next"); + my $got = mine(); + cmp_ok($got, '>=', $prev, "$mode -> $next: total did not decrease"); + $prev = $got; + $mode = $next; + + $s->query_safe('SELECT test_wait_totals_emit(3)'); + $expected += 3 unless $mode eq 'off'; + $got = mine(); + is($got, $expected, "capture $mode: 3 emissions " + . ($mode eq 'off' ? 'not counted' : 'counted')); + $prev = $got; +} + +# A completion pending at the moment capture changes is flushed by the +# assign hook and counted, because the wait happened while capture was on. +# The helper emits and changes the setting before returning to SQL, so no +# ClientRead and no statement marker publishes the completion first. +foreach my $pair ([qw(stats off)], [qw(trace off)], [qw(stats trace)], + [qw(trace stats)]) +{ + my ($from, $to) = @$pair; + $s->query_safe("SET pg_wait_event_tracing.capture = $from"); + $s->query_safe("SELECT test_wait_totals_emit_then_set_capture(3, '$to')"); + $expected += 3; + is(mine(), $expected, "pending completion counted on $from -> $to"); +} +$s->query_safe('SET pg_wait_event_tracing.capture = off'); +$s->quit; + +# --------------------------------------------------------------------- +# 5. Resets with a completion pending. +# --------------------------------------------------------------------- +my $legacy = sub { + my ($pid) = @_; + return $node->safe_psql('postgres', + "SELECT coalesce(sum(calls), 0) FROM pg_stat_wait_event_timing + WHERE pid = $pid AND wait_event = 'TestWaitTotals'"); +}; + +# Own reset: the pending completion is flushed first, then wiped from the +# per-backend payload; the instance total keeps it. +my $base = calls(); +my $r = $node->background_psql('postgres'); +$r->query_safe('SET pg_wait_event_tracing.capture = stats'); +my $rpid = $r->query_safe('SELECT pg_backend_pid()'); +$r->query_safe( + 'SELECT test_wait_totals_emit(4) \; SELECT pg_stat_reset_wait_event_timing()'); +$node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = $base + 4 FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die 'own reset: the pending completion was lost'; +is(calls(), $base + 4, 'own reset: all 4 counted exactly once'); +is($legacy->($rpid), '0', 'own reset: per-backend count was reset'); +$r->query_safe('SELECT test_wait_totals_emit(2)'); +$node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = $base + 6 FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die 'own reset: later emissions not counted'; +is($legacy->($rpid), '2', 'own reset: per-backend view counts again from zero'); +$r->quit; + +# Remote reset and reset-all, requested while the target holds a pending +# completion (it is burning CPU after its 4 emissions, 3 of them flushed). +# The reset takes effect at the target's next flush, before the pending +# completion is added: the per-backend view shows that one only, while the +# instance total keeps all four. +foreach my $how ('remote', 'all') +{ + $base = calls(); + my $t = $node->background_psql('postgres'); + $t->query_safe('SET pg_wait_event_tracing.capture = stats'); + my $tpid = $t->query_safe('SELECT pg_backend_pid()'); + $node->safe_psql('postgres', 'SELECT test_wait_totals_gate_reset()'); + $t->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 "$how reset: the emitter never reached its CPU stretch"; + is(calls(), $base + 3, + "$how reset: 3 completions published while the target holds the 4th"); + + if ($how eq 'remote') + { + $node->safe_psql('postgres', "SELECT pg_stat_reset_wait_event_timing($tpid)"); + } + else + { + $node->safe_psql('postgres', 'SELECT pg_stat_reset_wait_event_timing_all()'); + } + + $node->safe_psql('postgres', 'SELECT test_wait_totals_release()'); + $t->query_safe('SELECT 1'); # returns once the statement is over + $node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = $base + 4 FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die "$how reset: the pending completion was lost"; + usleep(300_000); + is(calls(), $base + 4, "$how reset: instance total kept all 4, once each"); + is($legacy->($tpid), '1', + "$how reset: per-backend view restarted, holding the flushed one only"); + $t->quit; +} + +$node->stop; +done_testing(); 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 new file mode 100644 index 00000000000..235e77cc23f --- /dev/null +++ b/src/test/modules/test_wait_totals/t/004_slots_servers.pl @@ -0,0 +1,129 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Instance totals of pg_wait_event_tracing: slot reuse, server processes and +# parallel workers. +# +# 6. Many short connections reuse ProcNumbers (the free list is first-in +# first-out, so max_connections is kept small to make it wrap around). The ledger of a slot is never +# cleared by a new owner, so the dedicated event's total equals everything +# emitted, and the test checks that reuse really happened. +# 7. With capture = stats cluster-wide, the checkpointer and the WAL writer +# contribute, asserted on events only they wait on (CheckpointerMain, +# WalWriterMain), not on a generic WAL write a backend could do as well. +# 8. Parallel workers that emit through a forced parallel plan are counted +# once each after they have exited, and the test shows that the workers, +# not the leader, really ran the emitter. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; +use Time::HiRes qw(usleep); + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +pg_wait_event_tracing.capture = 'stats' +debug_parallel_query = off +wal_writer_delay = 10ms +max_connections = 12 +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 event_calls +{ + my ($event) = @_; + return $node->safe_psql('postgres', + "SELECT coalesce(sum(calls), 0) FROM pg_stat_wait_event_totals + WHERE wait_event = '$event'"); +} + +sub calls { return event_calls('TestWaitTotals'); } + +# --------------------------------------------------------------------- +# 6. Slot reuse. +# --------------------------------------------------------------------- +my $conns = 30; +my $per_conn = 3; +my %seen; +my @order; +for my $i (1 .. $conns) +{ + my $out = $node->safe_psql('postgres', + "SELECT test_wait_totals_procnumber(), test_wait_totals_emit($per_conn)"); + my ($procno) = split /\|/, $out; + $seen{$procno}++; + push @order, $procno; +} +my $distinct = scalar keys %seen; +cmp_ok($distinct, '<', $conns, + "slots were reused: $distinct distinct ProcNumbers for $conns connections (" + . join(',', @order) . ')'); +$node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = " . ($conns * $per_conn) . " + FROM pg_stat_wait_event_totals WHERE wait_event = 'TestWaitTotals'") + or die 'slot reuse: totals never reached the emitted count'; +usleep(300_000); +is(calls(), $conns * $per_conn, + 'slot reuse: total equals everything emitted, no ledger was cleared'); + +# --------------------------------------------------------------------- +# 7. Server processes. +# --------------------------------------------------------------------- +$node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) >= 20 FROM pg_stat_wait_event_totals + WHERE wait_event = 'WalWriterMain'") + or die 'the WAL writer never contributed WalWriterMain waits'; +pass('WAL writer contributes its own WalWriterMain waits'); + +my $ckpt_before = event_calls('CheckpointerMain'); +$node->safe_psql('postgres', 'CHECKPOINT'); +$node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) > $ckpt_before FROM pg_stat_wait_event_totals + WHERE wait_event = 'CheckpointerMain'") + or die 'the checkpointer never contributed after a CHECKPOINT'; +pass('checkpointer contributes CheckpointerMain waits after a CHECKPOINT'); + +# --------------------------------------------------------------------- +# 8. Parallel workers. +# --------------------------------------------------------------------- +my $rows = 4000; +$node->safe_psql('postgres', + "CREATE TABLE ptab AS SELECT g FROM generate_series(1, $rows) g"); + +my $setup = q( +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 = 2; +SET parallel_leader_participation = off; +); +my $query = 'SELECT sum(test_wait_totals_emit_row(1)) FROM ptab'; + +my $plan = $node->safe_psql('postgres', "${setup}EXPLAIN (COSTS OFF) $query"); +like($plan, qr/Gather/, 'the emitter runs under a parallel plan'); + +my $base = calls(); +my $in_workers = $node->safe_psql('postgres', "$setup$query"); +is($in_workers, $rows, + 'every row was processed by a worker, none by the leader'); +$node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = $base + $rows FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die 'parallel workers: totals never reached the emitted count (now ' + . calls() . ", base $base)"; +usleep(300_000); +is(calls(), $base + $rows, + "parallel workers: $rows completions counted exactly once after they exited"); + +$node->stop; +done_testing(); diff --git a/src/test/modules/test_wait_totals/t/005_dictionary.pl b/src/test/modules/test_wait_totals/t/005_dictionary.pl new file mode 100644 index 00000000000..1583f3675dd --- /dev/null +++ b/src/test/modules/test_wait_totals/t/005_dictionary.pl @@ -0,0 +1,191 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Instance totals of pg_wait_event_tracing: the per-ledger LWLock tranche +# dictionary. Each process admits at most pg_wait_event_tracing.max_tranches +# distinct tranches (the minimum, 16, here); every admitted tranche must keep +# being found however full the table is, and tranches that do not fit go to +# the LWLock overflow pair with both their count and their time. +# +# 9. - Real contention on a named test tranche is found and counted. +# - A process fills its dictionary to capacity; its admitted keys are +# still found afterwards; further tranches go to overflow with count +# and time; no key moves between dictionary and overflow. +# - A new process reusing the slot does not clear the dictionary. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; +use Time::HiRes qw(usleep); + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +pg_wait_event_tracing.capture = 'stats' +pg_wait_event_tracing.max_tranches = 16 +debug_parallel_query = off +max_connections = 12 +)); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing'); +$node->safe_psql('postgres', 'CREATE EXTENSION test_wait_totals'); + +use constant LWLOCK_BASE => 16777216; # 0x01000000, the LWLock class + +sub key_calls +{ + my ($key) = @_; + return $node->safe_psql('postgres', + "SELECT coalesce(sum(calls), 0) FROM pg_stat_wait_event_totals + WHERE event_key = $key"); +} + +sub overflow +{ + # lwlock overflow calls and a flag whether its time is positive + return $node->safe_psql('postgres', + "SELECT lwlock_overflow_calls, lwlock_overflow_time_ms > 0 + FROM pg_stat_wait_event_totals_info"); +} + +sub wait_key_calls +{ + my ($key, $want, $what) = @_; + $node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = $want FROM pg_stat_wait_event_totals + WHERE event_key = $key") + or die "$what: key $key never reached $want calls (now " + . key_calls($key) . ')'; +} + +# --------------------------------------------------------------------- +# Real contention on a named test tranche. +# --------------------------------------------------------------------- +my $lock_tranche = $node->safe_psql('postgres', 'SELECT test_wait_totals_lock_tranche(0)'); +my $lock_key = LWLOCK_BASE + $lock_tranche; + +my $holder = $node->background_psql('postgres'); +$holder->query_until(qr/holding/, + "\\echo holding\nSELECT test_wait_totals_lock_hold(0, 1, 30000);\n"); +$node->poll_query_until('postgres', 'SELECT test_wait_totals_lock_holder(0) <> 0') + or die 'the holder never took the test lock'; + +# The waiter blocks on the held lock; the holder lets go once it sees it. +$node->safe_psql('postgres', 'SELECT test_wait_totals_lock_wait(0)'); +is($holder->query_safe('SELECT 1'), "1\n1", + 'the holder saw one waiter, released, and the session is usable again'); +$holder->quit; + +$node->poll_query_until('postgres', + "SELECT count(*) = 1 FROM pg_stat_wait_event_totals + WHERE event_key = $lock_key AND wait_event = 'test_wait_totals_lock_0' + AND wait_event_type = 'LWLock' AND calls >= 1 AND total_time_ms > 0") + or die 'the contended wait on the named test tranche was not counted'; +pass('a contended wait on a named test tranche is found and counted'); + +# --------------------------------------------------------------------- +# Fill one process's dictionary to capacity. A dictionary is never cleared, +# so any real LWLock wait recorded in the process (or in an earlier owner of +# its slot) would take a cell. Capture is therefore off on this second +# server, and the helper switches it on only around the synthetic emissions, +# with no SQL and no wait in between: nothing else is ever recorded, and the +# overflow pair changes only by these emissions. +# --------------------------------------------------------------------- +$node->stop; +$node = PostgreSQL::Test::Cluster->new('fill'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +pg_wait_event_tracing.max_tranches = 16 +debug_parallel_query = off +max_connections = 12 +)); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing'); +$node->safe_psql('postgres', 'CREATE EXTENSION test_wait_totals'); + +my $s = $node->background_psql('postgres'); +my $spn = $s->query_safe('SELECT test_wait_totals_procnumber()'); +my ($ov_calls0) = split /\|/, overflow(); + +# 16 admitted tranches (new in this process), then 4 more that must overflow, +# then the first 16 again (still found), then the 4 again (still overflow). +my $fresh = $node->safe_psql('postgres', "SELECT array_to_string(test_wait_totals_new_tranches(16, 'adm'), ' ')"); +my $fresh_x = $node->safe_psql('postgres', "SELECT array_to_string(test_wait_totals_new_tranches(4, 'ovf'), ' ')"); +my @adm = split / /, $fresh; +my @ovf = split / /, $fresh_x; +my $adm_arr = 'ARRAY[' . join(',', @adm) . ']'; +my $ovf_arr = 'ARRAY[' . join(',', @ovf) . ']'; + +$s->query_safe("SELECT test_wait_totals_emit_with_capture('stats', $adm_arr, 2)"); +$s->query_safe("SELECT test_wait_totals_emit_with_capture('stats', $ovf_arr, 3)"); +$s->query_safe("SELECT test_wait_totals_emit_with_capture('stats', $adm_arr, 3)"); +$s->query_safe("SELECT test_wait_totals_emit_with_capture('stats', $ovf_arr, 1)"); + +foreach my $id (@adm) +{ + wait_key_calls(LWLOCK_BASE + $id, 5, 'admitted key'); +} +pass('keys admitted before the table was full are still found after it'); + +foreach my $id (@ovf) +{ + is(key_calls(LWLOCK_BASE + $id), '0', + "tranche $id did not fit: no dictionary row of its own"); +} + +$node->poll_query_until('postgres', + "SELECT lwlock_overflow_calls = " . ($ov_calls0 + 16) . " AND lwlock_overflow_time_ms > 0 + FROM pg_stat_wait_event_totals_info") + or die 'overflow did not receive the 16 completions of the 4 extra tranches (now ' + . overflow() . ', base ' . $ov_calls0 . ')'; +pass('tranches that did not fit are in the overflow pair with count and time'); +my ($ov_after) = split /\|/, overflow(); +is($ov_after, $ov_calls0 + 16, 'overflow holds count 4*(3+1) exactly'); + +# No key moved: the overflow row of the view agrees with the info view, and +# the admitted keys' counts did not change by anything that overflowed. +is($node->safe_psql('postgres', + "SELECT calls FROM pg_stat_wait_event_totals WHERE event_key = -1"), + $ov_after, 'the -1 row of the totals view is the LWLock overflow pair'); +$s->quit; + +# --------------------------------------------------------------------- +# Slot reuse does not clear the dictionary: a new process on the same slot +# still has a full table, so a tranche it has not used yet overflows while +# an admitted one is found. Connect until the slot is handed out again. +# --------------------------------------------------------------------- +my $reuse; +for my $i (1 .. 30) +{ + my $t = $node->background_psql('postgres'); + my $pn = $t->query_safe('SELECT test_wait_totals_procnumber()'); + if ($pn eq $spn) + { + $reuse = $t; + last; + } + $t->quit; +} +ok(defined $reuse, "got slot $spn again"); + +my ($ov_before) = split /\|/, overflow(); +$reuse->query_safe("SELECT test_wait_totals_emit_with_capture('stats', $ovf_arr, 1)"); +$reuse->query_safe("SELECT test_wait_totals_emit_with_capture('stats', ARRAY[$adm[0]], 1)"); +wait_key_calls(LWLOCK_BASE + $adm[0], 6, 'slot reuse: admitted key'); +my ($ov_now) = split /\|/, overflow(); +is($ov_now, $ov_before + 4, + 'slot reuse: the previous owner\'s full dictionary was not cleared (4 tranches overflowed)'); +foreach my $id (@ovf) +{ + is(key_calls(LWLOCK_BASE + $id), '0', "slot reuse: tranche $id still has no row"); +} +$reuse->quit; + +$node->stop; +done_testing(); diff --git a/src/test/modules/test_wait_totals/t/006_coherence.pl b/src/test/modules/test_wait_totals/t/006_coherence.pl new file mode 100644 index 00000000000..ad391fd9b03 --- /dev/null +++ b/src/test/modules/test_wait_totals/t/006_coherence.pl @@ -0,0 +1,117 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Instance totals of pg_wait_event_tracing: coherence of concurrent reads. +# Several sessions emit waits at a high rate while another session reads the +# totals over and over. The assertions have no timing bounds; they are +# invariants that a torn or stale read would break: +# +# - successive reads, which do not overlap, are monotonic per field; +# - within one read, the total time is at least calls times the minimum +# duration of one wait (every emitted wait spins for at least a +# microsecond), which a read that paired a newer call count with an older +# time could not satisfy; +# - once the writers have exited, the total is exactly what they emitted. +# +# The deterministic seqlock checks (an odd count, a torn copy, a stalled +# writer, counter ranges) are in the module's own t/017_totals_ledger.pl. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +pg_wait_event_tracing.capture = 'stats' +debug_parallel_query = off +)); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing'); +$node->safe_psql('postgres', 'CREATE EXTENSION test_wait_totals'); + +my $writers = 4; +my $nsamples = 300; + +# Between two samples the reader waits for the writers' progress counter to +# advance, so every pair of samples is separated by known writer progress. +# The writers run until the reader has taken all its samples, and the reader +# starts only once every writer is running, so the reads overlap the writes +# whatever the scheduling. The watchdog inside the helpers only turns a +# hang into a failure. +$node->safe_psql('postgres', 'SELECT test_wait_totals_gate_reset()'); +my @w; +for my $i (1 .. $writers) +{ + my $s = $node->background_psql('postgres'); + $s->query_until(qr/started/, + "\\echo started\nSELECT test_wait_totals_emit_until_stopped(1);\n"); + push @w, $s; +} + +my $reader = $node->background_psql('postgres'); +$reader->query_safe("SELECT test_wait_totals_wait_writers($writers)"); +$reader->query_safe(q( +CREATE TEMP TABLE snap (i int, calls bigint, ms double precision); +DO $$ +DECLARE + i int := 0; + c bigint; + m double precision; + p bigint := 0; +BEGIN + LOOP + -- Writers must have made progress since the previous sample. + p := test_wait_totals_wait_progress(p); + SELECT coalesce(sum(calls), 0), coalesce(sum(total_time_ms), 0) + INTO c, m + FROM pg_stat_wait_event_totals WHERE wait_event = 'TestWaitTotals'; + i := i + 1; + INSERT INTO snap VALUES (i, c, m); + EXIT WHEN i >= ) . $nsamples . q(; + END LOOP; +END $$; +)); +$reader->query_safe('SELECT test_wait_totals_stop()'); + +is($reader->query_safe('SELECT count(*) FROM snap'), $nsamples, + "the reader took $nsamples samples while all writers ran"); + +is($reader->query_safe( + 'SELECT count(*) FROM (SELECT calls, ms, + lag(calls) OVER (ORDER BY i) AS pc, lag(ms) OVER (ORDER BY i) AS pm + FROM snap) x WHERE calls < pc OR ms < pm'), + '0', 'successive reads are monotonic per field'); + +is($reader->query_safe( + 'SELECT count(*) FROM snap WHERE ms * 1000000 < calls * 1000 * 0.999999'), + '0', 'every read has total time >= calls * minimum wait duration'); + +cmp_ok($reader->query_safe('SELECT max(calls) - min(calls) FROM snap'), + '>', 0, 'the writers made progress while the reader sampled'); +$reader->quit; + +my $total = 0; +foreach my $s (@w) +{ + my $out = $s->query_safe('SELECT 1'); + my ($n) = split /\n/, $out; + $total += $n; + $s->quit; +} + +$node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = $total FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die 'the total never reached what the writers emitted'; +is($node->safe_psql('postgres', + "SELECT coalesce(sum(calls), 0) FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'"), + $total, "after the writers exited the total is exactly what they emitted ($total)"); + +$node->stop; +done_testing(); diff --git a/src/test/modules/test_wait_totals/t/007_restart.pl b/src/test/modules/test_wait_totals/t/007_restart.pl new file mode 100644 index 00000000000..09e023debbe --- /dev/null +++ b/src/test/modules/test_wait_totals/t/007_restart.pl @@ -0,0 +1,104 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Instance totals of pg_wait_event_tracing across restarts. The ledgers live +# in shared memory, so they start from zero whenever the shared memory is +# created: after a clean restart and after a crash restart (kill -9 of a +# backend). Each time the incarnation changes, which is how a consumer tells +# "the totals restarted" from "the totals only moved". With cluster-wide +# capture, startup and background waits add to other events, so the +# assertions are on the dedicated event. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', q( +shared_preload_libraries = 'pg_wait_event_tracing' +pg_wait_event_tracing.capture = 'stats' +debug_parallel_query = off +restart_after_crash = on +)); +$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) = @_; + $node->poll_query_until('postgres', + "SELECT coalesce(sum(calls), 0) = $want FROM pg_stat_wait_event_totals + WHERE wait_event = 'TestWaitTotals'") + or die "calls never reached $want (now " . calls() . ')'; +} + +sub incarnation +{ + return $node->safe_psql('postgres', + 'SELECT incarnation FROM pg_stat_wait_event_totals_info'); +} + +my %seen; + +$node->safe_psql('postgres', 'SELECT test_wait_totals_emit(5)'); +wait_calls(5); +my $inc = incarnation(); +like($inc, qr/^[0-9a-f]{16}$/, 'incarnation is 16 hex digits'); +is(incarnation(), $inc, 'incarnation is stable while the server runs'); +$seen{$inc} = 1; + +# Clean restart. +$node->restart; +my $inc2 = incarnation(); +ok(!$seen{$inc2}, 'clean restart: new incarnation'); +$seen{$inc2} = 1; +is(calls(), '0', 'clean restart: the dedicated event starts from zero'); +$node->safe_psql('postgres', 'SELECT test_wait_totals_emit(3)'); +wait_calls(3); +is(calls(), '3', 'clean restart: counting works again, from zero'); + +# Crash restart: kill -9 of a client backend. The postmaster reinitializes +# shared memory and restarts. +my $victim = $node->background_psql('postgres'); +my $pid = $victim->query_safe('SELECT pg_backend_pid()'); +ok(kill('KILL', $pid), 'SIGKILL sent to a backend'); + +# Connections may fail while the postmaster recovers, and may even succeed +# against the old instance before it notices the death: accept only a +# successful query that shows a different incarnation. +my $inc3; +for (my $i = 0; $i < 1800; $i++) +{ + my ($ret, $out, $err) = $node->psql('postgres', + 'SELECT incarnation FROM pg_stat_wait_event_totals_info'); + if ($ret == 0 && $out =~ /^[0-9a-f]{16}$/ && $out ne $inc2) + { + $inc3 = $out; + last; + } + select(undef, undef, undef, 0.1); +} +die 'the server did not come back with a new incarnation' unless defined $inc3; +eval { $victim->quit }; + +ok(!$seen{$inc3}, 'crash restart: new incarnation'); +$seen{$inc3} = 1; +is(calls(), '0', 'crash restart: the dedicated event starts from zero'); +$node->safe_psql('postgres', 'SELECT test_wait_totals_emit(2)'); +wait_calls(2); +is(calls(), '2', 'crash restart: counting works again, from zero'); + +$node->stop; +done_testing(); -- 2.49.0