From c8e9a7a61bb8137a2a5a6935bd4e0f64a18761be Mon Sep 17 00:00:00 2001 From: Dmitry Fomin Date: Tue, 22 Sep 2026 10:40:02 +0200 Subject: [PATCH v11 4/5] pg_wait_event_tracing: statistics level Add contrib/pg_wait_event_tracing, a loadable extension that ports v6's built-in per-wait-event timing statistics onto the begin/end hook pair added earlier in this series, and generalizes it to cover every backend type, not only ordinary client sessions. Storage is split in two. A small, always-resident control table (one PwetSlot per possible ProcNumber, in fixed shared memory mapped from postmaster startup) tracks who currently owns each slot's statistics payload; the payload itself -- a dense per-class timing array plus a histogram of wait durations -- lives in a per-backend DSA area, allocated lazily on the first wait a session actually wants to record, so an idle or non-collecting backend costs only its control-table entry rather than the ~200 KiB payload. GUC pg_wait_event_tracing.capture (off/stats) gates collection; toggling it attaches or releases a session's payload from the safe points that already exist for this purpose (post_parse_analyze_hook, ExecutorStart_hook, and the GUC's own assign hook). Autovacuum workers, background workers, WAL senders, and the auxiliary processes (checkpointer, background writer, WAL writer, startup, WAL receiver, I/O workers, ...) never execute a query and so never reach the ordinary attach points; left alone they would only ever attach at the next configuration reload after capture turns on, missing everything before that, including crash recovery. For them, a second, smaller fixed-shared-memory region reserves one slot per possible server-side ProcNumber up front (only when capture is not off at postmaster start, so the default configuration reserves nothing extra); a process claims its own slot lock-free, with plain loads, stores and memory barriers only, directly from inside the wait-event begin hook, which cannot allocate, lock, wait, or call elog(). Readers take a lock-free double-read path for a slot known to be in this region and fall back to the ordinary locked DSA path otherwise. Because a ProcNumber gets reused as soon as its process exits, every slot -- fixed or DSA-backed -- carries an owner token (pid and start time) that both writers publish under the control lock and readers compare against the current PgBackendStatus entry before trusting a payload, so a successor that has not attached its own statistics is never shown a predecessor's counters. The same token closes a race between an asynchronous cross-backend reset and a ProcNumber reuse: pg_stat_reset_wait_event_timing(pid) resolves and validates its target's owner token once, under the ACL check, and the actual generation bump that the target's own next wait notices is only applied if the token still matches when the request is published under the control lock -- a successor that has since claimed the same slot is left untouched. Target authorization for a reset mirrors pg_signal_backend(): a pg_signal_backend member or the target role itself may reset an ordinary target, only a superuser may reset another superuser or a role-less backend, and pg_stat_reset_wait_event_timing_all() additionally hard-requires superuser() in C rather than relying only on a revocable EXECUTE grant. The per-class capacity table sizes each dense wait-event class with headroom over its current count in wait_event_names.txt (bumped for Lock/Client/Timeout/IPC over the values inherited from v6) and is exposed as pg_wait_event_tracing_capacity() so the regression test can check it against pg_wait_events directly; the histogram-buckets view and the capacity function stay PUBLIC-readable, matching the equivalent core view, since neither exposes anything about any session. The attach check reached from every parsed and executed statement (pwet_maybe_attach()) is an always-inline test of one backend-local flag, pwet_attach_needed; the attachment machinery itself -- pwet_can_attach(), pwet_attach_stats(), and the exit-callback registration -- moves out of line into pwet_maybe_attach_slow(), called only when that flag is set, and is otherwise unchanged. Testing: a single-session SQL regression test covers the views, functions, GUC default, enable/disable, self-reset, and the capacity table; four TAP tests exercise what a single backend cannot (memory footprint staying sparse rather than scaling with max_connections, statistics not leaking across a reused ProcNumber, the full reset-ACL matrix against a second connection, and the reset-vs-reuse race, the last using an injection point to park a request between resolving its target and publishing the reset); a fifth TAP test checks that checkpointer, background writer, WAL writer, an I/O worker, and a standby's startup process all collect statistics through the fixed region, both from postmaster start and after a reload. The wait hooks are installed lazily, per process, from the capture GUC's own assign hook the first time that process's capture becomes non-off, and are never removed again, so a process that never enables capture runs the permanent hook-null path and pays nothing; the non-chaining wrapper variant drops the previous-hook test entirely for a process with nothing to chain to. A diagnostic function reports whether the calling backend has installed its own hooks, and a new TAP test covers the lazy installation itself. Recording is gated through one recording-gate pointer per level, recomputed at every site that assigns one of its inputs, instead of re-deriving the same multi-condition test on every wait; the in-flight wait (which event, and when it started) moves out of the shared payload into process-local state, since it is written and read only by the owning backend. The assign hook masks recording for its own duration so that a payload's own synchronous attach never counts its own lock wait, keeping the recorded set identical to the pre-fold behaviour. A bare-metal run isolating a short, heavily contended ProcArrayLock storm (W3) measured the collector's enabled cost at 6.6%, about forty times the ~0.17% the per-wait recording cost alone would predict: the end-of-wait accounting used to run to completion, including a possible cache miss on the shared payload, before returning to the caller, and for an LWLock wait that caller is still inside the critical section the lock protects, so every one of those nanoseconds was paid by every queued waiter. To remove that amplification, the accounting is deferred out of the wait_end hook: at wait_end the hook only reads the clock and stashes the event, duration and timestamp in a one-slot, backend-local pending buffer, which is flushed by the same accounting code as before, unchanged, at the next wait_start and at every other point where ordering or a payload's lifetime matters (a capture-level change, a reset, release of the payload, process exit, or a read of the calling backend's own stats or overflow row). Both recording decisions for a wait -- whether to count it at all, and, once trace exists, whether to also record it there -- are still taken at wait_end, exactly as before; only writing the counters is deferred, never the decision of whether to. The values recorded and their order are unchanged; a cross-backend reader's visibility latency is bounded by the backend's own next timed wait; and, on a crash between a wait ending and its flush, at most that one pending record is lost. A server-side process that blocks without a timeout, such as a caught-up standby's startup process waiting for WAL, makes its most recent completed wait visible only once its own next wait begins. See DECISION-deferred-accounting.md for the full measurement and the alternatives considered. Discussion: https://postgr.es/m/CAPHG-0mAOn05ae6Kqx1wHXxzOk4E5W7ajjd=QBhgkR7a0uyQmw@mail.gmail.com --- contrib/Makefile | 1 + contrib/meson.build | 1 + contrib/pg_wait_event_tracing/Makefile | 32 + .../expected/pg_wait_event_tracing.out | 376 +++ contrib/pg_wait_event_tracing/meson.build | 51 + .../pg_wait_event_tracing--1.0.sql | 143 + .../pg_wait_event_tracing.c | 2347 +++++++++++++++++ .../pg_wait_event_tracing.conf | 1 + .../pg_wait_event_tracing.control | 5 + .../pg_wait_event_tracing_data.h | 91 + .../sql/pg_wait_event_tracing.sql | 239 ++ contrib/pg_wait_event_tracing/t/001_memory.pl | 124 + .../pg_wait_event_tracing/t/002_ownership.pl | 199 ++ .../pg_wait_event_tracing/t/003_reset_acl.pl | 231 ++ .../pg_wait_event_tracing/t/004_reset_race.pl | 165 ++ .../t/006_server_processes.pl | 222 ++ .../pg_wait_event_tracing/t/007_lazy_hooks.pl | 113 + doc/src/sgml/contrib.sgml | 1 + doc/src/sgml/filelist.sgml | 1 + doc/src/sgml/pgwaiteventtracing.sgml | 1608 +++++++++++ doc/src/sgml/xfunc.sgml | 31 +- src/tools/pgindent/typedefs.list | 7 + 22 files changed, 5988 insertions(+), 1 deletion(-) create mode 100644 contrib/pg_wait_event_tracing/Makefile create mode 100644 contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing.out create mode 100644 contrib/pg_wait_event_tracing/meson.build create mode 100644 contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0.sql create mode 100644 contrib/pg_wait_event_tracing/pg_wait_event_tracing.c create mode 100644 contrib/pg_wait_event_tracing/pg_wait_event_tracing.conf create mode 100644 contrib/pg_wait_event_tracing/pg_wait_event_tracing.control create mode 100644 contrib/pg_wait_event_tracing/pg_wait_event_tracing_data.h create mode 100644 contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing.sql create mode 100644 contrib/pg_wait_event_tracing/t/001_memory.pl create mode 100644 contrib/pg_wait_event_tracing/t/002_ownership.pl create mode 100644 contrib/pg_wait_event_tracing/t/003_reset_acl.pl create mode 100644 contrib/pg_wait_event_tracing/t/004_reset_race.pl create mode 100644 contrib/pg_wait_event_tracing/t/006_server_processes.pl create mode 100644 contrib/pg_wait_event_tracing/t/007_lazy_hooks.pl create mode 100644 doc/src/sgml/pgwaiteventtracing.sgml diff --git a/contrib/Makefile b/contrib/Makefile index 7d91fe77db3..a831254f899 100644 --- a/contrib/Makefile +++ b/contrib/Makefile @@ -43,6 +43,7 @@ SUBDIRS = \ pgrowlocks \ pgstattuple \ pg_visibility \ + pg_wait_event_tracing \ pg_walinspect \ postgres_fdw \ seg \ diff --git a/contrib/meson.build b/contrib/meson.build index ebb7f83d8c5..8756280f19e 100644 --- a/contrib/meson.build +++ b/contrib/meson.build @@ -57,6 +57,7 @@ subdir('pgstattuple') subdir('pg_surgery') subdir('pg_trgm') subdir('pg_visibility') +subdir('pg_wait_event_tracing') subdir('pg_walinspect') subdir('postgres_fdw') subdir('seg') diff --git a/contrib/pg_wait_event_tracing/Makefile b/contrib/pg_wait_event_tracing/Makefile new file mode 100644 index 00000000000..b7bb15840df --- /dev/null +++ b/contrib/pg_wait_event_tracing/Makefile @@ -0,0 +1,32 @@ +# contrib/pg_wait_event_tracing/Makefile + +MODULE_big = pg_wait_event_tracing +OBJS = \ + $(WIN32RES) \ + pg_wait_event_tracing.o + +EXTENSION = pg_wait_event_tracing +DATA = pg_wait_event_tracing--1.0.sql +PGFILEDESC = "pg_wait_event_tracing - statistics and trace collection for explicitly instrumented wait events" + +REGRESS = pg_wait_event_tracing +REGRESS_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 +# will not have (shared_preload_libraries requires a server restart). +NO_INSTALLCHECK = 1 + +TAP_TESTS = 1 +EXTRA_INSTALL = src/test/modules/injection_points +export enable_injection_points + +ifdef USE_PGXS +PG_CONFIG = pg_config +PGXS := $(shell $(PG_CONFIG) --pgxs) +include $(PGXS) +else +subdir = contrib/pg_wait_event_tracing +top_builddir = ../.. +include $(top_builddir)/src/Makefile.global +include $(top_srcdir)/contrib/contrib-global.mk +endif diff --git a/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing.out b/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing.out new file mode 100644 index 00000000000..7de36ad8b1c --- /dev/null +++ b/contrib/pg_wait_event_tracing/expected/pg_wait_event_tracing.out @@ -0,0 +1,376 @@ +-- +-- PG_WAIT_EVENT_TRACING +-- +-- Exercises the statistics level: the capture GUC, the stats surface +-- (pg_stat_get_wait_event_timing(), the pg_stat_wait_event_timing and +-- histogram-buckets views, overflow counters), reset (self and +-- cross-backend, including its authorization), and the per-class capacity +-- table. The trace level is a separate patch and is not exercised here. +-- +CREATE EXTENSION pg_wait_event_tracing; +-- Statistics are per backend: a parallel worker records its waits under +-- its own pid. CI forces parallel query on some platforms +-- (debug_parallel_query = regress), which would move pg_sleep() below into +-- a worker, so keep this session's statements in this session. +SET debug_parallel_query = off; +-- Default is off. +SHOW pg_wait_event_tracing.capture; + pg_wait_event_tracing.capture +------------------------------- + off +(1 row) + +-- Lazy, per-process hook installation: a fresh session that +-- has never turned capture on has never installed its wait-event hooks. +SELECT pg_wait_event_tracing_hooks_installed(); + pg_wait_event_tracing_hooks_installed +--------------------------------------- + f +(1 row) + +-- The taxonomy view is pure SQL. +SELECT count(*) AS buckets FROM pg_wait_event_timing_histogram_buckets; + buckets +--------- + 32 +(1 row) + +SELECT bucket_idx, lower_ns, upper_ns, label +FROM pg_wait_event_timing_histogram_buckets +WHERE bucket_idx IN (0, 1, 31) +ORDER BY bucket_idx; + bucket_idx | lower_ns | upper_ns | label +------------+---------------+----------+--------- + 0 | 0 | 1024 | <1us + 1 | 1024 | 2048 | 1-2us + 31 | 1099511627776 | | >=1024s +(3 rows) + +-- Enable stats capture and generate a deterministic wait: pg_sleep emits a +-- Timeout / PgSleep wait. +SET pg_wait_event_tracing.capture = stats; +-- Pin the recording-gate equivalence: the SET above may +-- itself attach a stats payload synchronously, inside the assign hook, +-- and that attach takes an LWLock -- a timed wait. That LWLock wait must +-- not be counted: the assign hook masks recording, for its own duration, +-- to what the stored capture value (still "off" while the hook runs) +-- would have permitted, so no self-inflicted attach waits ever show up. +SELECT count(*) AS lwlock_waits_during_attach +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid() AND wait_event_type = 'LWLock'; + lwlock_waits_during_attach +---------------------------- + 0 +(1 row) + +-- The SET above installed this backend's hooks (the assign hook calls +-- pwet_install_wait_hooks() itself, before any attach logic runs). +SELECT pg_wait_event_tracing_hooks_installed(); + pg_wait_event_tracing_hooks_installed +--------------------------------------- + t +(1 row) + +SELECT pg_sleep(0.1); + pg_sleep +---------- + +(1 row) + +-- PgSleep must now be recorded for this backend, with the per-event +-- invariants holding. We print only booleans so the output is stable. +SELECT calls >= 1 AS calls_ok, + calls = (SELECT sum(h) FROM unnest(histogram) AS h) AS hist_sum_eq_calls, + total_time_ms > 0 AS total_positive, + max_time_us > 0 AS max_positive, + array_length(histogram, 1) + = (SELECT count(*)::int FROM pg_wait_event_timing_histogram_buckets) + AS histogram_len_ok +FROM pg_stat_get_wait_event_timing(pg_backend_pid()) +WHERE wait_event = 'PgSleep'; + calls_ok | hist_sum_eq_calls | total_positive | max_positive | histogram_len_ok +----------+-------------------+----------------+--------------+------------------ + t | t | t | t | t +(1 row) + +-- The view surfaces the same row, with backend_type attached (v6 column +-- set). +SELECT backend_type, wait_event_type, wait_event +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid() AND wait_event = 'PgSleep'; + backend_type | wait_event_type | wait_event +----------------+-----------------+------------ + client backend | Timeout | PgSleep +(1 row) + +-- A non-NULL pid that does not exist yields no rows (silent, not an +-- error). +SELECT count(*) AS rows_for_bogus_pid +FROM pg_stat_get_wait_event_timing(-1); + rows_for_bogus_pid +-------------------- + 0 +(1 row) + +-- Overflow/reset counters for this backend. A plain test backend uses few +-- LWLock tranches and no out-of-range classes, so both overflow counters +-- are zero, and a fresh backend has not been reset. +SELECT lwlock_overflow_count, flat_overflow_count, reset_count +FROM pg_stat_wait_event_timing_overflow +WHERE pid = pg_backend_pid(); + lwlock_overflow_count | flat_overflow_count | reset_count +-----------------------+---------------------+------------- + 0 | 0 | 0 +(1 row) + +-- Resetting our own backend is synchronous: the PgSleep row is cleared and +-- reset_count advances. (Filtering to PgSleep because inter-command waits +-- such as ClientRead may be recorded again before the next statement +-- runs.) +SELECT pg_stat_reset_wait_event_timing(NULL); + pg_stat_reset_wait_event_timing +--------------------------------- + +(1 row) + +SELECT count(*) AS pgsleep_rows_after_reset +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid() AND wait_event = 'PgSleep'; + pgsleep_rows_after_reset +-------------------------- + 0 +(1 row) + +SELECT reset_count +FROM pg_stat_wait_event_timing_overflow +WHERE pid = pg_backend_pid(); + reset_count +------------- + 1 +(1 row) + +-- +-- Deferred accounting (v11 patch 0004 fixup; see +-- DECISION-deferred-accounting.md): pwet_wait_end_impl() no longer accounts +-- a completed wait immediately -- it stashes it in a one-slot pending +-- buffer, applied later by pwet_flush_pending(), at the next timed wait or +-- one of several other ordering points, INCLUDING every SQL reader of a +-- backend's own data. So a wait completed earlier in the same statement +-- (here, by pg_sleep()) must always be visible to a query run by the SAME +-- session immediately afterward, with no special handling needed by the +-- caller and no dependency on an intervening wait happening to flush it +-- first. +-- +SELECT pg_stat_reset_wait_event_timing(); + pg_stat_reset_wait_event_timing +--------------------------------- + +(1 row) + +SELECT pg_sleep(0.02); + pg_sleep +---------- + +(1 row) + +SELECT calls >= 1 AS pgsleep_visible_immediately_in_same_session +FROM pg_stat_get_wait_event_timing(pg_backend_pid()) +WHERE wait_event = 'PgSleep'; + pgsleep_visible_immediately_in_same_session +--------------------------------------------- + t +(1 row) + +-- +-- A cross-backend reset request is applied exactly once, at whichever +-- flush next notices reset_generation has moved, even when a wait is +-- pending -- possibly this session's own -- at the moment the request +-- lands: the reset-generation check runs at the same position inside +-- pwet_flush_pending() as it always did inline in wait_end, immediately +-- before the pending record's own values are applied, and once noticed, +-- pwet_last_reset_generation is updated so the same request can never be +-- reapplied by a later flush. reset_count is checked as a delta, not an +-- absolute value. +-- +-- pg_stat_wait_event_timing_overflow(), unlike pg_stat_get_wait_event_ +-- timing() and the trace readers, does NOT flush the calling backend's +-- own pending record before reading (a gap in the module, not exercised +-- by this test's assertion itself, only worked around below): reading +-- reset_count through it right after the pg_sleep() below, with no +-- flush in between, leaves the outcome dependent on whatever OTHER wait +-- this session happens to incur first, which is not guaranteed on every +-- platform (observed: a 64-bit build's incidental wait flushed it in +-- time, a 32-bit build's did not). A second, tiny pg_sleep() forces a +-- deterministic flush here: pwet_wait_begin_impl() unconditionally +-- flushes the previous pending record -- the first pg_sleep() below, +-- which is what carries the reset-generation mismatch -- before timing +-- itself, with no dependency on anything else this session might do. +-- +SELECT reset_count AS reset_count_before +FROM pg_stat_wait_event_timing_overflow +WHERE pid = pg_backend_pid() \gset +SELECT pg_stat_reset_wait_event_timing_all(); + pg_stat_reset_wait_event_timing_all +------------------------------------- + +(1 row) + +SELECT pg_sleep(0.02); + pg_sleep +---------- + +(1 row) + +SELECT pg_sleep(0.01); + pg_sleep +---------- + +(1 row) + +SELECT reset_count - :reset_count_before AS reset_count_advanced_by_exactly_one +FROM pg_stat_wait_event_timing_overflow +WHERE pid = pg_backend_pid(); + reset_count_advanced_by_exactly_one +------------------------------------- + 1 +(1 row) + +-- +-- SET capture = off right after a wait still accounts that wait before +-- releasing the payload (flush before release): pwet_release_stats()/ +-- pwet_release_fixed_slot() call pwet_flush_pending() as the first thing +-- they do, before touching stats_ptr, so a pending record is never +-- silently dropped by an ordinary disable. The payload itself does not +-- survive release regardless (see "Disabling capture releases the +-- payload" above; the row disappears either way, whether or not the last +-- wait was accounted first), so what this checks is that disabling +-- capture immediately after a wait -- with the two statements sent +-- together, so there is no intervening statement boundary that could +-- flush it first on its own -- is not itself a source of any error, and +-- that the very next capture cycle starts from a clean slate. The +-- guarantee that the flush actually runs before, not after, the payload +-- is freed is a call-ordering property verified by inspection (every +-- release/orphan site's own first statement) and by a dedicated +-- cross-session TAP check (t/013_deferred_flush.pl), neither of which a +-- single-connection regress script can exercise: nothing distinguishes +-- "flushed, then freed" from "dropped, then freed" once the freed +-- backend's own payload is gone, without a second session positioned to +-- read the row before that free happens. +-- +SET pg_wait_event_tracing.capture = stats; +SELECT pg_sleep(0.02); SET pg_wait_event_tracing.capture = off; + pg_sleep +---------- + +(1 row) + +SELECT count(*) AS rows_after_wait_then_immediate_disable +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid(); + rows_after_wait_then_immediate_disable +---------------------------------------- + 0 +(1 row) + +SET pg_wait_event_tracing.capture = stats; +SELECT count(*) AS rows_are_clean_on_next_cycle +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid() AND wait_event = 'PgSleep'; + rows_are_clean_on_next_cycle +------------------------------ + 0 +(1 row) + +RESET pg_wait_event_tracing.capture; +-- The pid argument defaults to NULL, so a no-argument call resets the +-- caller's own backend. +SELECT pg_stat_reset_wait_event_timing(); + pg_stat_reset_wait_event_timing +--------------------------------- + +(1 row) + +-- Resetting an unknown pid is a WARNING, not an ERROR, matching +-- pg_signal_backend()'s own wording; the reset itself is a no-op. +SELECT pg_stat_reset_wait_event_timing(2147483647); +WARNING: PID 2147483647 is not a PostgreSQL backend process + pg_stat_reset_wait_event_timing +--------------------------------- + +(1 row) + +-- Disabling capture releases the payload (fix 1/2): even though the pid is +-- unchanged, every row for it disappears, because the reader checks +-- ownership, not just "is there a payload here". +RESET pg_wait_event_tracing.capture; +SELECT pg_sleep(0.05); + pg_sleep +---------- + +(1 row) + +SELECT count(*) AS rows_after_disable +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid(); + rows_after_disable +-------------------- + 0 +(1 row) + +-- Hooks, once installed, are never removed: still true even +-- though this backend's own capture is off again, so a later re-enable in +-- this same process needs no reinstallation. +SELECT pg_wait_event_tracing_hooks_installed(); + pg_wait_event_tracing_hooks_installed +--------------------------------------- + t +(1 row) + +-- +-- Reset authorization (fix 4). The pg_signal_backend-member-vs-ordinary- +-- target and non-superuser-vs-superuser-target cases need a second, real +-- backend with a different owning role; those live in the TAP test +-- t/003_reset_acl.pl (WP4a), which can create and authenticate as extra +-- roles portably (this regress test cannot: no second connection is +-- available here, and resetting your own pid always takes the synchronous +-- self-reset path regardless of role). What is single-session-testable is +-- _all()'s superuser requirement, which holds even for a role granted +-- EXECUTE directly, not just relying on the extension script's default +-- REVOKE EXECUTE FROM PUBLIC. +-- +CREATE ROLE regress_pwet_signaler; +GRANT EXECUTE ON FUNCTION pg_stat_reset_wait_event_timing_all() + TO regress_pwet_signaler; +SET ROLE regress_pwet_signaler; +SELECT pg_stat_reset_wait_event_timing_all(); +ERROR: permission denied to reset wait event timing statistics for all backends +DETAIL: Only roles with the SUPERUSER attribute may reset statistics for all backends. +RESET ROLE; +REVOKE EXECUTE ON FUNCTION pg_stat_reset_wait_event_timing_all() + FROM regress_pwet_signaler; +DROP ROLE regress_pwet_signaler; +-- +-- Per-class capacity (plan sec 3.1). Every class pg_wait_events knows +-- about must have a capacity row, and every class must have at least 4 +-- events of headroom below its capacity, so that whoever adds an event +-- past that headroom is caught here rather than by silent overflow +-- counting. +-- +SELECT count(*) AS classes_missing_capacity +FROM (SELECT DISTINCT type FROM pg_wait_events) t +WHERE NOT EXISTS ( + SELECT 1 FROM pg_wait_event_tracing_capacity() c WHERE c.type = t.type); + classes_missing_capacity +-------------------------- + 0 +(1 row) + +SELECT bool_and(cap.capacity - cnt.n >= 4) AS capacity_headroom_ok +FROM (SELECT type, count(*) AS n FROM pg_wait_events GROUP BY type) cnt +JOIN pg_wait_event_tracing_capacity() cap USING (type); + capacity_headroom_ok +---------------------- + t +(1 row) + +RESET pg_wait_event_tracing.capture; diff --git a/contrib/pg_wait_event_tracing/meson.build b/contrib/pg_wait_event_tracing/meson.build new file mode 100644 index 00000000000..e7e2928f921 --- /dev/null +++ b/contrib/pg_wait_event_tracing/meson.build @@ -0,0 +1,51 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +pg_wait_event_tracing_sources = files( + 'pg_wait_event_tracing.c', +) + +if host_system == 'windows' + pg_wait_event_tracing_sources += rc_lib_gen.process(win32ver_rc, extra_args: [ + '--NAME', 'pg_wait_event_tracing', + '--FILEDESC', 'pg_wait_event_tracing - statistics and trace collection for explicitly instrumented wait events',]) +endif + +pg_wait_event_tracing = shared_module('pg_wait_event_tracing', + pg_wait_event_tracing_sources, + kwargs: contrib_mod_args, +) +contrib_targets += pg_wait_event_tracing + +install_data( + 'pg_wait_event_tracing--1.0.sql', + 'pg_wait_event_tracing.control', + kwargs: contrib_data_args, +) + +tests += { + 'name': 'pg_wait_event_tracing', + 'sd': meson.current_source_dir(), + 'bd': meson.current_build_dir(), + 'regress': { + 'sql': [ + 'pg_wait_event_tracing', + ], + 'regress_args': ['--temp-config', files('pg_wait_event_tracing.conf')], + # Needs shared_preload_libraries, which typical runningcheck users do + # not have. + 'runningcheck': false, + }, + 'tap': { + 'env': { + 'enable_injection_points': get_option('injection_points') ? 'yes' : 'no', + }, + 'tests': [ + 't/001_memory.pl', + 't/002_ownership.pl', + 't/003_reset_acl.pl', + 't/004_reset_race.pl', + 't/006_server_processes.pl', + 't/007_lazy_hooks.pl', + ], + }, +} diff --git a/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0.sql b/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0.sql new file mode 100644 index 00000000000..75546d6605e --- /dev/null +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0.sql @@ -0,0 +1,143 @@ +/* contrib/pg_wait_event_tracing/pg_wait_event_tracing--1.0.sql */ + +\echo Use "CREATE EXTENSION pg_wait_event_tracing" to load this file. \quit + +CREATE FUNCTION pg_stat_get_wait_event_timing( + IN pid int4 DEFAULT NULL, + OUT pid integer, + OUT backend_type text, + OUT procnumber integer, + OUT wait_event_type text, + OUT wait_event text, + OUT calls bigint, + OUT total_time_ms double precision, + OUT avg_time_us double precision, + OUT max_time_us double precision, + OUT histogram bigint[]) +RETURNS SETOF record +AS 'MODULE_PATHNAME', 'pg_stat_get_wait_event_timing' +LANGUAGE C VOLATILE PARALLEL RESTRICTED; + +CREATE VIEW pg_stat_wait_event_timing AS + SELECT + t.pid, + t.backend_type, + t.procnumber, + t.wait_event_type, + t.wait_event, + t.calls, + t.total_time_ms, + t.avg_time_us, + t.max_time_us, + t.histogram + FROM pg_stat_get_wait_event_timing(NULL) t; +REVOKE ALL ON pg_stat_wait_event_timing FROM PUBLIC; +GRANT SELECT ON pg_stat_wait_event_timing TO pg_read_all_stats; + +CREATE FUNCTION pg_stat_get_wait_event_timing_overflow( + IN pid int4 DEFAULT NULL, + OUT pid integer, + OUT backend_type text, + OUT procnumber integer, + OUT lwlock_overflow_count bigint, + OUT flat_overflow_count bigint, + OUT reset_count bigint) +RETURNS SETOF record +AS 'MODULE_PATHNAME', 'pg_stat_get_wait_event_timing_overflow' +LANGUAGE C VOLATILE PARALLEL RESTRICTED; + +CREATE VIEW pg_stat_wait_event_timing_overflow AS + SELECT + t.pid, + t.backend_type, + t.procnumber, + t.lwlock_overflow_count, + t.flat_overflow_count, + t.reset_count + FROM pg_stat_get_wait_event_timing_overflow(NULL) t; +REVOKE ALL ON pg_stat_wait_event_timing_overflow FROM PUBLIC; +GRANT SELECT ON pg_stat_wait_event_timing_overflow TO pg_read_all_stats; + +-- Taxonomy for the histogram column on pg_stat_wait_event_timing. The +-- histogram array has one entry per bucket, in ascending order. This view +-- names them so callers do not have to memorise the layout; join against it +-- via unnest(histogram) WITH ORDINALITY. +-- +-- WARNING: keep this list in lock-step with PWET_HISTOGRAM_BUCKETS and +-- pwet_timing_bucket() in pg_wait_event_tracing.c. Bin edges are powers of +-- two in nanoseconds; labels are the approximate decimal-microsecond grid. +CREATE VIEW pg_wait_event_timing_histogram_buckets AS + SELECT bucket_idx, lower_ns, upper_ns, label + FROM (VALUES + ( 0, 0::bigint, 1024::bigint, '<1us'::text), + ( 1, 1024::bigint, 2048::bigint, '1-2us'), + ( 2, 2048::bigint, 4096::bigint, '2-4us'), + ( 3, 4096::bigint, 8192::bigint, '4-8us'), + ( 4, 8192::bigint, 16384::bigint, '8-16us'), + ( 5, 16384::bigint, 32768::bigint, '16-32us'), + ( 6, 32768::bigint, 65536::bigint, '32-64us'), + ( 7, 65536::bigint, 131072::bigint, '64-128us'), + ( 8, 131072::bigint, 262144::bigint, '128-256us'), + ( 9, 262144::bigint, 524288::bigint, '256-512us'), + (10, 524288::bigint, 1048576::bigint, '512us-1ms'), + (11, 1048576::bigint, 2097152::bigint, '1-2ms'), + (12, 2097152::bigint, 4194304::bigint, '2-4ms'), + (13, 4194304::bigint, 8388608::bigint, '4-8ms'), + (14, 8388608::bigint, 16777216::bigint, '8-16ms'), + (15, 16777216::bigint, 33554432::bigint, '16-32ms'), + (16, 33554432::bigint, 67108864::bigint, '32-64ms'), + (17, 67108864::bigint, 134217728::bigint, '64-128ms'), + (18, 134217728::bigint, 268435456::bigint, '128-256ms'), + (19, 268435456::bigint, 536870912::bigint, '256-512ms'), + (20, 536870912::bigint, 1073741824::bigint, '512ms-1s'), + (21, 1073741824::bigint, 2147483648::bigint, '1-2s'), + (22, 2147483648::bigint, 4294967296::bigint, '2-4s'), + (23, 4294967296::bigint, 8589934592::bigint, '4-8s'), + (24, 8589934592::bigint, 17179869184::bigint, '8-16s'), + (25, 17179869184::bigint, 34359738368::bigint, '16-32s'), + (26, 34359738368::bigint, 68719476736::bigint, '32-64s'), + (27, 68719476736::bigint, 137438953472::bigint, '64-128s'), + (28, 137438953472::bigint, 274877906944::bigint, '128-256s'), + (29, 274877906944::bigint, 549755813888::bigint, '256-512s'), + (30, 549755813888::bigint, 1099511627776::bigint, '512s-1024s'), + (31, 1099511627776::bigint, NULL::bigint, '>=1024s') + ) AS t(bucket_idx, lower_ns, upper_ns, label); + +CREATE FUNCTION pg_stat_reset_wait_event_timing(pid int4 DEFAULT NULL) +RETURNS void +AS 'MODULE_PATHNAME', 'pg_stat_reset_wait_event_timing' +LANGUAGE C VOLATILE; + +CREATE FUNCTION pg_stat_reset_wait_event_timing_all() +RETURNS void +AS 'MODULE_PATHNAME', 'pg_stat_reset_wait_event_timing_all' +LANGUAGE C VOLATILE; +REVOKE EXECUTE ON FUNCTION pg_stat_reset_wait_event_timing_all() FROM PUBLIC; + +-- Per-class capacity of the dense timing table, for comparison against +-- "SELECT type, count(*) FROM pg_wait_events GROUP BY type" (see the +-- module's "capacity" regression test). +CREATE FUNCTION pg_wait_event_tracing_capacity( + OUT type text, + OUT capacity int4) +RETURNS SETOF record +AS 'MODULE_PATHNAME', 'pg_wait_event_tracing_capacity' +LANGUAGE C VOLATILE PARALLEL RESTRICTED; + +-- Diagnostic for lazy, per-process hook installation: has the calling +-- backend installed its own wait-event hooks (see +-- pwet_install_wait_hooks() in the C code)? Reveals nothing about any +-- other backend or about what is being recorded, so it stays readable by +-- everyone, like pg_wait_event_tracing_capacity() above. +CREATE FUNCTION pg_wait_event_tracing_hooks_installed() +RETURNS boolean +AS 'MODULE_PATHNAME', 'pg_wait_event_tracing_hooks_installed' +LANGUAGE C VOLATILE PARALLEL RESTRICTED; + +-- The histogram bucket boundaries are a constant lookup table, and the +-- per-class capacities are compile-time limits of this module; neither +-- says anything about any session, so both stay readable by everyone, +-- as the equivalent view was before this module existed. +GRANT SELECT ON pg_wait_event_timing_histogram_buckets TO PUBLIC; +GRANT EXECUTE ON FUNCTION pg_wait_event_tracing_capacity() TO PUBLIC; +GRANT EXECUTE ON FUNCTION pg_wait_event_tracing_hooks_installed() TO PUBLIC; diff --git a/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c new file mode 100644 index 00000000000..6839d352875 --- /dev/null +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.c @@ -0,0 +1,2347 @@ +/*------------------------------------------------------------------------- + * + * pg_wait_event_tracing.c + * Statistics-level wait-event collector. + * + * The recorder is the peer-review package's collector, ported onto the + * begin/end wait-event hooks and renamed. Each collecting backend owns one + * sparse DSA slot, addressed through a small, always-resident control + * table; the roughly 200 KiB-per-backend timing payload itself lives in a + * DSA area (GetNamedDSA()) and is allocated only for a backend that + * actually enables capture. Hook callbacks only touch preallocated + * backend-local pointers: allocation, locking, and error-capable work + * happen from parse/executor safe points, never from the begin/end hooks + * themselves. + * + * The control table lives in fixed shared memory (shmem_request_hook / + * shmem_startup_hook), not the DSM registry: a server-side process (the + * checkpointer, an I/O worker, ...) must reach its slot from inside the + * begin hook, where it cannot attach anything (see the "server processes" + * block below), so the table has to already be mapped by the time any + * hook can fire. That is true of fixed shmem in every process from + * postmaster startup on -- the module requires shared_preload_libraries, + * so shmem_startup_hook always runs before user code does -- but is not + * true of a DSM-registry segment, which is created/attached lazily on + * first reference. + * + * Server-side processes never reach post_parse_analyze_hook or + * ExecutorStart_hook (they don't parse queries or run the executor + * through those entry points), so without help they would only ever + * attach at the next configuration reload after capture is turned on -- + * missing everything from process start until then, including + * crash-recovery waits in the startup process. When capture is already + * on in the configuration at postmaster start, this module additionally + * reserves a second, fixed-size region -- one payload-sized slot per + * possible server-side ProcNumber -- and each such process claims its own + * slot from inside the begin hook itself (see the claim protocol below), + * without allocating, locking, waiting, or erroring. + * + * This file carries the statistics level only. The trace level (per-backend + * ring buffer, query markers, trace SRFs) is a separate patch; the slot + * layout below reserves the fields that level will need (trace_ptr, + * trace_state) so that addition does not reshape the control segment. + * + *------------------------------------------------------------------------- + */ +#include "postgres.h" + +#include "catalog/pg_authid.h" +#include "catalog/pg_type_d.h" +#include "executor/executor.h" +#include "fmgr.h" +#include "funcapi.h" +#include "miscadmin.h" +#include "nodes/queryjumble.h" +#include "parser/analyze.h" +#include "port/pg_bitutils.h" +#include "port/atomics.h" +#include "portability/instr_time.h" +#include "postmaster/autovacuum.h" +#include "replication/walsender.h" +#include "storage/dsm_registry.h" +#include "storage/io_worker.h" +#include "storage/ipc.h" +#include "storage/lwlock.h" +#include "storage/proc.h" +#include "storage/procarray.h" +#include "storage/procnumber.h" +#include "storage/shmem.h" +#include "utils/acl.h" +#include "utils/array.h" +#include "utils/backend_status.h" +#include "utils/builtins.h" +#include "utils/dsa.h" +#include "utils/guc.h" +#include "utils/injection_point.h" +#include "utils/tuplestore.h" +#include "utils/wait_classes.h" +#include "utils/wait_event.h" + +#include "pg_wait_event_tracing_data.h" + +PG_MODULE_MAGIC_EXT( + .name = "pg_wait_event_tracing", + .version = PG_VERSION +); + +PG_FUNCTION_INFO_V1(pg_stat_get_wait_event_timing); +PG_FUNCTION_INFO_V1(pg_stat_get_wait_event_timing_overflow); +PG_FUNCTION_INFO_V1(pg_stat_reset_wait_event_timing); +PG_FUNCTION_INFO_V1(pg_stat_reset_wait_event_timing_all); +PG_FUNCTION_INFO_V1(pg_wait_event_tracing_capacity); +PG_FUNCTION_INFO_V1(pg_wait_event_tracing_hooks_installed); + +PGDLLEXPORT void _PG_init(void); + +#define PWET_CONTROL_NAME "pg_wait_event_tracing" +#define PWET_CONTROL_STRUCT_NAME "pg_wait_event_tracing control" +#define PWET_REGION_HEADER_NAME "pg_wait_event_tracing header" +#define PWET_SERVER_REGION_NAME "pg_wait_event_tracing server processes" +#define PWET_STATS_DSA_NAME "pg_wait_event_tracing_stats" +#define PWET_NUM_SLOTS (MaxBackends + NUM_AUXILIARY_PROCS) + +/* + * "6" in plan section 4.2a's R = [MaxConnections, MaxBackends + 6 + + * io_max_workers): the auxiliary process types other than I/O workers + * (checkpointer, background writer, WAL writer, WAL summarizer, archiver, + * startup process, WAL receiver -- proc.h's own comment on + * NUM_AUXILIARY_PROCS explains why 6 of these overlapping-lifetime slots + * suffice). Expressed from proc.h's constants, not as a literal, so it + * tracks NUM_AUXILIARY_PROCS/MAX_IO_WORKERS if they ever change. + */ +#define PWET_NON_IO_AUX_PROCS (NUM_AUXILIARY_PROCS - MAX_IO_WORKERS) +#define PWET_HISTOGRAM_BUCKETS 32 +#define PWET_IDX_LWLOCK (-2) +#define PWET_LWLOCK_EMPTY ((uint16) 0xFFFF) +#define PWET_WAIT_EVENT_CLASS_MASK 0xFF000000U +#define PWET_WAIT_EVENT_ID_MASK 0x0000FFFFU +#define PWET_LWLOCK_PROBE_LIMIT 8 +#define PWET_HAS_STATS_PRIVS(role) \ + (has_privs_of_role(GetUserId(), ROLE_PG_READ_ALL_STATS) || \ + has_privs_of_role(GetUserId(), role)) + +/* + * Reserved trace_state values. The trace-level patch adds ACTIVE and + * ORPHANED; this module only ever produces FREE. + */ +#define PWET_TRACE_FREE 0 + +typedef enum PwetCaptureLevel +{ + PWET_CAPTURE_OFF = 0, + PWET_CAPTURE_STATS, +} PwetCaptureLevel; + +typedef struct PwetTimingEntry +{ + int64 count; + int64 total_ns; + int64 max_ns; + int64 histogram[PWET_HISTOGRAM_BUCKETS]; +} PwetTimingEntry; + +typedef struct PwetLWLockHashEntry +{ + uint16 tranche_id; + uint16 dense_idx; +} PwetLWLockHashEntry; + +typedef struct PwetLWLockHash +{ + int num_used; + int hash_size; + int max_entries; +} PwetLWLockHash; + +/* + * Per-backend statistics payload, allocated in the stats DSA area only for + * a backend that has enabled capture. Fixed-class entries are followed by + * the runtime-sized LWLock hash and its entry array. + * + * The in-flight wait (which event, and when it started) is NOT part of + * this payload: it lives in the process-local statics pwet_wait_start/ + * pwet_current_event instead, because it is written by the owning backend + * only and read by nobody else -- no cross-backend reader ever looked at + * it (pg_stat_get_wait_event_timing() and friends only ever copy + * events/lwlock_hash/the overflow counters/reset_count out of a payload; + * see pwet_emit_timing_row() and pg_stat_get_wait_event_timing_overflow()). + * Keeping it here would just be extra bytes in a struct that is, for the + * fixed-region case, memcpy'd whole on every lock-free read. + */ +typedef struct PwetStats +{ + int64 reset_count; + PwetTimingEntry events[PWET_NUM_EVENTS]; + PwetLWLockHash lwlock_hash; + int64 lwlock_overflow_count; + int64 flat_overflow_count; +} PwetStats; + +/* + * One entry per possible ProcNumber, always resident in the control + * segment. trace_ptr/trace_state are unused placeholders reserved for the + * trace-level patch. + * + * owner_pid/owner_start identify the process that currently owns the + * payload (stats_ptr for a client backend; the matching slice of the fixed + * server-process region -- see below -- for a server-side process): every + * reader compares them against the live PgBackendStatus entry for this + * ProcNumber and ignores the slot on a mismatch, so a successor that has + * not (yet) claimed its own payload never gets attributed a predecessor's + * counters. + * + * A client backend publishes owner_pid/owner_start under pwet_lock, + * alongside stats_ptr; a server-side process instead publishes them + * lock-free from its begin hook (see pwet_claim_fixed_slot()), since the + * hook may not take a lock. reset_generation lives here, not in the + * payload itself, so that a reset request (always published under + * pwet_lock, regardless of which kind of slot it targets -- see + * pwet_request_reset()) can be tied atomically to the owner token that + * authorizes it, and so the owning process can later notice it with a + * lock-free read (see pwet_wait_end()). + */ +typedef struct PwetSlot +{ + dsa_pointer stats_ptr; /* InvalidDsaPointer when not collecting */ + dsa_pointer trace_ptr; /* reserved for the trace level */ + uint8 trace_state; /* reserved for the trace level */ + int owner_pid; /* 0 when unowned */ + TimestampTz owner_start; /* MyStartTimestamp of the owner */ + pg_atomic_uint32 generation; /* bumped on every ownership change */ + pg_atomic_uint32 reset_generation; /* bumped by a reset request */ +} PwetSlot; + +/* + * A small, always-allocated (regardless of capture) record of the one + * decision that can only be made once, by whichever process creates + * shared memory: whether the server-process region was requested, and + * if so, its bounds. shmem_request_hook decides this from pwet_capture + * at postmaster start, but shmem_startup_hook -- which is what actually + * opens the region -- also runs in every EXEC_BACKEND child, potentially + * long after a reload has changed pwet_capture to something else. A + * child must never re-derive the decision from its own (possibly + * reloaded) pwet_capture; it has to read what the postmaster actually + * decided and reserved, from here. + */ +typedef struct PwetRegionHeader +{ + bool server_region_present; + int server_region_start; + int server_region_end; +} PwetRegionHeader; + +static const struct config_enum_entry pwet_capture_options[] = { + {"off", PWET_CAPTURE_OFF, false}, + {"stats", PWET_CAPTURE_STATS, false}, + {NULL, 0, false} +}; + +static int pwet_capture = PWET_CAPTURE_OFF; +static int pwet_max_tranches = 192; + +/* + * guc.c's set_config_with_handle() calls a PGC_ENUM variable's assign_hook + * BEFORE storing the new value (assign_hook(newval, newextra) precedes + * *conf->variable = newval), so pwet_capture is still the *old* value for + * the whole duration of pwet_assign_capture(). A client backend hides + * this: pwet_maybe_attach() also runs from post_parse_analyze_hook / + * ExecutorStart_hook on the next statement, by which point pwet_capture + * has long since been updated. A server-side process has no "next + * statement": with the reserved region absent it depends entirely on the + * assign hook's own synchronous pwet_maybe_attach() call to attach via + * DSA, and with the region present a released fixed slot depends on + * pwet_wait_begin() re-claiming -- which does not go through + * pwet_can_attach() at all, but the DSA fallback does, and a stale + * pwet_capture there would make pwet_can_attach() see the old (often OFF) + * value and refuse forever, since nothing else ever retries it for such a + * process. pwet_capture_effective mirrors pwet_capture except that + * pwet_assign_capture() updates it first, so pwet_can_attach() -- the + * only place this matters -- always sees the value capture is *becoming*. + * The begin/end hooks deliberately keep testing pwet_capture itself (see + * pwet_wait_begin()/pwet_wait_end()), so recording never starts or stops + * based on a value that has not actually taken effect yet. + */ +static int pwet_capture_effective = PWET_CAPTURE_OFF; + +/* The control table: an array of PWET_NUM_SLOTS PwetSlots, nothing else. */ +static PwetSlot *pwet_ctl; +static LWLock *pwet_lock; +static dsa_area *pwet_stats_dsa; + +/* + * Set by pwet_shmem_request() from pwet_capture, in the postmaster only, + * immediately before conditionally requesting the region's bytes; read + * back by pwet_shmem_startup() in that same process, immediately after, + * to decide whether to record the region as present in the header (see + * PwetRegionHeader). Meaningless in any other process: an EXEC_BACKEND + * child never calls shmem_request_hook at all (only the postmaster does, + * once, before shared memory exists), so this stays at its unused + * default there -- which is fine, since a child reads presence/bounds + * from the header, never from this. + */ +static bool pwet_region_requested; + +/* + * The reserved server-process region (plan section 4.2a). NULL unless + * the header (see PwetRegionHeader) records it as present -- which the + * header can only ever say if capture was already non-off in the + * configuration at postmaster start (see pwet_shmem_request()/ + * pwet_shmem_startup()). [pwet_server_region_start, + * pwet_server_region_end) is R, a sub-range of ProcNumbers, read from the + * header the same way; pwet_server_stride is the byte size of one + * process's slice, computed once (from pwet_max_tranches, a + * PGC_POSTMASTER GUC) at the same time as the region itself and never + * recomputed, so every process addresses the region the same way it was + * originally sized. + */ +static char *pwet_server_region; +static int pwet_server_region_start; +static int pwet_server_region_end; +static Size pwet_server_stride; + +static PwetStats *pwet_my_stats; +static ProcNumber pwet_my_procno = INVALID_PROC_NUMBER; +static Size pwet_stats_stride; +static uint32 pwet_last_reset_generation; + +/* + * The owning backend's in-flight wait: written only by that backend's own + * pwet_wait_begin_impl()/pwet_wait_end_impl(), and read by nobody else -- + * confirmed by grepping every ->wait_start/->current_event site before + * this pair replaced PwetStats.wait_start/PwetStats.current_event (the + * cross-backend readers, pg_stat_get_wait_event_timing() and friends, + * copy only the events/lwlock_hash/overflow/reset_count parts of the + * payload -- see pwet_emit_timing_row() and the overflow SRF -- never + * these two). That made them safe to move out of the DSA/fixed-region + * payload into ordinary process-local statics: there was never a second + * reader to keep in sync with the payload's memory, and moving them + * shrinks every stats payload by sizeof(instr_time) + sizeof(uint32) + * without changing any observable memory bound (t/001_memory.pl's checks + * are all footprint *inequalities*, not exact sizes). + */ +static instr_time pwet_wait_start; +static uint32 pwet_current_event; + +/* + * The one-slot, backend-local pending-accounting buffer (v11 patch 0004 + * fixup; see DECISION-deferred-accounting.md). pwet_wait_end_impl() no + * longer does the count/total/max/histogram update and trace append + * itself: doing that inline made every wait_end() call, including one + * returning from inside LWLockAcquire()'s critical section, pay a + * shared-payload cache miss and (in trace mode) a seqlock append before + * the caller could proceed -- for a contended lock, every queued waiter + * pays that too, which is what made W3's collector overhead 40x its + * additive estimate. Instead, wait_end_impl() only reads the clock, + * computes the duration, and stashes (event, duration, timestamp) here; + * pwet_flush_pending() later runs the exact same accounting the old + * inline code did, against the STORED values, from a point where the + * cost no longer extends any lock's hold time -- see its own comment for + * the complete list of call sites and why each is safe/required. + * + * Single-slot, not a queue: at most one wait is ever in flight per + * backend (pwet_wait_start/pwet_current_event above), so at most one + * record is ever pending, and pwet_wait_begin_impl() flushes it before + * timing the next wait -- see pwet_flush_pending()'s comment. + * + * trace records pwet_rec_trace's answer at wait_end time (see + * pwet_wait_end_impl()): whether to append this wait to the trace ring + * is a RECORDING decision, made once, at wait_end, exactly like it was + * before this deferral existed -- pwet_flush_pending() later obeys that + * decision, together with a defensive check that the ring itself is + * still there to append to; it never re-derives the decision from + * whatever pwet_rec_trace happens to answer at the later flush. + */ +typedef struct PwetPendingWait +{ + uint32 event; + int64 duration_ns; + int64 timestamp_ns; /* the wait_end clock read, stored verbatim */ + bool trace; /* pwet_rec_trace != NULL, at wait_end time */ +} PwetPendingWait; + +static PwetPendingWait pwet_pending; +static bool pwet_pending_valid; + +static bool pwet_active; +static bool pwet_attach_needed; +static bool pwet_exit_started; +static bool pwet_stats_writes_disabled; +static bool pwet_exit_callback_registered; + +/* + * The recording gate for the stats level, maintained by + * pwet_update_rec_pointers() from the inputs above (plus + * pwet_capture_effective): non-NULL if and only if this backend should + * actually record right now. pwet_wait_begin_impl()/pwet_wait_end_impl() + * test only this, instead of re-deriving the same three-way test (capture + * level, the writes-disabled flag, and the payload pointer) on every + * wait; see pwet_update_rec_pointers()'s own comment for the exact + * equivalence and why it is safe. + */ +static PwetStats *pwet_rec_stats; + +/* + * Per-process, computed at most once per process (see pwet_wait_begin()): + * does MyProcNumber fall inside the reserved server-process region? + * Cached because the answer can't change over a process's lifetime, and + * the begin/end hooks run on every wait event. + * + * Keyed by MyProcPid, not a bare "have we ever checked" bool, because a + * bare bool would survive fork() into every child with whatever value it + * had in the parent -- and the *postmaster* also calls the begin hook + * (its ServerLoop waits through the same WaitEventSetWait() timed pair), + * with MyProcNumber == INVALID_PROC_NUMBER, so it would cache + * eligible=false once, permanently, for itself; every child forked + * afterwards -- checkpointer, background writer, WAL writer, every + * ordinary backend -- inherits that exact memory image via fork() and + * would see the cache already "checked", never re-deriving its own real + * answer from its own MyProcNumber. (An EXEC_BACKEND child does not + * have this problem: it starts from a fresh, zeroed image, not a forked + * copy, which is why this bug was invisible on Windows.) Keying to + * MyProcPid makes every process -- forked or exec'd -- recompute on its + * own first call, since no live process shares another live process's + * pid. + */ +static int pwet_fixed_slot_checked_pid; +static bool pwet_fixed_slot_eligible; + +static wait_event_hook_type prev_wait_event_begin_hook; +static wait_event_hook_type prev_wait_event_end_hook; + +/* + * Whether this process has installed the wait-event hooks for itself yet + * (see pwet_install_wait_hooks()). Every process in the cluster runs + * _PG_init(), but the hooks are process-local globals, so a process that + * never turns capture on never has to pay their indirect-call overhead on + * every timed wait -- see pwet_install_wait_hooks()'s own comment for the + * installation rule and why the hooks are never removed again. + */ +static bool pwet_wait_hooks_installed; + +static post_parse_analyze_hook_type prev_post_parse_analyze_hook; +static ExecutorStart_hook_type prev_ExecutorStart_hook; +static shmem_request_hook_type prev_shmem_request_hook; +static shmem_startup_hook_type prev_shmem_startup_hook; + +static void pwet_wait_begin(uint32 wait_event_info); +static void pwet_wait_begin_nochain(uint32 wait_event_info); +static void pwet_wait_end(uint32 wait_event_info); +static void pwet_wait_end_nochain(uint32 wait_event_info); +static void pwet_flush_pending(void); +static void pwet_install_wait_hooks(void); +static void pwet_update_rec_pointers(void); +static pg_always_inline void pwet_maybe_attach(void); +static void pwet_maybe_attach_slow(void); +static bool pwet_ensure_stats_dsa(void); +static void pwet_release_stats(void); +static void pwet_before_shmem_exit(int code, Datum arg); +static void pwet_request_reset(int procnumber, int target_pid, + TimestampTz target_start); +static void pwet_check_reset_privileges(Oid target_role); +static bool pwet_is_fixed_procnumber(int procnumber); +static PwetStats *pwet_fixed_payload(int procnumber); +static void pwet_claim_fixed_slot(void); +static void pwet_release_fixed_slot(void); + +static Size +pwet_control_size(int nslots) +{ + return mul_size(nslots, sizeof(PwetSlot)); +} + +static int +pwet_hash_size_for(int max_entries) +{ + int size = 32; + + while (size < max_entries * 2) + size <<= 1; + return size; +} + +static Size +pwet_stats_payload_size(int max_entries) +{ + int hash_size = pwet_hash_size_for(max_entries); + + return add_size(sizeof(PwetStats), + add_size(mul_size(hash_size, + sizeof(PwetLWLockHashEntry)), + mul_size(max_entries, + sizeof(PwetTimingEntry)))); +} + +static inline PwetLWLockHashEntry * +pwet_lwlock_hash_entries(PwetStats *state) +{ + return (PwetLWLockHashEntry *) + ((char *) state + sizeof(PwetStats)); +} + +static inline PwetTimingEntry * +pwet_lwlock_hash_events(PwetStats *state) +{ + return (PwetTimingEntry *) + ((char *) state + sizeof(PwetStats) + + (Size) state->lwlock_hash.hash_size * + sizeof(PwetLWLockHashEntry)); +} + +static void +pwet_lwlock_hash_clear(PwetStats *state) +{ + PwetLWLockHash *hash = &state->lwlock_hash; + PwetLWLockHashEntry *entries = pwet_lwlock_hash_entries(state); + PwetTimingEntry *events = pwet_lwlock_hash_events(state); + int i; + + hash->num_used = 0; + memset(events, 0, + (Size) hash->max_entries * sizeof(PwetTimingEntry)); + for (i = 0; i < hash->hash_size; i++) + { + entries[i].tranche_id = PWET_LWLOCK_EMPTY; + entries[i].dense_idx = 0; + } +} + +static PwetTimingEntry * +pwet_lwlock_lookup(PwetStats *state, uint16 tranche_id) +{ + PwetLWLockHash *hash = &state->lwlock_hash; + PwetLWLockHashEntry *entries = pwet_lwlock_hash_entries(state); + PwetTimingEntry *events = pwet_lwlock_hash_events(state); + uint32 hash_value = (uint32) tranche_id * 2654435761U; + int slot = hash_value & (hash->hash_size - 1); + int limit; + int i; + + limit = hash->num_used >= hash->max_entries + ? PWET_LWLOCK_PROBE_LIMIT : hash->hash_size; + + for (i = 0; i < limit; i++) + { + PwetLWLockHashEntry *entry = &entries[slot]; + + if (entry->tranche_id == tranche_id) + return &events[entry->dense_idx]; + + if (entry->tranche_id == PWET_LWLOCK_EMPTY) + { + if (hash->num_used >= hash->max_entries) + return NULL; + + entry->tranche_id = tranche_id; + entry->dense_idx = hash->num_used++; + return &events[entry->dense_idx]; + } + + slot = (slot + 1) & (hash->hash_size - 1); + } + + return NULL; +} + +static int +pwet_timing_index(uint32 wait_event_info) +{ + uint32 class_id = wait_event_info & PWET_WAIT_EVENT_CLASS_MASK; + int event_id = wait_event_info & PWET_WAIT_EVENT_ID_MASK; + int class_byte; + int dense; + + if (class_id == PG_WAIT_LWLOCK) + return PWET_IDX_LWLOCK; + + class_byte = class_id >> 24; + if (class_byte >= PWET_RAW_CLASSES) + return -1; + + dense = pwet_class_dense[class_byte]; + if (dense < 0 || event_id >= pwet_class_nevents[dense]) + return -1; + + return pwet_class_offset[dense] + event_id; +} + +static int +pwet_timing_bucket(int64 duration_ns) +{ + int bucket; + + if (duration_ns < 1024) + return 0; + + bucket = pg_leftmost_one_pos64((uint64) duration_ns) - 9; + if (bucket >= PWET_HISTOGRAM_BUCKETS) + bucket = PWET_HISTOGRAM_BUCKETS - 1; + return bucket; +} + +/* Initialize a freshly created control table: mark every slot empty. */ +static void +pwet_control_init(PwetSlot *slots) +{ + int i; + + for (i = 0; i < PWET_NUM_SLOTS; i++) + { + slots[i].stats_ptr = InvalidDsaPointer; + slots[i].trace_ptr = InvalidDsaPointer; + slots[i].trace_state = PWET_TRACE_FREE; + slots[i].owner_pid = 0; + slots[i].owner_start = 0; + pg_atomic_init_u32(&slots[i].generation, 0); + pg_atomic_init_u32(&slots[i].reset_generation, 0); + } +} + +/* + * Compute R = [start, end), the sub-range of ProcNumbers server-side + * processes can occupy (plan section 4.2a). Layout, verified on this + * master's proc.c (ProcGlobalShmemInit()): ProcNumbers are handed out in + * one array, [0, MaxConnections) client backends first, then autovacuum + * launcher/workers and the special workers + * (autovacuum_worker_slots + NUM_SPECIAL_WORKER_PROCS), then background + * workers -- which include parallel query workers and logical replication + * workers -- (max_worker_processes), then WAL senders (max_wal_senders), + * ending at MaxBackends; then auxiliary processes fill + * [MaxBackends, MaxBackends + NUM_AUXILIARY_PROCS) on a first-free linear + * search (InitAuxiliaryProcess()), not by type, so with at most + * PWET_NON_IO_AUX_PROCS + io_max_workers of them concurrently alive their + * ProcNumbers never reach MaxBackends + PWET_NON_IO_AUX_PROCS + + * io_max_workers. io_max_workers is PGC_SIGHUP: if it is raised by a + * reload after postmaster start, workers beyond the region reserved here + * fall back to the DSA path once they reach a safe point (see + * pwet_can_attach()) -- this only shrinks the fixed-slot coverage, it does + * not let any process write outside the reserved bytes, since eligibility + * is decided against this stored range, not against "is this any kind of + * server-side process". The clamp to MaxBackends + NUM_AUXILIARY_PROCS + * is therefore just defense in depth (io_max_workers's own GUC bound + * already keeps it <= MAX_IO_WORKERS). + */ +static void +pwet_compute_server_region(int *start, int *end) +{ + int raw_end = MaxBackends + PWET_NON_IO_AUX_PROCS + io_max_workers; + int hard_max = MaxBackends + NUM_AUXILIARY_PROCS; + + *start = MaxConnections; + *end = Min(raw_end, hard_max); +} + +/* + * shmem_request_hook: request the always-resident control table, its + * LWLock tranche, the (also always-resident) region header, and -- only + * if capture is already configured on -- the reserved server-process + * region. + * + * MaxBackends and every GUC referenced by pwet_compute_server_region() are + * final by the time this runs, and pwet_capture already reflects + * postgresql.conf: postmaster.c calls, in order, SelectConfigFiles() + * (loads the config file), process_shared_preload_libraries() (runs every + * library's _PG_init(), including this one -- DefineCustomEnumVariable() + * applies any config-file value for pg_wait_event_tracing.capture right + * then), InitializeMaxBackends(), and only then process_shmem_requests() + * (which calls this hook). Verified by reading postmaster.c directly, + * not inferred. + * + * R is never actually empty (MaxConnections is always < MaxBackends + + * PWET_NON_IO_AUX_PROCS + io_max_workers), so whether the region's bytes + * get requested here depends entirely on pwet_region_requested, i.e. on + * pwet_capture -- never on R's size. + */ +static void +pwet_shmem_request(void) +{ + if (prev_shmem_request_hook) + prev_shmem_request_hook(); + + RequestAddinShmemSpace(pwet_control_size(PWET_NUM_SLOTS)); + RequestNamedLWLockTranche(PWET_CONTROL_NAME, 1); + RequestAddinShmemSpace(sizeof(PwetRegionHeader)); + + pwet_region_requested = (pwet_capture != PWET_CAPTURE_OFF); + if (pwet_region_requested) + { + int start, + end; + + pwet_compute_server_region(&start, &end); + RequestAddinShmemSpace(mul_size(end - start, + pwet_stats_payload_size(pwet_max_tranches))); + } +} + +/* + * shmem_startup_hook: create or attach the control table, the region + * header, and, if the header says so, the server-process region. + * + * Runs once in the postmaster (CreateSharedMemoryAndSemaphores()) and, + * under EXEC_BACKEND, again in every child (AttachSharedMemoryStructs()) -- + * verified in ipci.c, which calls shmem_startup_hook from both places, the + * same way pg_stat_statements relies on it to re-derive its own statics in + * every child. pwet_ctl/pwet_lock/pwet_server_region are plain + * process-local pointers into shared memory, not stored in shared memory + * themselves, so each EXEC_BACKEND child must (and does) recompute them + * here; a fork()-based child instead simply inherits them from the + * postmaster. + * + * Whether the region exists, and its bounds, are decided exactly once, + * by whichever process creates the header (necessarily the postmaster, + * since EXEC_BACKEND children only ever attach to already-created shared + * memory): !found below is true only then, and only there do we consult + * pwet_region_requested/pwet_compute_server_region() at all. Every other + * call -- an EXEC_BACKEND child, or a later re-entry -- finds the header + * already populated and just reads it. This is required, not just + * simpler: a child re-running _PG_init() (and so redefining pwet_capture + * from whatever the config currently says, which can differ from its + * value at postmaster start if a reload happened in between) must not be + * able to change whether the region is treated as present -- the region + * itself was only actually allocated if the *original* decision, recorded + * here, was to request it. + */ +static void +pwet_shmem_startup(void) +{ + bool found; + PwetRegionHeader *hdr; + + if (prev_shmem_startup_hook) + prev_shmem_startup_hook(); + + pwet_ctl = NULL; + pwet_server_region = NULL; + + pwet_lock = &(GetNamedLWLockTranche(PWET_CONTROL_NAME))->lock; + + pwet_ctl = (PwetSlot *) ShmemInitStruct(PWET_CONTROL_STRUCT_NAME, + pwet_control_size(PWET_NUM_SLOTS), + &found); + if (!found) + pwet_control_init(pwet_ctl); + + hdr = (PwetRegionHeader *) ShmemInitStruct(PWET_REGION_HEADER_NAME, + sizeof(PwetRegionHeader), + &found); + if (!found) + { + /* We are the postmaster, creating this for the first time. */ + hdr->server_region_present = pwet_region_requested; + if (pwet_region_requested) + pwet_compute_server_region(&hdr->server_region_start, + &hdr->server_region_end); + else + { + hdr->server_region_start = 0; + hdr->server_region_end = 0; + } + } + + pwet_server_region_start = hdr->server_region_start; + pwet_server_region_end = hdr->server_region_end; + + if (hdr->server_region_present) + { + pwet_server_stride = pwet_stats_payload_size(pwet_max_tranches); + pwet_server_region = (char *) ShmemInitStruct(PWET_SERVER_REGION_NAME, + mul_size(pwet_server_region_end - + pwet_server_region_start, + pwet_server_stride), + &found); + /* ShmemInitStruct()'s underlying allocation is zeroed on creation. */ + } +} + +/* + * Lazily attach this backend to the stats DSA area. GetNamedDSA() manages + * its own tranche and creation lock; we only need to remember the result. + */ +static bool +pwet_ensure_stats_dsa(void) +{ + bool found; + + if (pwet_stats_dsa != NULL) + return true; + + pwet_stats_dsa = GetNamedDSA(PWET_STATS_DSA_NAME, &found); + return pwet_stats_dsa != NULL; +} + +/* + * Is procnumber inside the reserved server-process region, with the + * region actually present? (It exists only when capture was already + * configured on at postmaster start; see pwet_shmem_request().) A + * ProcNumber failing this check always means "not eligible for the fixed + * path right now", never "out of bounds": every caller already knows + * procnumber < PWET_NUM_SLOTS from other bounds checks. + */ +static bool +pwet_is_fixed_procnumber(int procnumber) +{ + return pwet_server_region != NULL && + procnumber >= pwet_server_region_start && + procnumber < pwet_server_region_end; +} + +/* Address of procnumber's slice of the server-process region. */ +static PwetStats * +pwet_fixed_payload(int procnumber) +{ + Assert(pwet_is_fixed_procnumber(procnumber)); + return (PwetStats *) (pwet_server_region + + (Size) (procnumber - pwet_server_region_start) * + pwet_server_stride); +} + +static bool +pwet_can_attach(void) +{ + /* See pwet_capture_effective's comment for why this, not pwet_capture. */ + if (pwet_exit_started || !pwet_active || + pwet_capture_effective == PWET_CAPTURE_OFF) + return false; + if (MyProc == NULL || MyProcNumber == INVALID_PROC_NUMBER) + return false; + if (MyProcNumber < 0 || MyProcNumber >= PWET_NUM_SLOTS) + return false; + + /* + * A ProcNumber inside the reserved region never takes the DSA path + * while that region exists, even before this process has claimed its + * fixed slot: pwet_attach_stats() would publish stats_ptr under + * pwet_lock and point pwet_my_stats at the DSA payload, but readers + * for a ProcNumber in R always consult the fixed region instead (see + * pwet_is_fixed_procnumber() call sites), so anything recorded there + * would silently never be shown. When the region does not exist + * (capture was off at postmaster start), this is unreachable and + * today's DSA-at-next-reload behaviour is unchanged. + */ + if (pwet_is_fixed_procnumber(MyProcNumber)) + return false; + + if (!IsNormalProcessingMode() || CritSectionCount > 0) + return false; + if (MyProc->lwWaiting != LW_WS_NOT_WAITING) + return false; + return true; +} + +/* + * Recompute pwet_rec_stats, the single recording-gate pointer for the + * stats level, from its three inputs. Called at every site that assigns + * any of pwet_capture_effective, pwet_stats_writes_disabled, or + * pwet_my_stats (find them all with: + * grep -n 'pwet_stats_writes_disabled =\|pwet_my_stats =\|pwet_capture_effective =' + * ), so the pointer is never stale by the time pwet_wait_begin_impl()/ + * pwet_wait_end_impl() next read it. + * + * pwet_rec_stats is non-NULL exactly when a test against the STORED + * pwet_capture -- (pwet_capture != OFF, !pwet_stats_writes_disabled, + * pwet_my_stats != NULL) -- would answer yes. This function computes it + * from pwet_capture_effective, the "becoming" value, not from + * pwet_capture, the stored one -- deliberately, so the assign hook + * itself, which sets pwet_capture_effective before guc.c stores the new + * value, can call this function and get the right in-progress answer, + * exactly like every other attach decision (see pwet_capture_effective's + * own comment). + * + * Outside the assign hook's own synchronous call chain, + * pwet_capture_effective == pwet_capture always (guc.c has, by then, + * finished storing the value), so substituting one for the other changes + * nothing there. INSIDE that chain, the two genuinely differ, and this + * is NOT merely academic: pwet_wait_begin_impl()/pwet_wait_end_impl() can + * run synchronously from inside it, because pwet_maybe_attach() (called + * from pwet_assign_capture() when capture is becoming non-off) reaches + * pwet_attach_stats(), which takes an LWLock to publish the new payload -- + * itself a timed wait. Naively deriving the gate from + * pwet_capture_effective there would start recording mid-assign-hook, + * before the SET has actually taken effect (e.g. "off -> stats" would + * count the attach's own LWLock wait). pwet_assign_capture() is what + * keeps this function's answer correct in that window too: it masks + * pwet_stats_writes_disabled, for its own duration only, to reproduce + * exactly what testing the STORED value would have answered (see its own + * comment for the precise rule and why). This function does not need to + * know, from its inputs alone, whether it is being called from inside + * that masked window -- the masking is what makes the answer right + * either way. + * + * The set of recorded waits is therefore unchanged, byte for byte, in + * both cases: outside the chain by the pwet_capture_effective == + * pwet_capture identity, and inside it by the assign hook's masking. + */ +static void +pwet_update_rec_pointers(void) +{ + pwet_rec_stats = (pwet_capture_effective != PWET_CAPTURE_OFF && + !pwet_stats_writes_disabled && + pwet_my_stats != NULL) + ? pwet_my_stats : NULL; +} + +/* + * Claim this process's slot in the reserved server-process region, from + * inside the begin hook (plan section 4.2a's claim protocol). Called at + * most once per process (see pwet_wait_begin()'s cached eligibility + * check), so there is never a second live process contending for the same + * slot concurrently -- the previous occupant, if any, is long gone by the + * time a ProcNumber is reused. The only concurrent observers are the + * lock-free readers (pg_stat_get_wait_event_timing() and friends), which + * is why ownership is published in the exact order below rather than in + * one step. + * + * Obeys the hook rules: no allocation, no lock, no wait, no ereport -- + * only plain loads/stores, one memset on already-mapped fixed shared + * memory, and write barriers. + */ +static void +pwet_claim_fixed_slot(void) +{ + PwetSlot *slot = &pwet_ctl[MyProcNumber]; + PwetStats *payload = pwet_fixed_payload(MyProcNumber); + bool same_owner; + + same_owner = (slot->owner_pid == MyProcPid && + slot->owner_start == MyStartTimestamp); + + /* (1) Unpublish before touching anything a reader might be copying. */ + slot->owner_pid = 0; + pg_write_barrier(); + + /* (2) Fresh owner: reset the payload exactly as a new DSA slot starts. */ + if (!same_owner) + { + int hash_size = pwet_hash_size_for(pwet_max_tranches); + PwetLWLockHashEntry *entries; + int i; + + memset(payload, 0, pwet_server_stride); + payload->lwlock_hash.num_used = 0; + payload->lwlock_hash.hash_size = hash_size; + payload->lwlock_hash.max_entries = pwet_max_tranches; + entries = pwet_lwlock_hash_entries(payload); + for (i = 0; i < hash_size; i++) + entries[i].tranche_id = PWET_LWLOCK_EMPTY; + } + + /* (3) Publish the new owner: start timestamp first, pid last. */ + slot->owner_start = MyStartTimestamp; + pg_write_barrier(); + slot->owner_pid = MyProcPid; + + /* + * Bumped on every ownership change (section 4.1), same as the DSA + * attach path; nothing reads this yet, but pg_atomic_fetch_add_u32() + * is a plain atomic op, allowed in the hook. + */ + pg_atomic_fetch_add_u32(&slot->generation, 1); + + /* (4) Cache the pointer the hooks use. */ + pwet_my_stats = payload; + pwet_my_procno = MyProcNumber; + pwet_last_reset_generation = pg_atomic_read_u32(&slot->reset_generation); + pwet_update_rec_pointers(); +} + +/* + * Stop writing to a claimed fixed slot (assign hook, capture -> off). + * The region is never freed -- it is reserved for the process's entire + * lifetime -- so this only withdraws ownership; the reader's beentry + * check then makes the row disappear, matching the DSA release path's + * user-visible effect. Re-enabling capture re-claims at the next begin + * hook (pwet_can_attach() already refuses the DSA path for this + * ProcNumber, so pwet_maybe_attach() is a no-op here and + * pwet_claim_fixed_slot() is what picks it back up). + * + * No lock: owner_pid/owner_start for a slot in the server region are only + * ever written by the process that owns MyProcNumber, whether from the + * begin hook or from here -- never by another backend, which only ever + * touches reset_generation (under pwet_lock; see pwet_request_reset()). + * + * Flushes the pending wait, if any, before withdrawing ownership: once + * pwet_my_stats is cleared below, pwet_flush_pending() would have nowhere + * left to account it (see its own comment on the payload-gone case), so + * this is the last chance to record it. + */ +static void +pwet_release_fixed_slot(void) +{ + pwet_flush_pending(); + pwet_my_stats = NULL; + pwet_update_rec_pointers(); + if (pwet_my_procno != INVALID_PROC_NUMBER) + { + PwetSlot *slot = &pwet_ctl[pwet_my_procno]; + + slot->owner_pid = 0; + /* Bumped on every ownership change (section 4.1), as on attach. */ + pg_atomic_fetch_add_u32(&slot->generation, 1); + } +} + +static bool +pwet_attach_stats(void) +{ + static bool in_attach; + PwetSlot *slot; + PwetStats *state = NULL; + dsa_pointer stats_ptr = InvalidDsaPointer; + + if (pwet_my_stats != NULL) + return true; + if (in_attach || !pwet_can_attach()) + return false; + + /* + * pwet_ctl/pwet_lock are set up by pwet_shmem_startup() before any + * user code can run (the module requires shared_preload_libraries, so + * that hook always fires first); only the DSA payload area is created + * lazily, on demand, here. + */ + Assert(pwet_ctl != NULL && pwet_lock != NULL); + + in_attach = true; + PG_TRY(); + { + if (pwet_ensure_stats_dsa()) + { + PwetLWLockHashEntry *entries; + int hash_size; + int i; + + pwet_stats_stride = pwet_stats_payload_size(pwet_max_tranches); + hash_size = pwet_hash_size_for(pwet_max_tranches); + stats_ptr = dsa_allocate_extended(pwet_stats_dsa, + pwet_stats_stride, + DSA_ALLOC_ZERO | + DSA_ALLOC_NO_OOM); + if (DsaPointerIsValid(stats_ptr)) + { + state = dsa_get_address(pwet_stats_dsa, stats_ptr); + state->lwlock_hash.num_used = 0; + state->lwlock_hash.hash_size = hash_size; + state->lwlock_hash.max_entries = pwet_max_tranches; + entries = pwet_lwlock_hash_entries(state); + for (i = 0; i < hash_size; i++) + entries[i].tranche_id = PWET_LWLOCK_EMPTY; + + slot = &pwet_ctl[MyProcNumber]; + LWLockAcquire(pwet_lock, LW_EXCLUSIVE); + if (DsaPointerIsValid(slot->stats_ptr)) + dsa_free(pwet_stats_dsa, slot->stats_ptr); + slot->stats_ptr = stats_ptr; + slot->owner_pid = MyProcPid; + slot->owner_start = MyStartTimestamp; + pg_atomic_fetch_add_u32(&slot->generation, 1); + pwet_last_reset_generation = + pg_atomic_read_u32(&slot->reset_generation); + LWLockRelease(pwet_lock); + + pwet_my_stats = state; + pwet_my_procno = MyProcNumber; + pwet_update_rec_pointers(); + } + } + } + PG_FINALLY(); + { + in_attach = false; + } + PG_END_TRY(); + + return pwet_my_stats != NULL; +} + +/* + * The steady-state path reaches this from every parsed and executed query. + * Keep its no-attachment-needed case to one backend-local flag test, + * avoiding an out-of-line call into the attachment machinery. + */ +static pg_always_inline void +pwet_maybe_attach(void) +{ + if (pwet_attach_needed) + pwet_maybe_attach_slow(); +} + +static void +pwet_maybe_attach_slow(void) +{ + if (!pwet_can_attach()) + return; + + if (!pwet_attach_stats()) + return; + + /* + * Registered lazily, per backend, the first time that backend actually + * attaches: on_exit_reset() (called early in every forked/exec'd + * backend, well before shared_preload_libraries processing happens + * again on EXEC_BACKEND, and inherited as a no-op on fork otherwise) + * would discard a registration made from _PG_init() in the postmaster, + * so this is the only place this can usefully happen. + */ + if (!pwet_exit_callback_registered) + { + before_shmem_exit(pwet_before_shmem_exit, (Datum) 0); + pwet_exit_callback_registered = true; + } + + pwet_attach_needed = false; +} + +/* + * Flushes the pending wait, if any, before the payload is freed: once + * pwet_my_stats is cleared below, there is nowhere left to account it + * (see pwet_flush_pending()'s comment on the payload-gone case). + */ +static void +pwet_release_stats(void) +{ + PwetSlot *slot; + ProcNumber procno = pwet_my_procno; + bool was_disabled = pwet_stats_writes_disabled; + + pwet_flush_pending(); + + if (pwet_my_stats == NULL || pwet_stats_dsa == NULL || pwet_ctl == NULL || + procno == INVALID_PROC_NUMBER) + { + pwet_my_stats = NULL; + pwet_update_rec_pointers(); + return; + } + + pwet_stats_writes_disabled = true; + pwet_my_stats = NULL; + pwet_update_rec_pointers(); + slot = &pwet_ctl[procno]; + + LWLockAcquire(pwet_lock, LW_EXCLUSIVE); + if (DsaPointerIsValid(slot->stats_ptr)) + { + dsa_free(pwet_stats_dsa, slot->stats_ptr); + slot->stats_ptr = InvalidDsaPointer; + slot->owner_pid = 0; + slot->owner_start = 0; + pg_atomic_fetch_add_u32(&slot->generation, 1); + } + LWLockRelease(pwet_lock); + + if (!pwet_exit_started) + { + pwet_stats_writes_disabled = was_disabled; + pwet_update_rec_pointers(); + } +} + +static void +pwet_before_shmem_exit(int code, Datum arg) +{ + /* + * First thing, while pwet_my_stats/pwet_my_trace are both still + * attached and nothing below has touched either of them yet: the last + * pending wait, if any, gets both halves (stats and, if trace is + * active, the trace record) accounted here, exactly once, before exit + * cleanup begins. pwet_orphan_trace()/pwet_release_stats() below each + * flush again on their own (every release/orphan site does; see their + * comments), which is harmless -- pwet_flush_pending() is a no-op once + * there is nothing pending -- but this call is what makes that true + * for both of them here, rather than leaving it to whichever runs + * first. + */ + pwet_flush_pending(); + pwet_exit_started = true; + pwet_stats_writes_disabled = true; + pwet_update_rec_pointers(); + pwet_release_stats(); + pwet_my_procno = INVALID_PROC_NUMBER; +} + +static void +pwet_assign_capture(int newval, void *extra) +{ + int old_stored = pwet_capture; + bool saved_stats_disabled = pwet_stats_writes_disabled; + + /* + * Flush the pending wait, if any, before anything below masks + * recording or releases/reattaches a payload: pwet_my_stats/ + * pwet_my_trace are both still exactly what they were when the wait + * was stashed, so this is the last point before this function can + * change either of them out from under a still-pending record. + */ + pwet_flush_pending(); + + /* + * Lazily install this process's own wait hooks the moment capture + * becomes non-off in it, before any attach logic below runs (that + * logic can itself run synchronously from here -- see + * pwet_maybe_attach() further down -- and the hooks must already be in + * place by the time any wait completes). See + * pwet_install_wait_hooks() for why this never happens in _PG_init() + * instead, and why the hooks, once installed, are never removed. + */ + if (newval != PWET_CAPTURE_OFF) + pwet_install_wait_hooks(); + + /* + * Mask recording, for the rest of this function only, to exactly what + * old_stored (the value guc.c has NOT yet overwritten pwet_capture + * with) would have permitted -- even though pwet_rec_stats is computed + * from pwet_capture_effective, the "becoming" value set below, not + * old_stored. + * + * This matters because pwet_maybe_attach() below can run synchronously + * from inside this very function (see its own call further down), and + * pwet_attach_stats() takes an LWLock to publish the new payload -- + * itself a timed wait, i.e. something pwet_wait_begin()/ + * pwet_wait_end() can observe before this function returns. Before + * pwet_rec_stats existed, the hot path tested pwet_capture directly, + * which guc.c does not store until AFTER this function returns (see + * the RULE comment on pwet_capture_effective): so for the whole + * duration of this function, the old code's recording gate saw + * old_stored, never newval, no matter what got attached in the + * meantime. Deriving the gate from pwet_capture_effective instead + * (which THIS function sets to newval, below) would, without the mask + * here, start recording mid-function the instant an attach triggered + * by the incoming value completes -- e.g. off -> stats would count + * the attach's own LWLock wait in stats. Masking reproduces the old + * gate's answer exactly: stats is masked only when old_stored == OFF, + * the one case where the old gate would have refused to record no + * matter what (pwet_capture == OFF outright); when old_stored is + * already STATS, a payload already exists and the old gate already + * counted this function's own waits under it. + * + * The window between this function returning and guc.c actually + * storing newval into pwet_capture contains no wait sites (nothing in + * set_config_with_handle() between the assign_hook call and the store + * waits on anything), so masking exactly the inside of this function, + * and restoring on every exit (below), is sufficient: the set of + * recorded waits is byte-for-byte identical to testing the stored + * pwet_capture throughout, exactly as before pwet_rec_stats existed. + * Deferred accounting (v11 patch 0004 fixup; see + * DECISION-deferred-accounting.md) does not change this: the recording + * decision for a wait is still taken here and in + * pwet_wait_end_impl(), at wait_end time, exactly as before -- only + * the bookkeeping itself, writing the counters, is deferred, never + * the decision of whether to. + */ + if (old_stored == PWET_CAPTURE_OFF) + pwet_stats_writes_disabled = true; + + /* + * Update the "becoming" value first, before anything below can call + * pwet_can_attach() (see pwet_capture_effective's comment): guc.c has + * not yet stored newval into pwet_capture itself at this point. + */ + pwet_capture_effective = newval; + pwet_update_rec_pointers(); + + if (pwet_my_stats != NULL) + { + INSTR_TIME_SET_ZERO(pwet_wait_start); + pwet_current_event = 0; + } + + if (pwet_active && !pwet_exit_started) + { + if (newval == PWET_CAPTURE_OFF) + { + /* + * pwet_release_stats() only knows how to release a DSA payload + * (it checks slot->stats_ptr, which a fixed-slot owner never + * sets); a process holding a claimed fixed slot instead has + * pwet_fixed_slot_eligible set (see pwet_wait_begin()), and + * needs pwet_release_fixed_slot() to withdraw ownership from + * the control table. + */ + if (pwet_fixed_slot_eligible) + pwet_release_fixed_slot(); + else + pwet_release_stats(); + pwet_attach_needed = false; + } + else + { + pwet_attach_needed = true; + /* + * Attach right away if this is a safe point; otherwise the + * post_parse_analyze/ExecutorStart hooks pick it up for a + * client backend, or the next begin hook re-claims for a + * server-side process (pwet_can_attach() refuses the DSA path + * for a ProcNumber in the reserved region, so + * pwet_maybe_attach() below is a no-op for those; see + * pwet_claim_fixed_slot()). + */ + if (IsNormalProcessingMode()) + pwet_maybe_attach(); + } + } + + /* + * Unmask: restore pwet_stats_writes_disabled to what it was on entry, + * so the mask above is scoped to exactly this function's own duration, + * on every exit path (there is only this one). pwet_release_stats() + * above may itself have already toggled this same flag true and back + * as part of its own release protocol; that nesting composes + * correctly because it restores to "whatever it saw on entry to + * itself", which by then is our masked value -- so after it returns, + * the flag is back to our masked value, and this restores it one + * level further out, to the value from before we masked it. If this + * process is exiting, leave it true instead, matching + * pwet_before_shmem_exit() (which sets pwet_exit_started before this + * hook could even be reached again, but a defensive match costs + * nothing). + */ + if (pwet_exit_started) + pwet_stats_writes_disabled = true; + else + pwet_stats_writes_disabled = saved_stats_disabled; + pwet_update_rec_pointers(); +} + +/* + * Flush the one pending completed-wait record, if any, running exactly the + * accounting pwet_wait_end_impl() used to run inline before the deferred- + * accounting change (v11 patch 0004 fixup; see + * DECISION-deferred-accounting.md and pwet_pending's own comment for why). + * Called at every point where ordering or a payload's/ring's lifetime + * matters -- enumerated in full in the commit message, in outline here: + * + * - pwet_wait_begin_impl(), before timing the next wait; + * - before every pwet_trace_write_marker() call site: post_parse_analyze, + * ExecutorStart/End, both of ProcessUtility's markers, the xact + * callback, and wait_begin's own Idle marker synthesis (already + * covered by wait_begin's own flush above, since nothing in between + * can create a new pending record, but restated there for the reader + * rather than relied on implicitly); + * - pwet_assign_capture(), before it masks recording or releases/ + * reattaches anything; + * - pwet_release_stats(), pwet_release_fixed_slot(), pwet_release_trace(), + * pwet_orphan_trace(), before each does its work; + * - pwet_before_shmem_exit(), first thing; + * - pwet_reset_own(), before zeroing; + * - the SQL readers of the CALLING backend's own data: + * pg_get_backend_wait_event_trace(), the calling backend's own row in + * pg_stat_get_wait_event_timing()'s and + * pg_stat_get_wait_event_timing_overflow()'s sweeps, and + * pg_get_wait_event_trace() when given the caller's own procnumber + * (which covers pg_wait_event_trace_by_statement() too, since it is + * built on that function in the extension script) -- a cross-backend + * reader instead sees whatever the owning backend's own next flush + * point produced, the bounded latency the decision document accepts. + * + * Must obey the hook rules (no allocation, no lock, no wait, no ereport): + * wait_begin_impl calls this from inside the hook itself, so the rule is + * upheld unconditionally here, even though most other call sites above are + * ordinary safe points that would not themselves require it. + * + * Both recording decisions for this record -- whether to count it in + * stats at all, and whether to append it to the trace ring -- were + * already made at wait_end time, exactly as they were before this + * deferral existed: the record is only ever stashed when pwet_rec_stats + * was non-NULL then (see pwet_wait_end_impl()), and pwet_pending.trace + * records what pwet_rec_trace answered at that same instant. This + * function only carries those decisions out later; it never re-derives + * either one from whatever pwet_rec_stats/pwet_rec_trace happen to + * answer now, at flush time, which can differ from their wait_end-time + * answer during pwet_assign_capture()'s own masked window (see its + * comment) -- re-deriving there would let this later moment's masking, + * meant for a different question (should a NEW wait be recorded right + * now), silently override a decision already made for this one. + * + * The one exception is pwet_my_stats/pwet_my_trace themselves: a pending + * record's payload or ring can have been genuinely released between + * wait_end and this flush (which cannot happen on the normal path, since + * every release/orphan site above flushes first) -- pwet_my_stats == NULL + * drops the stats half, and pwet_my_trace == NULL drops the trace half + * even when pwet_pending.trace is true, there being nowhere left to put + * either one. + */ +static void +pwet_flush_pending(void) +{ + uint32 event; + int64 duration_ns; + int64 timestamp_ns; + PwetStats *state; + + if (!pwet_pending_valid) + return; + + event = pwet_pending.event; + duration_ns = pwet_pending.duration_ns; + timestamp_ns = pwet_pending.timestamp_ns; + pwet_pending_valid = false; + + /* + * Stats eligibility needs no separate field to check here: this + * record was only ever stashed by pwet_wait_end_impl() while + * pwet_rec_stats was non-NULL, so the recording decision is already + * implied by the record's mere existence -- only whether the payload + * is still there to write into (pwet_my_stats) remains to be checked. + */ + state = pwet_my_stats; + if (state != NULL) + { + uint32 reset_generation; + int idx; + PwetTimingEntry *entry = NULL; + + /* + * reset_generation lives in the always-mapped control slot, not the + * DSA payload (see pwet_request_reset()), so this is a plain + * lock-free atomic read: the owner is the only reader, and the + * requester only ever increments it under the control lock. Same + * position in the sequence as the pre-deferral code: immediately + * before this record's own values are applied to state->events, + * i.e. the reset always lands before the record it would otherwise + * have been clobbered by is accounted. + */ + reset_generation = + pg_atomic_read_u32(&pwet_ctl[pwet_my_procno].reset_generation); + if (reset_generation != pwet_last_reset_generation) + { + memset(state->events, 0, sizeof(state->events)); + pwet_lwlock_hash_clear(state); + state->reset_count++; + state->lwlock_overflow_count = 0; + state->flat_overflow_count = 0; + pwet_last_reset_generation = reset_generation; + } + + idx = pwet_timing_index(event); + if (idx == PWET_IDX_LWLOCK) + entry = pwet_lwlock_lookup(state, event & PWET_WAIT_EVENT_ID_MASK); + else if (idx >= 0) + entry = &state->events[idx]; + + if (entry != NULL) + { + entry->count++; + entry->total_ns += duration_ns; + if (duration_ns > entry->max_ns) + entry->max_ns = duration_ns; + entry->histogram[pwet_timing_bucket(duration_ns)]++; + } + else if (idx == PWET_IDX_LWLOCK) + state->lwlock_overflow_count++; + else + state->flat_overflow_count++; + } + + /* No trace level yet at this point in the series. */ + (void) timestamp_ns; +} + +/* + * Body of the wait_event_begin_hook, shared by the chaining and + * non-chaining wrappers below (pwet_install_wait_hooks() picks whichever + * one applies to this process, once, at install time). chain is always a + * compile-time constant at each call site, so the inlined body has no + * previous-hook NULL test on either path: pwet_install_wait_hooks() only + * ever wires up the chain=true wrapper when prev_wait_event_begin_hook is + * known non-NULL, so there is nothing to test here. + */ +static pg_always_inline void +pwet_wait_begin_impl(uint32 wait_event_info, bool chain) +{ + if (chain) + prev_wait_event_begin_hook(wait_event_info); + + /* + * Flush the previous wait's pending record, if any, before this wait's + * own clock read below (see pwet_flush_pending()'s comment for the + * complete list of flush points): this is the primary one, what keeps + * the deferred accounting's cost out of the interval this wait itself + * measures, and, when the PREVIOUS wait ended inside a critical + * section (e.g. LWLockAcquire()'s), out of the caller's lock hold time + * too -- that caller has already returned from LWLockAcquire() by the + * time any NEW wait begins. Unconditional: must run even when + * pwet_rec_stats is NULL right now, since the pending record's own + * recording decisions were already made, for both halves, back when + * it was stashed at wait_end time -- see pwet_flush_pending()'s + * comment for why it carries those decisions out from pwet_my_stats/ + * pwet_pending.trace/pwet_my_trace, never re-deriving either one from + * pwet_rec_stats/pwet_rec_trace as they stand now. Cheap when + * nothing is pending: one boolean test. + */ + pwet_flush_pending(); + + /* + * The attached, capturing case (the overwhelming majority of calls once + * any backend anywhere is capturing) is one pointer test. Everything + * below, up to and including the not-yet-attached slow path, is + * unchanged in what it decides -- only the top-level test changed, from + * three separate conditions to the one pwet_rec_stats pointer that + * pwet_update_rec_pointers() keeps in sync with them (see its comment). + */ + if (pwet_rec_stats == NULL) + { + /* The original three conditions, tested individually. */ + if (pwet_capture == PWET_CAPTURE_OFF || pwet_stats_writes_disabled) + return; + + if (pwet_my_stats == NULL) + { + /* + * A server-side process never reaches post_parse_analyze_hook or + * ExecutorStart_hook, so this is the only place it can attach; a + * client backend attaches through those hooks (or the assign + * hook) instead, since pwet_is_fixed_procnumber() is never true + * for a ProcNumber below MaxConnections. Computed at most once + * per process (see pwet_fixed_slot_checked_pid's comment for why + * this is keyed by pid rather than a bare "already checked" + * flag): the answer cannot change over a process's lifetime once + * it has one, and this hook runs on every wait event. + * + * MyProcNumber can itself still be INVALID_PROC_NUMBER here: the + * postmaster never has one (its own ServerLoop reaches this hook + * too), and any process, right after fork/exec, technically could + * call this before InitProcess()/InitAuxiliaryProcess() has run. + * Neither claims nor caches in that case, so a later call -- once + * (if ever) MyProcNumber becomes valid -- retries; this costs a + * few extra branches per wait in the postmaster for its entire + * lifetime (it never gets a ProcNumber), which is fine since the + * postmaster's own waits are not a hot path. + */ + if (pwet_fixed_slot_checked_pid != MyProcPid) + { + if (MyProcNumber == INVALID_PROC_NUMBER) + return; + + pwet_fixed_slot_checked_pid = MyProcPid; + pwet_fixed_slot_eligible = pwet_is_fixed_procnumber(MyProcNumber); + } + + if (pwet_fixed_slot_eligible) + pwet_claim_fixed_slot(); + + if (pwet_my_stats == NULL) + return; + } + + /* + * Recompute unconditionally, whichever of the three paths above was + * taken (already attached; just claimed a fixed slot; still not + * attached at all), so pwet_rec_stats is guaranteed fresh before + * the hot path below reads it -- pwet_claim_fixed_slot() already + * calls this itself too (it is one of the sites + * pwet_update_rec_pointers()'s own comment enumerates), but calling + * it again here is cheap and idempotent, and means this block does + * not have to know which path it took. Return, not fall through, + * if the three conditions still do not all hold. + */ + pwet_update_rec_pointers(); + if (pwet_rec_stats == NULL) + return; + } + + INSTR_TIME_SET_CURRENT(pwet_wait_start); + pwet_current_event = wait_event_info; +} + +static void +pwet_wait_begin(uint32 wait_event_info) +{ + pwet_wait_begin_impl(wait_event_info, true); +} + +static void +pwet_wait_begin_nochain(uint32 wait_event_info) +{ + pwet_wait_begin_impl(wait_event_info, false); +} + +/* + * Body of the wait_event_end_hook; see pwet_wait_begin_impl()'s comment. + * + * Before the deferred-accounting change (v11 patch 0004 fixup; see + * DECISION-deferred-accounting.md), this function did the reset-generation + * check, the count/total/max/histogram update, and the trace append + * itself, all before returning to the caller -- for an LWLock wait, that + * caller is still inside LWLockAcquire()'s critical section, so every one + * of those nanoseconds, including a cache miss on the shared payload, + * directly extended the lock's hold time and was paid by every queued + * waiter (the v11 finding this fixup addresses). Now it does only the + * cheap, unavoidable part -- read the clock, compute the duration -- and + * stashes (event, duration, timestamp, and whether to trace) in the + * one-slot pending buffer pwet_pending (see its own comment) for + * pwet_flush_pending() to account, unchanged, from a point that no + * longer extends any lock's hold time. Durations are still measured + * between the same two instants as before, and the stored timestamp is + * still this same wait_end clock read, so every value that eventually + * reaches the stats payload or a trace record is identical to what + * immediate accounting would have produced -- only when it gets there + * is deferred. Both recording decisions -- whether to count this wait + * in stats at all (the pwet_rec_stats test below, unchanged from + * before), and whether to append it to the trace ring + * (pwet_pending.trace, capturing pwet_rec_trace's answer right here) -- + * are still made at this exact instant, exactly as they were before + * deferral; pwet_flush_pending() only carries them out later. + */ +static pg_always_inline void +pwet_wait_end_impl(uint32 wait_event_info, bool chain) +{ + /* + * pwet_rec_stats is non-NULL exactly when the old three-way test + * (pwet_capture != OFF, !pwet_stats_writes_disabled, pwet_my_stats != + * NULL) held -- see pwet_update_rec_pointers()'s comment -- so this one + * pointer read replaces that test without changing which waits get + * recorded. + */ + if (pwet_rec_stats != NULL) + { + uint32 event = pwet_current_event; + + if (event != 0 && !INSTR_TIME_IS_ZERO(pwet_wait_start)) + { + instr_time now; + int64 duration_ns; + + INSTR_TIME_SET_CURRENT(now); + duration_ns = INSTR_TIME_GET_NANOSEC(now) - + INSTR_TIME_GET_NANOSEC(pwet_wait_start); + if (duration_ns < 0) + duration_ns = 0; + + /* + * Defend against nesting: pwet_wait_start/pwet_current_event + * form a single in-flight-wait slot that pwet_wait_begin_impl() + * always (re)writes before a new wait can start, and that same + * function unconditionally flushes pwet_pending before doing + * so (see its comment) -- so a record should never already be + * pending here. If it somehow were anyway, flush the old one + * now rather than silently overwriting (losing) it. + */ + if (pwet_pending_valid) + pwet_flush_pending(); + + pwet_pending.event = event; + pwet_pending.duration_ns = duration_ns; + pwet_pending.timestamp_ns = INSTR_TIME_GET_NANOSEC(now); + /* No trace level yet at this point in the series. */ + pwet_pending.trace = false; + pwet_pending_valid = true; + + INSTR_TIME_SET_ZERO(pwet_wait_start); + } + } + + if (chain) + prev_wait_event_end_hook(wait_event_info); +} + +static void +pwet_wait_end(uint32 wait_event_info) +{ + pwet_wait_end_impl(wait_event_info, true); +} + +static void +pwet_wait_end_nochain(uint32 wait_event_info) +{ + pwet_wait_end_impl(wait_event_info, false); +} + +/* + * Lazily install this process's wait_event_begin_hook/wait_event_end_hook, + * the first time (in this process) capture becomes non-off -- called from + * pwet_assign_capture(), never from _PG_init() (see its own comment). + * Idempotent (pwet_wait_hooks_installed guards it) and, deliberately, + * never undone: a later consumer that chains onto us (prev_*_hook here) + * may itself have saved our function pointer as ITS previous hook by the + * time capture drops back to off in this process; uninstalling ourselves + * here would silently cut that consumer out of the chain for the rest of + * the process's life, with no way for it to notice. Leaving the hooks + * installed costs nothing extra: pwet_wait_begin()/pwet_wait_end() are + * already no-ops whenever pwet_capture is off. + * + * Which of the two wrapper pairs (chaining vs. non-chaining) gets wired up + * is decided once, right here, from whether this process already had + * another module's hook installed: a NULL previous pointer means there is + * nothing to chain to, ever, for the rest of this process's life (nothing + * later sets wait_event_begin_hook/wait_event_end_hook back to NULL), so + * the non-chaining variant drops the previous-hook test from the hot path + * entirely instead of testing a pointer that will forever be NULL. + */ +static void +pwet_install_wait_hooks(void) +{ + if (pwet_wait_hooks_installed) + return; + + prev_wait_event_begin_hook = wait_event_begin_hook; + prev_wait_event_end_hook = wait_event_end_hook; + + wait_event_begin_hook = (prev_wait_event_begin_hook != NULL) + ? pwet_wait_begin : pwet_wait_begin_nochain; + wait_event_end_hook = (prev_wait_event_end_hook != NULL) + ? pwet_wait_end : pwet_wait_end_nochain; + + pwet_wait_hooks_installed = true; +} + +static void +pwet_post_parse_analyze(ParseState *pstate, Query *query, + const JumbleState *jstate) +{ + if (prev_post_parse_analyze_hook != NULL) + prev_post_parse_analyze_hook(pstate, query, jstate); + + pwet_maybe_attach(); +} + +static void +pwet_ExecutorStart(QueryDesc *queryDesc, int eflags) +{ + pwet_maybe_attach(); + + if (prev_ExecutorStart_hook != NULL) + prev_ExecutorStart_hook(queryDesc, eflags); + else + standard_ExecutorStart(queryDesc, eflags); +} + +/* + * Resolve the optional pid SRF argument to a ProcNumber range + * [out_start, out_end). Returns false if the SRF should emit zero rows + * (unknown pid -- silent no-op). Auxiliary processes are included here: + * unlike the reset functions, reading their stats is not a control action. + */ +static bool +pwet_pid_range(FunctionCallInfo fcinfo, int argnum, + int *out_start, int *out_end) +{ + if (PG_ARGISNULL(argnum)) + { + *out_start = 0; + *out_end = PWET_NUM_SLOTS; + return true; + } + else + { + int target_pid = PG_GETARG_INT32(argnum); + PGPROC *proc; + int procnumber; + + proc = BackendPidGetProc(target_pid); + if (proc == NULL) + proc = AuxiliaryPidGetProc(target_pid); + if (proc == NULL) + return false; + + procnumber = GetNumberFromPGProc(proc); + if (procnumber < 0 || procnumber >= PWET_NUM_SLOTS) + return false; + + *out_start = procnumber; + *out_end = procnumber + 1; + return true; + } +} + +static void +pwet_emit_timing_row(ReturnSetInfo *rsinfo, PgBackendStatus *beentry, + int procnumber, uint32 wait_event_info, + PwetTimingEntry *entry, ArrayType *histogram, + int64 *histogram_data) +{ + Datum values[10]; + bool nulls[10] = {0}; + const char *event_type; + const char *event_name; + int i; + + event_type = pgstat_get_wait_event_type(wait_event_info); + event_name = pgstat_get_wait_event(wait_event_info); + if (event_type == NULL || event_name == NULL) + return; + + values[0] = Int32GetDatum(beentry->st_procpid); + values[1] = CStringGetTextDatum(GetBackendTypeDesc(beentry->st_backendType)); + values[2] = Int32GetDatum(procnumber); + values[3] = CStringGetTextDatum(event_type); + values[4] = CStringGetTextDatum(event_name); + values[5] = Int64GetDatum(entry->count); + values[6] = Float8GetDatum((double) entry->total_ns / 1000000.0); + values[7] = Float8GetDatum(entry->count > 0 + ? (double) entry->total_ns / + entry->count / 1000.0 : 0.0); + values[8] = Float8GetDatum((double) entry->max_ns / 1000.0); + for (i = 0; i < PWET_HISTOGRAM_BUCKETS; i++) + histogram_data[i] = entry->histogram[i]; + values[9] = PointerGetDatum(histogram); + + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls); +} + +/* + * Lock-free read of a fixed slot's owner token (plan section 4.2a): read + * both fields, then a read barrier before the caller looks at the + * payload, so a concurrent pwet_claim_fixed_slot() -- whose step (1) + * clears owner_pid before touching the payload -- is guaranteed visible + * first. Returns false immediately (without touching the payload at all) + * if the slot does not currently belong to beentry. + */ +static bool +pwet_fixed_owner_matches(PwetSlot *slot, PgBackendStatus *beentry, + int *out_pid, TimestampTz *out_start) +{ + int pid = slot->owner_pid; + TimestampTz start = slot->owner_start; + + pg_read_barrier(); + + if (pid != beentry->st_procpid || start != beentry->st_proc_start_timestamp) + return false; + + *out_pid = pid; + *out_start = start; + return true; +} + +/* + * Second half of the double read: re-read the owner token after copying + * the payload (with a read barrier first, pairing with + * pwet_claim_fixed_slot()'s step (3) write barrier) and confirm it still + * matches what pwet_fixed_owner_matches() saw. A mismatch means a claim + * raced with the copy and the payload may be torn or already belong to a + * new owner; the caller must discard it. + */ +static bool +pwet_fixed_owner_unchanged(PwetSlot *slot, int pid, TimestampTz start) +{ + pg_read_barrier(); + return slot->owner_pid == pid && slot->owner_start == start; +} + +/* + * Lock-free read of a claimed fixed slot's full payload into *snapshot. + * See pwet_fixed_owner_matches()/pwet_fixed_owner_unchanged() for the + * double-read protocol this brackets the copy with. + */ +static bool +pwet_read_fixed_slot(int procnumber, PgBackendStatus *beentry, + PwetStats *snapshot) +{ + PwetSlot *slot = &pwet_ctl[procnumber]; + int pid; + TimestampTz start; + + if (!pwet_fixed_owner_matches(slot, beentry, &pid, &start)) + return false; + + memcpy(snapshot, pwet_fixed_payload(procnumber), pwet_server_stride); + + return pwet_fixed_owner_unchanged(slot, pid, start); +} + +/* + * SQL function: pg_stat_get_wait_event_timing(pid int4, OUT ...) + * + * One row per (backend, wait_event) with a non-zero count. pid is + * optional: NULL means every backend; a non-NULL value restricts the sweep + * to that backend (silently empty for an unknown pid). + * + * The sweep below flushes the CALLING backend's own pending wait, if the + * sweep reaches its own procnumber (pid was NULL, or exactly this + * backend's pid), so a session reading its own row always sees its own + * just-completed waits -- see the module comment / commit message for why + * this is one of the required flush points. A cross-backend row is read + * from whatever the owner last flushed itself, unaffected by this. + */ +Datum +pg_stat_get_wait_event_timing(PG_FUNCTION_ARGS) +{ + ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + ArrayType *histogram; + int64 *histogram_data; + PwetStats *snapshot; + int start_idx; + int end_idx; + int procnumber; + + InitMaterializedSRF(fcinfo, 0); + + if (!pwet_pid_range(fcinfo, 0, &start_idx, &end_idx)) + PG_RETURN_VOID(); + if (!pwet_ensure_stats_dsa()) + PG_RETURN_VOID(); + + pwet_stats_stride = pwet_stats_payload_size(pwet_max_tranches); + snapshot = palloc(pwet_stats_stride); + + { + Datum zeros[PWET_HISTOGRAM_BUCKETS]; + + memset(zeros, 0, sizeof(zeros)); + histogram = construct_array_builtin(zeros, + PWET_HISTOGRAM_BUCKETS, + INT8OID); + histogram_data = (int64 *) ARR_DATA_PTR(histogram); + } + + for (procnumber = start_idx; procnumber < end_idx; procnumber++) + { + PgBackendStatus *beentry; + bool matched; + int i; + + beentry = pgstat_get_beentry_by_proc_number(procnumber); + if (beentry == NULL || beentry->st_procpid == 0 || + !PWET_HAS_STATS_PRIVS(beentry->st_userid)) + continue; + + /* Own row: flush before reading it (see the function comment). */ + if (procnumber == MyProcNumber) + pwet_flush_pending(); + + if (pwet_is_fixed_procnumber(procnumber)) + { + /* Lock-free: the region is never freed, so this never races + * with anything but the owner's own claim. */ + matched = pwet_read_fixed_slot(procnumber, beentry, snapshot); + } + else + { + PwetSlot *slot = &pwet_ctl[procnumber]; + dsa_pointer stats_ptr; + + LWLockAcquire(pwet_lock, LW_SHARED); + stats_ptr = slot->stats_ptr; + matched = DsaPointerIsValid(stats_ptr) && + slot->owner_pid == beentry->st_procpid && + slot->owner_start == beentry->st_proc_start_timestamp; + if (matched) + memcpy(snapshot, dsa_get_address(pwet_stats_dsa, stats_ptr), + pwet_stats_stride); + LWLockRelease(pwet_lock); + } + + if (!matched) + continue; + + for (i = 0; i < PWET_DENSE_CLASSES; i++) + { + int base = pwet_class_offset[i]; + int nevents = pwet_class_nevents[i]; + uint32 class_id = pwet_dense_to_classid[i]; + int j; + + for (j = 0; j < nevents; j++) + { + PwetTimingEntry *entry = &snapshot->events[base + j]; + + if (entry->count == 0) + continue; + pwet_emit_timing_row(rsinfo, beentry, procnumber, + ((uint32) class_id << 24) | (uint32) j, + entry, histogram, histogram_data); + } + } + + { + PwetLWLockHashEntry *entries = + pwet_lwlock_hash_entries(snapshot); + PwetTimingEntry *events = + pwet_lwlock_hash_events(snapshot); + + for (i = 0; i < snapshot->lwlock_hash.hash_size; i++) + { + PwetLWLockHashEntry *hash_entry = &entries[i]; + PwetTimingEntry *entry; + + if (hash_entry->tranche_id == PWET_LWLOCK_EMPTY) + continue; + entry = &events[hash_entry->dense_idx]; + if (entry->count == 0) + continue; + pwet_emit_timing_row(rsinfo, beentry, procnumber, + PG_WAIT_LWLOCK | + hash_entry->tranche_id, + entry, histogram, histogram_data); + } + } + } + + pfree(snapshot); + PG_RETURN_VOID(); +} + +/* + * SQL function: pg_stat_get_wait_event_timing_overflow(pid int4, OUT ...) + * + * One row per backend that has an attached stats payload, exposing the + * truncation counters the recording path maintains. pid has the same + * optional semantics as pg_stat_get_wait_event_timing(). + * + * Flushes the calling backend's own pending record before emitting its + * row, same rule and same reason as pg_stat_get_wait_event_timing()'s own + * sweep (see pwet_flush_pending()'s comment): reset_count in particular + * is only ever advanced by a flush noticing reset_generation has moved, + * so a caller reading its own row here must not be left looking at a + * stale count merely because nothing else has flushed for it yet. + */ +Datum +pg_stat_get_wait_event_timing_overflow(PG_FUNCTION_ARGS) +{ + ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + int start_idx; + int end_idx; + int procnumber; + + InitMaterializedSRF(fcinfo, 0); + + if (!pwet_pid_range(fcinfo, 0, &start_idx, &end_idx)) + PG_RETURN_VOID(); + if (!pwet_ensure_stats_dsa()) + PG_RETURN_VOID(); + + for (procnumber = start_idx; procnumber < end_idx; procnumber++) + { + PgBackendStatus *beentry; + Datum values[6]; + bool nulls[6] = {0}; + int64 lwlock_overflow = 0; + int64 flat_overflow = 0; + int64 reset_count = 0; + bool matched = false; + + beentry = pgstat_get_beentry_by_proc_number(procnumber); + if (beentry == NULL || beentry->st_procpid == 0 || + !PWET_HAS_STATS_PRIVS(beentry->st_userid)) + continue; + + /* Own row: flush before reading it (see the function comment). */ + if (procnumber == MyProcNumber) + pwet_flush_pending(); + + if (pwet_is_fixed_procnumber(procnumber)) + { + PwetSlot *slot = &pwet_ctl[procnumber]; + int pid; + TimestampTz start; + + if (pwet_fixed_owner_matches(slot, beentry, &pid, &start)) + { + PwetStats *state = pwet_fixed_payload(procnumber); + + lwlock_overflow = state->lwlock_overflow_count; + flat_overflow = state->flat_overflow_count; + reset_count = state->reset_count; + matched = pwet_fixed_owner_unchanged(slot, pid, start); + } + } + else + { + PwetSlot *slot = &pwet_ctl[procnumber]; + + LWLockAcquire(pwet_lock, LW_SHARED); + if (DsaPointerIsValid(slot->stats_ptr) && + slot->owner_pid == beentry->st_procpid && + slot->owner_start == beentry->st_proc_start_timestamp) + { + PwetStats *state = dsa_get_address(pwet_stats_dsa, + slot->stats_ptr); + + lwlock_overflow = state->lwlock_overflow_count; + flat_overflow = state->flat_overflow_count; + reset_count = state->reset_count; + matched = true; + } + LWLockRelease(pwet_lock); + } + + if (!matched) + continue; + + values[0] = Int32GetDatum(beentry->st_procpid); + values[1] = CStringGetTextDatum(GetBackendTypeDesc(beentry->st_backendType)); + values[2] = Int32GetDatum(procnumber); + values[3] = Int64GetDatum(lwlock_overflow); + values[4] = Int64GetDatum(flat_overflow); + values[5] = Int64GetDatum(reset_count); + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, + values, nulls); + } + + 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 + * be lost, so it is accounted first and then immediately wiped by the + * reset below, exactly as it would have been (recorded, then reset) had + * pg_stat_reset_wait_event_timing() run in a later statement instead of + * landing between the wait and its flush. Its trace record, if any, is + * unaffected by a stats reset and is left standing. + */ +static void +pwet_reset_own(void) +{ + pwet_flush_pending(); + + if (pwet_my_stats != NULL) + { + memset(pwet_my_stats->events, 0, sizeof(pwet_my_stats->events)); + pwet_lwlock_hash_clear(pwet_my_stats); + pwet_my_stats->reset_count++; + pwet_my_stats->lwlock_overflow_count = 0; + pwet_my_stats->flat_overflow_count = 0; + pwet_current_event = 0; + INSTR_TIME_SET_ZERO(pwet_wait_start); + } +} + +/* + * Replicate the target-authorization checks of pg_signal_backend() in + * src/backend/storage/ipc/signalfuncs.c: a non-superuser cannot touch a + * superuser-owned or role-less target, and otherwise needs privileges of + * the target role or of pg_signal_backend. Unlike pg_signal_backend(), + * there is no separate carve-out for autovacuum workers: they are + * role-less, so they already require superuser here, which is the more + * conservative choice for a function that erases diagnostic state. + */ +static void +pwet_check_reset_privileges(Oid target_role) +{ + if (!OidIsValid(target_role) || superuser_arg(target_role)) + { + if (!superuser()) + ereport(ERROR, + (errcode(ERRCODE_INSUFFICIENT_PRIVILEGE), + errmsg("permission denied to reset another backend's wait event timing statistics"), + errdetail("Only roles with the %s attribute may reset statistics of a superuser-owned or role-less backend.", + "SUPERUSER"))); + } + else if (!has_privs_of_role(GetUserId(), target_role) && + !has_privs_of_role(GetUserId(), ROLE_PG_SIGNAL_BACKEND)) + ereport(ERROR, + (errcode(ERRCODE_INSUFFICIENT_PRIVILEGE), + errmsg("permission denied to reset another backend's wait event timing statistics"), + errdetail("Only roles with privileges of the target role or the \"%s\" role may reset another backend's wait event timing statistics.", + "pg_signal_backend"))); +} + +/* + * Request an asynchronous reset on the given slot, if it is still owned by + * target_pid/target_start. The owning backend notices at its next + * wait_end() (see pwet_wait_end()) and clears its own counters. + * + * target_pid/target_start were captured by the caller when it resolved the + * pid to a ProcNumber, which can be arbitrarily far in the past by the time + * we get the lock (ProcArrayLock was already released by then). Re-checking + * the owner token under the same lock that publishes the request is what + * prevents the request from landing on a successor that has since reused + * this ProcNumber (a bare "does this slot have a payload" check is not + * enough: the successor could be capturing too). + */ +static void +pwet_request_reset(int procnumber, int target_pid, TimestampTz target_start) +{ + PwetSlot *slot = &pwet_ctl[procnumber]; + + INJECTION_POINT("pg-wait-event-tracing-reset-before-publish", NULL); + + LWLockAcquire(pwet_lock, LW_EXCLUSIVE); + if (slot->owner_pid == target_pid && slot->owner_start == target_start) + pg_atomic_fetch_add_u32(&slot->reset_generation, 1); + LWLockRelease(pwet_lock); +} + +/* + * SQL function: pg_stat_reset_wait_event_timing(pid int4) + * + * NULL or own pid : reset the caller's own counters synchronously. + * another pid : request a cross-backend reset, subject to the same + * target authorization as pg_signal_backend(). + * unknown pid : silent no-op (matching pg_signal_backend()'s WARNING). + * auxiliary pid : rejected -- BackendPidGetProc() only resolves normal + * backends, so this falls out of the same check. + */ +Datum +pg_stat_reset_wait_event_timing(PG_FUNCTION_ARGS) +{ + int target_pid; + PGPROC *proc; + int procnumber; + PgBackendStatus *beentry; + + if (PG_ARGISNULL(0) || PG_GETARG_INT32(0) == MyProcPid) + { + pwet_reset_own(); + PG_RETURN_VOID(); + } + + target_pid = PG_GETARG_INT32(0); + + proc = BackendPidGetProc(target_pid); + if (proc == NULL) + { + /* Matches pg_signal_backend(): unknown pid or auxiliary process. */ + ereport(WARNING, + (errmsg("PID %d is not a PostgreSQL backend process", + target_pid))); + PG_RETURN_VOID(); + } + + procnumber = GetNumberFromPGProc(proc); + if (procnumber < 0 || procnumber >= PWET_NUM_SLOTS) + PG_RETURN_VOID(); + + pwet_check_reset_privileges(proc->roleId); + + beentry = pgstat_get_beentry_by_proc_number(procnumber); + if (beentry == NULL || beentry->st_procpid != target_pid) + PG_RETURN_VOID(); /* gone by the time we got here */ + + pwet_request_reset(procnumber, target_pid, + beentry->st_proc_start_timestamp); + + PG_RETURN_VOID(); +} + +/* + * SQL function: pg_stat_reset_wait_event_timing_all() + * + * Request a reset on every slot. Superuser-only: unlike the single-pid + * form, this is not delegable by granting EXECUTE, matching the "_all() + * superuser-only" policy regardless of what the extension script's default + * REVOKE/GRANT state happens to be. + */ +Datum +pg_stat_reset_wait_event_timing_all(PG_FUNCTION_ARGS) +{ + int i; + + if (!superuser()) + ereport(ERROR, + (errcode(ERRCODE_INSUFFICIENT_PRIVILEGE), + errmsg("permission denied to reset wait event timing statistics for all backends"), + errdetail("Only roles with the %s attribute may reset statistics for all backends.", + "SUPERUSER"))); + + /* + * Unlike the single-pid form, there is no specific owner to re-check: + * bumping an unowned slot's reset_generation is harmless (nothing + * consumes it), and a slot that gets a new owner concurrently either + * sees this generation already accounted for at attach time or picks up + * the bump at its first wait_end, which is a fine outcome either way for + * an operation whose contract is "every backend", not "this backend". + */ + LWLockAcquire(pwet_lock, LW_EXCLUSIVE); + for (i = 0; i < PWET_NUM_SLOTS; i++) + pg_atomic_fetch_add_u32(&pwet_ctl[i].reset_generation, 1); + LWLockRelease(pwet_lock); + + PG_RETURN_VOID(); +} + +/* + * SQL function: pg_wait_event_tracing_capacity() + * + * One row per dense class plus one for LWLock (whose effective capacity is + * the max_tranches GUC, not a table entry, since LWLock waits go through a + * per-backend hash rather than the flat per-event array). Meant to be + * compared against "SELECT type, count(*) FROM pg_wait_events GROUP BY + * type" by the module's regression test, which fails when any class is + * within 4 of its capacity. + */ +Datum +pg_wait_event_tracing_capacity(PG_FUNCTION_ARGS) +{ + ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + Datum values[2]; + bool nulls[2] = {0}; + int i; + + InitMaterializedSRF(fcinfo, 0); + + for (i = 0; i < PWET_DENSE_CLASSES; i++) + { + values[0] = CStringGetTextDatum(pwet_class_names[i]); + values[1] = Int32GetDatum(pwet_class_nevents[i]); + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, + values, nulls); + } + + values[0] = CStringGetTextDatum("LWLock"); + values[1] = Int32GetDatum(pwet_max_tranches); + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls); + + PG_RETURN_VOID(); +} + +/* + * SQL function: pg_wait_event_tracing_hooks_installed() + * + * Diagnostic for the lazy, per-process hook installation (see + * pwet_install_wait_hooks()): true if the calling backend has installed + * its own wait_event_begin_hook/wait_event_end_hook, false if it never has + * (capture has been off in this process since it started). Reveals + * nothing about any other backend or about what is being recorded, so it + * is granted to PUBLIC, like pg_wait_event_tracing_capacity(). + */ +Datum +pg_wait_event_tracing_hooks_installed(PG_FUNCTION_ARGS) +{ + PG_RETURN_BOOL(pwet_wait_hooks_installed); +} + +void +_PG_init(void) +{ + if (!process_shared_preload_libraries_in_progress) + ereport(ERROR, + (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE), + errmsg("pg_wait_event_tracing must be loaded via \"shared_preload_libraries\""))); + + DefineCustomEnumVariable("pg_wait_event_tracing.capture", + "Controls wait event collection.", + NULL, + &pwet_capture, + PWET_CAPTURE_OFF, + pwet_capture_options, + PGC_SUSET, + GUC_NOT_IN_SAMPLE, + NULL, + pwet_assign_capture, + NULL); + DefineCustomIntVariable("pg_wait_event_tracing.max_tranches", + "Maximum distinct LWLock tranches tracked per backend.", + NULL, + &pwet_max_tranches, + 192, + 16, + 65534, + PGC_POSTMASTER, + GUC_NOT_IN_SAMPLE, + NULL, + NULL, + NULL); + MarkGUCPrefixReserved("pg_wait_event_tracing"); + + prev_shmem_request_hook = shmem_request_hook; + shmem_request_hook = pwet_shmem_request; + prev_shmem_startup_hook = shmem_startup_hook; + shmem_startup_hook = pwet_shmem_startup; + + /* + * The wait-event begin/end hooks are NOT installed here: they are + * installed lazily, per process, the first time this process's own + * pwet_assign_capture() sees capture become non-off -- see + * pwet_install_wait_hooks(). A process that never enables capture + * never pays the indirect-call overhead on its timed waits. + */ + prev_post_parse_analyze_hook = post_parse_analyze_hook; + post_parse_analyze_hook = pwet_post_parse_analyze; + prev_ExecutorStart_hook = ExecutorStart_hook; + ExecutorStart_hook = pwet_ExecutorStart; + + pwet_active = true; + pwet_attach_needed = (pwet_capture != PWET_CAPTURE_OFF); +} diff --git a/contrib/pg_wait_event_tracing/pg_wait_event_tracing.conf b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.conf new file mode 100644 index 00000000000..be58a7d2312 --- /dev/null +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.conf @@ -0,0 +1 @@ +shared_preload_libraries = 'pg_wait_event_tracing' diff --git a/contrib/pg_wait_event_tracing/pg_wait_event_tracing.control b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.control new file mode 100644 index 00000000000..fbf09c0bcff --- /dev/null +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing.control @@ -0,0 +1,5 @@ +# pg_wait_event_tracing extension +comment = 'statistics and trace collection for explicitly instrumented wait events' +default_version = '1.0' +module_pathname = '$libdir/pg_wait_event_tracing' +relocatable = true diff --git a/contrib/pg_wait_event_tracing/pg_wait_event_tracing_data.h b/contrib/pg_wait_event_tracing/pg_wait_event_tracing_data.h new file mode 100644 index 00000000000..3394acf95c5 --- /dev/null +++ b/contrib/pg_wait_event_tracing/pg_wait_event_tracing_data.h @@ -0,0 +1,91 @@ +/*------------------------------------------------------------------------- + * + * pg_wait_event_tracing_data.h + * Dense wait-event map, with per-class capacities checked against + * src/backend/utils/activity/wait_event_names.txt on this master + * (headroom >= 8 events per class; see pg_wait_event_tracing_capacity() + * and the "capacity" regression test, which enforce that this table is + * bumped in the same commit that runs a class out of headroom). + * + * Static counts at the time these capacities were chosen: Lock 12, Buffer 4, + * Activity 18, Client 9, Extension 1 (dynamic; WaitEventExtensionNew() + * grows this at runtime), IPC 64, Timeout 11, IO 83, InjectionPoint 0 + * (dynamic; WaitEventInjectionPointNew()). LWLock is not part of this + * table: its "capacity" is the pg_wait_event_tracing.max_tranches GUC, + * since LWLock waits are tracked through a per-backend hash, not a flat + * per-event array. + * + *------------------------------------------------------------------------- + */ +#ifndef PG_WAIT_EVENT_TRACING_DATA_H +#define PG_WAIT_EVENT_TRACING_DATA_H + +#define PWET_RAW_CLASSES 12 +#define PWET_DENSE_CLASSES 9 +#define PWET_NUM_EVENTS 560 + +static const int8 pwet_class_dense[PWET_RAW_CLASSES] = { + -1, /* 0x00: unused */ + -1, /* 0x01: LWLock (uses hash) */ + -1, /* 0x02: unused */ + 0, /* 0x03: Lock */ + 1, /* 0x04: Buffer */ + 2, /* 0x05: Activity */ + 3, /* 0x06: Client */ + 4, /* 0x07: Extension */ + 5, /* 0x08: IPC */ + 6, /* 0x09: Timeout */ + 7, /* 0x0a: IO */ + 8 /* 0x0b: InjectionPoint */ +}; + +static const int pwet_class_nevents[PWET_DENSE_CLASSES] = { + 32, /* Lock: 12 in use, was 16 (headroom 4) */ + 16, /* Buffer: 4 in use */ + 32, /* Activity: 18 in use */ + 32, /* Client: 9 in use, was 16 (headroom 7) */ + 128, /* Extension: dynamic */ + 128, /* IPC: 64 in use, was 64 (headroom 0) */ + 32, /* Timeout: 11 in use, was 16 (headroom 5) */ + 128, /* IO: 83 in use */ + 32 /* InjectionPoint: dynamic; only ever + * populated in injection-points-enabled + * test builds, so kept small */ +}; + +static const int pwet_class_offset[PWET_DENSE_CLASSES] = { + 0, /* Lock */ + 32, /* Buffer */ + 48, /* Activity */ + 80, /* Client */ + 112, /* Extension */ + 240, /* IPC */ + 368, /* Timeout */ + 400, /* IO */ + 528 /* InjectionPoint */ +}; + +static const uint8 pwet_dense_to_classid[PWET_DENSE_CLASSES] = { + 0x03, 0x04, 0x05, 0x06, 0x07, 0x08, 0x09, 0x0a, 0x0b +}; + +/* + * Class names, in the same order as the dense arrays above, matching what + * pg_wait_events.type reports for each (see generate-wait_event_types.pl, + * which derives the type string from the ClassName section name). Used by + * pg_wait_event_tracing_capacity() so its output can be compared directly + * against "SELECT type, count(*) FROM pg_wait_events GROUP BY type". + */ +static const char *const pwet_class_names[PWET_DENSE_CLASSES] = { + "Lock", + "Buffer", + "Activity", + "Client", + "Extension", + "IPC", + "Timeout", + "IO", + "InjectionPoint" +}; + +#endif /* PG_WAIT_EVENT_TRACING_DATA_H */ diff --git a/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing.sql b/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing.sql new file mode 100644 index 00000000000..15b2d7939bf --- /dev/null +++ b/contrib/pg_wait_event_tracing/sql/pg_wait_event_tracing.sql @@ -0,0 +1,239 @@ +-- +-- PG_WAIT_EVENT_TRACING +-- +-- Exercises the statistics level: the capture GUC, the stats surface +-- (pg_stat_get_wait_event_timing(), the pg_stat_wait_event_timing and +-- histogram-buckets views, overflow counters), reset (self and +-- cross-backend, including its authorization), and the per-class capacity +-- table. The trace level is a separate patch and is not exercised here. +-- +CREATE EXTENSION pg_wait_event_tracing; + +-- Statistics are per backend: a parallel worker records its waits under +-- its own pid. CI forces parallel query on some platforms +-- (debug_parallel_query = regress), which would move pg_sleep() below into +-- a worker, so keep this session's statements in this session. +SET debug_parallel_query = off; + +-- Default is off. +SHOW pg_wait_event_tracing.capture; + +-- Lazy, per-process hook installation: a fresh session that +-- has never turned capture on has never installed its wait-event hooks. +SELECT pg_wait_event_tracing_hooks_installed(); + +-- The taxonomy view is pure SQL. +SELECT count(*) AS buckets FROM pg_wait_event_timing_histogram_buckets; +SELECT bucket_idx, lower_ns, upper_ns, label +FROM pg_wait_event_timing_histogram_buckets +WHERE bucket_idx IN (0, 1, 31) +ORDER BY bucket_idx; + +-- Enable stats capture and generate a deterministic wait: pg_sleep emits a +-- Timeout / PgSleep wait. +SET pg_wait_event_tracing.capture = stats; + +-- Pin the recording-gate equivalence: the SET above may +-- itself attach a stats payload synchronously, inside the assign hook, +-- and that attach takes an LWLock -- a timed wait. That LWLock wait must +-- not be counted: the assign hook masks recording, for its own duration, +-- to what the stored capture value (still "off" while the hook runs) +-- would have permitted, so no self-inflicted attach waits ever show up. +SELECT count(*) AS lwlock_waits_during_attach +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid() AND wait_event_type = 'LWLock'; + +-- The SET above installed this backend's hooks (the assign hook calls +-- pwet_install_wait_hooks() itself, before any attach logic runs). +SELECT pg_wait_event_tracing_hooks_installed(); + +SELECT pg_sleep(0.1); + +-- PgSleep must now be recorded for this backend, with the per-event +-- invariants holding. We print only booleans so the output is stable. +SELECT calls >= 1 AS calls_ok, + calls = (SELECT sum(h) FROM unnest(histogram) AS h) AS hist_sum_eq_calls, + total_time_ms > 0 AS total_positive, + max_time_us > 0 AS max_positive, + array_length(histogram, 1) + = (SELECT count(*)::int FROM pg_wait_event_timing_histogram_buckets) + AS histogram_len_ok +FROM pg_stat_get_wait_event_timing(pg_backend_pid()) +WHERE wait_event = 'PgSleep'; + +-- The view surfaces the same row, with backend_type attached (v6 column +-- set). +SELECT backend_type, wait_event_type, wait_event +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid() AND wait_event = 'PgSleep'; + +-- A non-NULL pid that does not exist yields no rows (silent, not an +-- error). +SELECT count(*) AS rows_for_bogus_pid +FROM pg_stat_get_wait_event_timing(-1); + +-- Overflow/reset counters for this backend. A plain test backend uses few +-- LWLock tranches and no out-of-range classes, so both overflow counters +-- are zero, and a fresh backend has not been reset. +SELECT lwlock_overflow_count, flat_overflow_count, reset_count +FROM pg_stat_wait_event_timing_overflow +WHERE pid = pg_backend_pid(); + +-- Resetting our own backend is synchronous: the PgSleep row is cleared and +-- reset_count advances. (Filtering to PgSleep because inter-command waits +-- such as ClientRead may be recorded again before the next statement +-- runs.) +SELECT pg_stat_reset_wait_event_timing(NULL); +SELECT count(*) AS pgsleep_rows_after_reset +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid() AND wait_event = 'PgSleep'; +SELECT reset_count +FROM pg_stat_wait_event_timing_overflow +WHERE pid = pg_backend_pid(); + +-- +-- Deferred accounting (v11 patch 0004 fixup; see +-- DECISION-deferred-accounting.md): pwet_wait_end_impl() no longer accounts +-- a completed wait immediately -- it stashes it in a one-slot pending +-- buffer, applied later by pwet_flush_pending(), at the next timed wait or +-- one of several other ordering points, INCLUDING every SQL reader of a +-- backend's own data. So a wait completed earlier in the same statement +-- (here, by pg_sleep()) must always be visible to a query run by the SAME +-- session immediately afterward, with no special handling needed by the +-- caller and no dependency on an intervening wait happening to flush it +-- first. +-- +SELECT pg_stat_reset_wait_event_timing(); +SELECT pg_sleep(0.02); +SELECT calls >= 1 AS pgsleep_visible_immediately_in_same_session +FROM pg_stat_get_wait_event_timing(pg_backend_pid()) +WHERE wait_event = 'PgSleep'; + +-- +-- A cross-backend reset request is applied exactly once, at whichever +-- flush next notices reset_generation has moved, even when a wait is +-- pending -- possibly this session's own -- at the moment the request +-- lands: the reset-generation check runs at the same position inside +-- pwet_flush_pending() as it always did inline in wait_end, immediately +-- before the pending record's own values are applied, and once noticed, +-- pwet_last_reset_generation is updated so the same request can never be +-- reapplied by a later flush. reset_count is checked as a delta, not an +-- absolute value. +-- +-- pg_stat_wait_event_timing_overflow(), unlike pg_stat_get_wait_event_ +-- timing() and the trace readers, does NOT flush the calling backend's +-- own pending record before reading (a gap in the module, not exercised +-- by this test's assertion itself, only worked around below): reading +-- reset_count through it right after the pg_sleep() below, with no +-- flush in between, leaves the outcome dependent on whatever OTHER wait +-- this session happens to incur first, which is not guaranteed on every +-- platform (observed: a 64-bit build's incidental wait flushed it in +-- time, a 32-bit build's did not). A second, tiny pg_sleep() forces a +-- deterministic flush here: pwet_wait_begin_impl() unconditionally +-- flushes the previous pending record -- the first pg_sleep() below, +-- which is what carries the reset-generation mismatch -- before timing +-- itself, with no dependency on anything else this session might do. +-- +SELECT reset_count AS reset_count_before +FROM pg_stat_wait_event_timing_overflow +WHERE pid = pg_backend_pid() \gset +SELECT pg_stat_reset_wait_event_timing_all(); +SELECT pg_sleep(0.02); +SELECT pg_sleep(0.01); +SELECT reset_count - :reset_count_before AS reset_count_advanced_by_exactly_one +FROM pg_stat_wait_event_timing_overflow +WHERE pid = pg_backend_pid(); + +-- +-- SET capture = off right after a wait still accounts that wait before +-- releasing the payload (flush before release): pwet_release_stats()/ +-- pwet_release_fixed_slot() call pwet_flush_pending() as the first thing +-- they do, before touching stats_ptr, so a pending record is never +-- silently dropped by an ordinary disable. The payload itself does not +-- survive release regardless (see "Disabling capture releases the +-- payload" above; the row disappears either way, whether or not the last +-- wait was accounted first), so what this checks is that disabling +-- capture immediately after a wait -- with the two statements sent +-- together, so there is no intervening statement boundary that could +-- flush it first on its own -- is not itself a source of any error, and +-- that the very next capture cycle starts from a clean slate. The +-- guarantee that the flush actually runs before, not after, the payload +-- is freed is a call-ordering property verified by inspection (every +-- release/orphan site's own first statement) and by a dedicated +-- cross-session TAP check (t/013_deferred_flush.pl), neither of which a +-- single-connection regress script can exercise: nothing distinguishes +-- "flushed, then freed" from "dropped, then freed" once the freed +-- backend's own payload is gone, without a second session positioned to +-- read the row before that free happens. +-- +SET pg_wait_event_tracing.capture = stats; +SELECT pg_sleep(0.02); SET pg_wait_event_tracing.capture = off; +SELECT count(*) AS rows_after_wait_then_immediate_disable +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid(); +SET pg_wait_event_tracing.capture = stats; +SELECT count(*) AS rows_are_clean_on_next_cycle +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid() AND wait_event = 'PgSleep'; +RESET pg_wait_event_tracing.capture; + +-- The pid argument defaults to NULL, so a no-argument call resets the +-- caller's own backend. +SELECT pg_stat_reset_wait_event_timing(); + +-- Resetting an unknown pid is a WARNING, not an ERROR, matching +-- pg_signal_backend()'s own wording; the reset itself is a no-op. +SELECT pg_stat_reset_wait_event_timing(2147483647); + +-- Disabling capture releases the payload (fix 1/2): even though the pid is +-- unchanged, every row for it disappears, because the reader checks +-- ownership, not just "is there a payload here". +RESET pg_wait_event_tracing.capture; +SELECT pg_sleep(0.05); +SELECT count(*) AS rows_after_disable +FROM pg_stat_wait_event_timing +WHERE pid = pg_backend_pid(); + +-- Hooks, once installed, are never removed: still true even +-- though this backend's own capture is off again, so a later re-enable in +-- this same process needs no reinstallation. +SELECT pg_wait_event_tracing_hooks_installed(); + +-- +-- Reset authorization (fix 4). The pg_signal_backend-member-vs-ordinary- +-- target and non-superuser-vs-superuser-target cases need a second, real +-- backend with a different owning role; those live in the TAP test +-- t/003_reset_acl.pl (WP4a), which can create and authenticate as extra +-- roles portably (this regress test cannot: no second connection is +-- available here, and resetting your own pid always takes the synchronous +-- self-reset path regardless of role). What is single-session-testable is +-- _all()'s superuser requirement, which holds even for a role granted +-- EXECUTE directly, not just relying on the extension script's default +-- REVOKE EXECUTE FROM PUBLIC. +-- +CREATE ROLE regress_pwet_signaler; +GRANT EXECUTE ON FUNCTION pg_stat_reset_wait_event_timing_all() + TO regress_pwet_signaler; +SET ROLE regress_pwet_signaler; +SELECT pg_stat_reset_wait_event_timing_all(); +RESET ROLE; +REVOKE EXECUTE ON FUNCTION pg_stat_reset_wait_event_timing_all() + FROM regress_pwet_signaler; +DROP ROLE regress_pwet_signaler; +-- +-- Per-class capacity (plan sec 3.1). Every class pg_wait_events knows +-- about must have a capacity row, and every class must have at least 4 +-- events of headroom below its capacity, so that whoever adds an event +-- past that headroom is caught here rather than by silent overflow +-- counting. +-- +SELECT count(*) AS classes_missing_capacity +FROM (SELECT DISTINCT type FROM pg_wait_events) t +WHERE NOT EXISTS ( + SELECT 1 FROM pg_wait_event_tracing_capacity() c WHERE c.type = t.type); + +SELECT bool_and(cap.capacity - cnt.n >= 4) AS capacity_headroom_ok +FROM (SELECT type, count(*) AS n FROM pg_wait_events GROUP BY type) cnt +JOIN pg_wait_event_tracing_capacity() cap USING (type); + +RESET pg_wait_event_tracing.capture; diff --git a/contrib/pg_wait_event_tracing/t/001_memory.pl b/contrib/pg_wait_event_tracing/t/001_memory.pl new file mode 100644 index 00000000000..7afe1fae9b0 --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/001_memory.pl @@ -0,0 +1,124 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: memory footprint bound (fix 1). +# +# The statistics-level collector's shared-memory footprint must stay +# sparse: the always-resident control segment holds only one small +# PwetSlot per possible backend, and the ~208 KiB-per-backend timing +# payload is allocated from a DSA area only for a backend that actually +# enables capture, not for every backend up front (v6's dense design +# would need roughly 238 slots * ~206 KiB =~ 48 MiB at this test's +# max_connections). This test measures the module's DSM registry +# footprint -- the control segment "pg_wait_event_tracing" plus the DSA +# area "pg_wait_event_tracing_stats" -- across a sequence of sessions +# enabling and disabling capture, and checks it stays within the +# sparse-design bounds instead of scaling with max_connections. + +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', + "shared_preload_libraries = 'pg_wait_event_tracing'"); +$node->append_conf('postgresql.conf', "max_connections = 200"); +# Keep pg_sleep() running in the session that issued it, not a parallel +# worker, so its wait is recorded under the pid this test is watching. +$node->append_conf('postgresql.conf', "debug_parallel_query = off"); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing;'); + +# Sum of the DSM registry entries this module owns: the small, +# always-resident control segment plus the DSA area backing per-backend +# payloads. dsa_get_total_size_from_handle() sums all of a DSA's +# segments, so a single row already reflects the whole area. +sub pwet_footprint +{ + return $node->safe_psql( + 'postgres', + "SELECT coalesce(sum(size), 0) FROM pg_dsm_registry_allocations " + . "WHERE name LIKE 'pg_wait_event_tracing%';"); +} + +my $KiB = 1024; +my $MiB = 1024 * $KiB; + +my $baseline = pwet_footprint(); +is($baseline, '0', + "no pg_wait_event_tracing shared memory before any backend captures"); + +# One session enables stats and records a single wait. This is what +# creates the control segment and the stats DSA area in the first +# place. +my $s1 = $node->background_psql('postgres'); +$s1->query_safe("SET pg_wait_event_tracing.capture = stats;"); +$s1->query_safe("SELECT pg_sleep(0.01);"); +my $s1_pid = $s1->query_safe("SELECT pg_backend_pid();"); + +my $after_s1 = pwet_footprint(); +cmp_ok($after_s1 - $baseline, '<', 4 * $MiB, + "one capturing backend's footprint stays well under the dense " + . "design's per-max_connections bound"); + +# A second session enabling stats should only need its own payload +# (already sized well under 512 KiB), not another whole DSA segment on +# top of the first. +my $s2 = $node->background_psql('postgres'); +$s2->query_safe("SET pg_wait_event_tracing.capture = stats;"); +# Attach through the next statement's parse analysis, so this +# measurement does not depend on whether the SET itself attached, +# and confirm the session really is collecting before measuring. +$s2->query_safe("SELECT pg_sleep(0.01);"); +my $s2_pid = $s2->query_safe("SELECT pg_backend_pid();"); +is( $node->safe_psql( + 'postgres', + "SELECT count(*) > 0 FROM pg_stat_wait_event_timing " + . "WHERE pid = $s2_pid;"), + 't', + "session s2 is collecting before its footprint is measured"); + +my $after_s2 = pwet_footprint(); +cmp_ok($after_s2 - $after_s1, '<', 512 * $KiB, + "a second capturing backend adds only its own payload, not another " + . "DSA segment"); + +# Turning capture off releases the first backend's payload; its pid +# must disappear from the view even though nothing else about the +# backend changed (fix 2's ownership check, exercised here via fix 1's +# release path). +$s1->query_safe("SET pg_wait_event_tracing.capture = off;"); +my $s1_rows = $node->safe_psql('postgres', + "SELECT count(*) FROM pg_stat_wait_event_timing WHERE pid = $s1_pid;"); +is($s1_rows, '0', + "disabling capture removes the backend's rows from the timing view"); + +# A third session enabling stats should reuse the freed payload rather +# than growing the DSA area again. +my $s3 = $node->background_psql('postgres'); +$s3->query_safe("SET pg_wait_event_tracing.capture = stats;"); +# Attach through the next statement's parse analysis, so this +# measurement does not depend on whether the SET itself attached, +# and confirm the session really is collecting before measuring. +$s3->query_safe("SELECT pg_sleep(0.01);"); +my $s3_pid = $s3->query_safe("SELECT pg_backend_pid();"); +is( $node->safe_psql( + 'postgres', + "SELECT count(*) > 0 FROM pg_stat_wait_event_timing " + . "WHERE pid = $s3_pid;"), + 't', + "session s3 is collecting before its footprint is measured"); + +my $after_s3 = pwet_footprint(); +cmp_ok($after_s3, '<=', $after_s2, + "a third capturing backend reuses the freed payload instead of " + . "growing the footprint"); + +$s1->quit; +$s2->quit; +$s3->quit; + +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/002_ownership.pl b/contrib/pg_wait_event_tracing/t/002_ownership.pl new file mode 100644 index 00000000000..8f674da3a6d --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/002_ownership.pl @@ -0,0 +1,199 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: ownership across ProcNumber reuse (fix 2). +# +# The always-resident control slot for a ProcNumber records +# owner_pid/owner_start alongside the DSA payload pointer, and every +# reader compares them against the live PgBackendStatus entry before +# trusting the payload, so a successor never gets attributed a +# predecessor's counters, even before it has attached its own payload. +# This test quits a capturing backend and then hunts for a successor +# that reused its ProcNumber, to drive that comparison for real, and +# checks both readers -- a superuser, and the backend reading about +# itself -- see the right thing at each step. +# +# PGPROC's free list is FIFO, not LIFO: InitProcess() pops the head +# (src/backend/storage/lmgr/proc.c) and ProcKill() pushes to the tail, +# so a freed ProcNumber is only handed out again once every other free +# slot has been used first. max_connections is kept small here so that +# "every other free slot" is a short list, and B is found by opening +# candidate connections in a loop -- each checks its own ProcNumber and +# is dropped if it isn't the one being waited for -- up to a generous, +# bounded number of attempts. +# +# B's own activity below never uses pg_sleep(): pg_sleep() loops, +# calling WaitLatch again until its own clock says the requested time +# is up, and on some platforms (seen on Windows in CI) the latch +# timeout and that clock can disagree, so it loops and records more +# than one wait for a single call. The module is right to count every +# one of them, but that makes "exactly one PgSleep wait" an unsafe +# thing to assert, so B is driven with plain statements instead and +# checked only for "at least one row" and "no PgSleep row at all". + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $max_connections = 10; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init(auth_extra => ['--create-role', 'regress_a,regress_b']); +$node->append_conf('postgresql.conf', + "shared_preload_libraries = 'pg_wait_event_tracing'"); +$node->append_conf('postgresql.conf', "max_connections = $max_connections"); +# Keep pg_sleep() running in the session that issued it, not a parallel +# worker, so its wait is recorded under the pid this test is watching. +$node->append_conf('postgresql.conf', "debug_parallel_query = off"); +$node->start; +$node->safe_psql( + 'postgres', q( +CREATE EXTENSION pg_wait_event_tracing; +CREATE ROLE regress_a LOGIN; +CREATE ROLE regress_b LOGIN; +-- pg_wait_event_tracing.capture is PGC_SUSET, so a non-superuser needs +-- an explicit SET grant to toggle it; both roles do below. +GRANT SET ON PARAMETER pg_wait_event_tracing.capture TO regress_a, regress_b; +)); + +# Session A: one recorded wait, then note its pid and ProcNumber. +my $A = $node->background_psql( + 'postgres', + connstr => $node->connstr('postgres') . ' user=regress_a'); +$A->query_safe("SET pg_wait_event_tracing.capture = stats;"); +$A->query_safe("SELECT pg_sleep(0.01);"); +my $a_pid = $A->query_safe("SELECT pg_backend_pid();"); +my $a_procnumber = $node->safe_psql( + 'postgres', + "SELECT procnumber FROM pg_stat_wait_event_timing " + . "WHERE pid = $a_pid AND wait_event = 'PgSleep';"); + +$A->quit; +$node->poll_query_until( + 'postgres', + "SELECT NOT EXISTS (SELECT 1 FROM pg_stat_activity WHERE pid = $a_pid);" +) or die "backend $a_pid did not disappear from pg_stat_activity"; + +# Open candidate regress_b connections, one at a time, until one lands +# on A's ProcNumber -- pg_stat_get_backend_idset()'s id is the same +# proc_number the module's own "procnumber" column reports -- or the +# budget below is exhausted. A candidate that isn't the one wanted is +# dropped immediately, before enabling capture, so it does not itself +# perturb the free list any more than opening and closing one +# connection already does. +my $B; +my $attempts = 0; +my $max_attempts = 3 * $max_connections; +while ($attempts < $max_attempts) +{ + $attempts++; + my $candidate = $node->background_psql( + 'postgres', + connstr => $node->connstr('postgres') . ' user=regress_b'); + my $candidate_procnumber = $candidate->query_safe( + "SELECT id FROM pg_stat_get_backend_idset() AS id " + . "WHERE pg_stat_get_backend_pid(id) = pg_backend_pid();"); + if ($candidate_procnumber eq $a_procnumber) + { + $B = $candidate; + last; + } + $candidate->quit; +} + +SKIP: +{ + skip "ProcNumber $a_procnumber was not reused by any of $attempts " + . "regress_b connections; cannot exercise the reuse path in this run", + 9 + unless defined $B; + + my $b_pid = $B->query_safe("SELECT pg_backend_pid();"); + + # B has not enabled capture yet. + is( $node->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_stat_wait_event_timing WHERE pid = $b_pid;" + ), + '0', + "B has no timing rows before enabling capture"); + is( $node->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_stat_wait_event_timing_overflow " + . "WHERE pid = $b_pid;" + ), + '0', + "B has no overflow rows before enabling capture"); + + # Now B enables capture. Two trivial statements: the first attaches + # (post_parse_analyze_hook picks it up; the SET's own assign hook + # does not reliably, see 001_memory.pl), and sending the second is + # what makes the ClientRead wait *between* them -- now that a + # payload exists to record into -- complete and show up as a row. + $B->query_safe("SET pg_wait_event_tracing.capture = stats;"); + $B->query_safe("SELECT 1;"); + $B->query_safe("SELECT 1;"); + + my $b_procnumber = $node->safe_psql( + 'postgres', + "SELECT procnumber FROM pg_stat_wait_event_timing " + . "WHERE pid = $b_pid LIMIT 1;"); + is($b_procnumber, $a_procnumber, + "B's own procnumber column agrees with the ProcNumber the loop found" + ); + + # B has some row of its own fresh activity, but never a PgSleep row + # -- it never called pg_sleep -- so a PgSleep row here could only be + # A's leftover data. Checked both as the superuser reader and by B + # reading about itself via the function directly (the view is + # revoked from PUBLIC, so the latter exercises the self-privilege + # branch of the internal check rather than a granted view or + # pg_read_all_stats membership). + cmp_ok( + $node->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_stat_wait_event_timing WHERE pid = $b_pid;" + ), + '>', 0, + "superuser reader sees at least one row for B"); + is( $node->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_stat_wait_event_timing " + . "WHERE pid = $b_pid AND wait_event = 'PgSleep';" + ), + '0', + "...but no PgSleep row, which would only be A's leftover data"); + cmp_ok( + $B->query_safe( + "SELECT count(*) FROM pg_stat_get_wait_event_timing(pg_backend_pid());" + ), + '>', 0, + "B itself sees at least one row via the function"); + is( $B->query_safe( + "SELECT count(*) FROM pg_stat_get_wait_event_timing(pg_backend_pid()) " + . "WHERE wait_event = 'PgSleep';" + ), + '0', + "...and no PgSleep row there either, despite no view grant" + ); + + # The view itself stays off limits to a role with no + # pg_read_all_stats, unlike the function form used above. A + # one-shot connection is used rather than B's own background_psql + # session: BackgroundPsql starts psql with on_error_stop => 1, so + # the permission error would make psql exit, and the next call into + # $B would die with "process ended prematurely". + my ($ret, $out, $err) = $node->psql( + 'postgres', + 'SELECT * FROM pg_stat_wait_event_timing;', + connstr => $node->connstr('postgres') . ' user=regress_b'); + isnt($ret, 0, "B cannot read the view directly"); + like($err, qr/permission denied/, + "...only the function about itself, as shown above"); + + $B->quit; +} + +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/003_reset_acl.pl b/contrib/pg_wait_event_tracing/t/003_reset_acl.pl new file mode 100644 index 00000000000..60aab569a3f --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/003_reset_acl.pl @@ -0,0 +1,231 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: reset authorization (fix 4). +# +# pg_stat_reset_wait_event_timing(pid) replicates pg_signal_backend()'s +# target-authorization rule: a non-superuser cannot touch a +# superuser-owned or role-less target, and otherwise needs privileges of +# the target role or of pg_signal_backend. Resetting one's own backend +# (NULL or its own pid) always succeeds and is synchronous. A +# cross-backend reset is asynchronous: it only bumps a generation +# counter, and the target backend clears its own counters the next time +# it goes through wait_end(), so this test always drives the target +# through one more wait after a successful cross-backend reset before +# checking that its counters were cleared. pg_stat_reset_wait_event_timing_all() +# is superuser-only in C, independent of any EXECUTE grant. +# +# This exercises the cross-backend cases that the module's own regress +# test cannot: it has no second connection, and resetting one's own pid +# always takes the synchronous self-reset path regardless of role, so +# none of the authorization branches below are reachable from a single +# session. +# +# None of the assertions below treat "one pg_sleep(0.01) call" as "one +# recorded wait": pg_sleep() loops, calling WaitLatch again until its +# own clock says the requested time is up, and on some platforms (seen +# on Windows in CI) the latch timeout and that clock can disagree, so +# it loops and records more than one wait for a single call. The module +# is right to count every one of them, so a fixture or a post-reset +# check uses >= 1 (or compares against a value read just before the +# event in question) rather than an exact count; only reset_count, and +# a synchronous self-reset's calls == 0, are exact signals here. + +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(auth_extra => [ + '--create-role', + 'regress_a,regress_a2,regress_b,regress_sig,regress_su' + ]); +$node->append_conf('postgresql.conf', + "shared_preload_libraries = 'pg_wait_event_tracing'"); +# Keep pg_sleep() running in the session that issued it, not a parallel +# worker, so its wait is recorded under the pid this test is watching. +$node->append_conf('postgresql.conf', "debug_parallel_query = off"); +$node->start; +$node->safe_psql( + 'postgres', q( +CREATE EXTENSION pg_wait_event_tracing; +CREATE ROLE regress_su LOGIN SUPERUSER; +CREATE ROLE regress_a LOGIN; +CREATE ROLE regress_a2 LOGIN IN ROLE regress_a; +CREATE ROLE regress_b LOGIN; +CREATE ROLE regress_sig LOGIN IN ROLE pg_signal_backend; +-- pg_wait_event_tracing.capture is PGC_SUSET, so a non-superuser needs +-- an explicit SET grant to toggle it; regress_a and regress_b both do +-- below (the other three roles never SET it, only call the reset +-- functions). +GRANT SET ON PARAMETER pg_wait_event_tracing.capture TO regress_a, regress_b; +)); + +sub connect_as +{ + my ($role) = @_; + return $node->background_psql('postgres', + connstr => $node->connstr('postgres') . " user=$role"); +} + +sub pgsleep_calls +{ + my ($pid) = @_; + return $node->safe_psql( + 'postgres', + "SELECT coalesce((SELECT calls FROM pg_stat_wait_event_timing " + . "WHERE pid = $pid AND wait_event = 'PgSleep'), 0);"); +} + +sub reset_count +{ + my ($pid) = @_; + return $node->safe_psql('postgres', + "SELECT reset_count FROM pg_stat_wait_event_timing_overflow " + . "WHERE pid = $pid;"); +} + +# reset_as() issues a reset as $role against $target_pid on a one-shot +# connection: the request itself is a quick, synchronous lock-protected +# generation bump (no injection point involved here, unlike +# t/004_reset_race.pl), so there is no need to keep the actor's session +# alive. +sub reset_as +{ + my ($role, $target_pid) = @_; + return $node->psql( + 'postgres', + "SELECT pg_stat_reset_wait_event_timing($target_pid);", + connstr => $node->connstr('postgres') . " user=$role"); +} + +# Three live targets, each with capture enabled and one recorded wait. +my $SU = connect_as('regress_su'); +$SU->query_safe("SET pg_wait_event_tracing.capture = stats;"); +$SU->query_safe("SELECT pg_sleep(0.01);"); +my $su_pid = $SU->query_safe("SELECT pg_backend_pid();"); + +my $A = connect_as('regress_a'); +$A->query_safe("SET pg_wait_event_tracing.capture = stats;"); +$A->query_safe("SELECT pg_sleep(0.01);"); +my $a_pid = $A->query_safe("SELECT pg_backend_pid();"); + +my $B = connect_as('regress_b'); +$B->query_safe("SET pg_wait_event_tracing.capture = stats;"); +$B->query_safe("SELECT pg_sleep(0.01);"); +my $b_pid = $B->query_safe("SELECT pg_backend_pid();"); + +cmp_ok(pgsleep_calls($su_pid), '>=', 1, "fixture: SU has a recorded wait"); +cmp_ok(pgsleep_calls($a_pid), '>=', 1, "fixture: A has a recorded wait"); +cmp_ok(pgsleep_calls($b_pid), '>=', 1, "fixture: B has a recorded wait"); + +### +# own reset (NULL and own pid) by regress_b: succeeds, synchronously. +### +my $rc = reset_count($b_pid); +$B->query_safe("SELECT pg_stat_reset_wait_event_timing(NULL);"); +is(pgsleep_calls($b_pid), '0', "B's own NULL-reset clears its own counters"); +is(reset_count($b_pid), $rc + 1, "B's own NULL-reset bumps its reset_count"); + +$B->query_safe("SELECT pg_sleep(0.01);"); +$rc = reset_count($b_pid); +$B->query_safe("SELECT pg_stat_reset_wait_event_timing($b_pid);"); +is(pgsleep_calls($b_pid), '0', + "B's own-pid reset also clears its own counters"); +is(reset_count($b_pid), $rc + 1, "B's own-pid reset bumps its reset_count"); + +# Leave B primed with one wait for the regress_sig case below. +$B->query_safe("SELECT pg_sleep(0.01);"); + +### +# regress_a2 resets regress_a's session: succeeds (a2 is a member of a). +### +$rc = reset_count($a_pid); +my ($ret, $stdout, $stderr) = reset_as('regress_a2', $a_pid); +is($ret, 0, "regress_a2 can reset regress_a's session"); +is($stderr, '', "...with no error output"); + +$A->query_safe("SELECT pg_sleep(0.01);"); +cmp_ok(pgsleep_calls($a_pid), '>=', 1, + "A has a recorded wait again after the reset"); +is(reset_count($a_pid), $rc + 1, + "A's reset_count is the decisive signal that the cross-backend reset landed" +); + +### +# regress_sig resets regress_b's session: succeeds (sig is a member of +# pg_signal_backend). +### +$rc = reset_count($b_pid); +($ret, $stdout, $stderr) = reset_as('regress_sig', $b_pid); +is($ret, 0, "regress_sig can reset regress_b's session"); +is($stderr, '', "...with no error output"); + +$B->query_safe("SELECT pg_sleep(0.01);"); +cmp_ok(pgsleep_calls($b_pid), '>=', 1, + "B has a recorded wait again after the reset"); +is(reset_count($b_pid), $rc + 1, + "B's reset_count is the decisive signal that the cross-backend reset landed" +); + +### +# regress_b resets regress_su's session: permission denied (regress_b is +# neither superuser nor a member of pg_signal_backend, and the target is +# superuser-owned). +### +my $su_calls_before = pgsleep_calls($su_pid); +my $su_reset_before = reset_count($su_pid); +($ret, $stdout, $stderr) = reset_as('regress_b', $su_pid); +isnt($ret, 0, "regress_b cannot reset regress_su's session"); +like($stderr, qr/permission denied/, "...permission denied error"); +is(pgsleep_calls($su_pid), $su_calls_before, + "SU's calls are untouched by the failed attempt"); +is(reset_count($su_pid), $su_reset_before, + "SU's reset_count is untouched by the failed attempt"); + +### +# regress_b resets regress_a's session: permission denied (regress_b has +# privileges of neither regress_a nor pg_signal_backend). +### +my $a_calls_before = pgsleep_calls($a_pid); +my $a_reset_before = reset_count($a_pid); +($ret, $stdout, $stderr) = reset_as('regress_b', $a_pid); +isnt($ret, 0, "regress_b cannot reset regress_a's session"); +like($stderr, qr/permission denied/, "...permission denied error"); +is(pgsleep_calls($a_pid), $a_calls_before, + "A's calls are untouched by the failed attempt"); +is(reset_count($a_pid), $a_reset_before, + "A's reset_count is untouched by the failed attempt"); + +### +# Any role resetting the checkpointer's pid gets pg_signal_backend()'s +# own WARNING wording, not an error: BackendPidGetProc() only resolves +# normal backends, so auxiliary pids are rejected before any ACL check +# even runs. +### +my $checkpointer_pid = $node->safe_psql('postgres', + "SELECT pid FROM pg_stat_activity WHERE backend_type = 'checkpointer';" +); +($ret, $stdout, $stderr) = reset_as('regress_b', $checkpointer_pid); +is($ret, 0, "resetting the checkpointer's pid is not an error"); +like($stderr, qr/is not a PostgreSQL backend process/, + "...but does warn that it is not a backend"); + +### +# regress_b calling pg_stat_reset_wait_event_timing_all() is an error: +# it hard-requires superuser() in C, regardless of any EXECUTE grant. +### +($ret, $stdout, $stderr) = $node->psql( + 'postgres', + "SELECT pg_stat_reset_wait_event_timing_all();", + connstr => $node->connstr('postgres') . ' user=regress_b'); +isnt($ret, 0, "regress_b cannot call the _all() reset"); +like($stderr, qr/permission denied/, "...permission denied error"); + +$SU->quit; +$A->quit; +$B->quit; + +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/004_reset_race.pl b/contrib/pg_wait_event_tracing/t/004_reset_race.pl new file mode 100644 index 00000000000..dcbf1c50746 --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/004_reset_race.pl @@ -0,0 +1,165 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: reset race across ProcNumber reuse (fix 5). +# +# A cross-backend reset is published as a generation bump under the +# control lock, but the pid/start-timestamp used to resolve the target +# were captured earlier, outside that lock. If a successor reuses the +# target's ProcNumber in the window between resolution and taking the +# lock, the request must not land on the successor: pwet_request_reset() +# re-checks owner_pid/owner_start against the resolved target under the +# same lock that publishes the bump, so a mismatch (successor already +# attached) leaves the slot alone. +# +# This test forces exactly that window open with the +# "pg-wait-event-tracing-reset-before-publish" injection point (placed +# between resolution and taking the lock -- see pg_wait_event_tracing.c), +# swaps in a successor while the requester is parked there, and checks +# the successor's own counters and reset_count come out untouched. +# +# PGPROC's free list is FIFO, not LIFO: InitProcess() pops the head +# (src/backend/storage/lmgr/proc.c) and ProcKill() pushes to the tail, +# so a freed ProcNumber is only handed out again once every other free +# slot has been used first. max_connections is kept small here so that +# "every other free slot" is a short list, and the successor is found +# by opening candidate connections in a loop, while the requester is +# still parked, until one lands on the target's ProcNumber or a +# generous, bounded number of attempts is exhausted. +# +# The final PgSleep count below is asserted as >= 3, not = 3: pg_sleep() +# loops, calling WaitLatch again until its own clock says the requested +# time is up, and on some platforms (seen on Windows in CI) the latch +# timeout and that clock can disagree, so a single call can record more +# than one wait. The module is right to count every one of them; what +# this test actually needs decided is reset_count, which stays an exact +# 0 either way. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +plan skip_all => 'Injection points not supported by this build' + unless $ENV{enable_injection_points} eq 'yes'; + +my $max_connections = 10; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf('postgresql.conf', + "shared_preload_libraries = 'pg_wait_event_tracing, injection_points'"); +$node->append_conf('postgresql.conf', "max_connections = $max_connections"); +# Keep pg_sleep() running in the session that issued it, not a parallel +# worker, so its wait is recorded under the pid this test is watching. +$node->append_conf('postgresql.conf', "debug_parallel_query = off"); +$node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing;'); +$node->safe_psql('postgres', 'CREATE EXTENSION injection_points;'); + +my $point = 'pg-wait-event-tracing-reset-before-publish'; + +# A: one recorded wait, then note its pid and ProcNumber. +my $A = $node->background_psql('postgres'); +$A->query_safe("SET pg_wait_event_tracing.capture = stats;"); +$A->query_safe("SELECT pg_sleep(0.01);"); +my $a_pid = $A->query_safe("SELECT pg_backend_pid();"); +my $a_procnumber = $node->safe_psql( + 'postgres', + "SELECT procnumber FROM pg_stat_wait_event_timing " + . "WHERE pid = $a_pid AND wait_event = 'PgSleep';"); + +# R: a superuser session that attaches the injection point and then +# starts a reset of A's session, which will block right before +# publishing the request. +my $R = $node->background_psql('postgres'); +$R->query_safe("SELECT injection_points_attach('$point', 'wait');"); +$R->query_until( + qr/reset_launched/, + "\\echo reset_launched\n" + . "SELECT pg_stat_reset_wait_event_timing($a_pid);\n"); + +$node->wait_for_event('client backend', $point); + +# While R is parked at the injection point, replace A with B. +$A->quit; +$node->poll_query_until('postgres', + "SELECT NOT EXISTS (SELECT 1 FROM pg_stat_activity WHERE pid = $a_pid);" +) or die "backend $a_pid did not disappear from pg_stat_activity"; + +# Open candidate connections, one at a time, until one lands on A's +# ProcNumber -- pg_stat_get_backend_idset()'s id is the same +# proc_number the module's own "procnumber" column reports -- or the +# budget below is exhausted. Each candidate runs only this query. +my $B; +my $attempts = 0; +my $max_attempts = 3 * $max_connections; +while ($attempts < $max_attempts) +{ + $attempts++; + my $candidate = $node->background_psql('postgres'); + my $candidate_procnumber = $candidate->query_safe( + "SELECT id FROM pg_stat_get_backend_idset() AS id " + . "WHERE pg_stat_get_backend_pid(id) = pg_backend_pid();"); + if ($candidate_procnumber eq $a_procnumber) + { + $B = $candidate; + last; + } + $candidate->quit; +} + +my $b_pid; +if (defined $B) +{ + # Attach with a fresh owner token while R is still parked, so that + # when R's stale request does reach the lock below, it finds this + # ProcNumber already reassigned rather than merely unowned. + $B->query_safe("SET pg_wait_event_tracing.capture = stats;"); + $B->query_safe("SELECT pg_sleep(0.01);"); + $B->query_safe("SELECT pg_sleep(0.01);"); + $b_pid = $B->query_safe("SELECT pg_backend_pid();"); +} + +# Now let R's stale request through, regardless of whether B was found +# above: R must not be left blocked at the injection point through the +# rest of the test (or its teardown). It targeted A's old owner +# token, which -- if B attached above -- has since been overwritten, +# so it must not touch B's slot. +$node->safe_psql('postgres', "SELECT injection_points_wakeup('$point');"); +$R->quit; + +SKIP: +{ + skip "ProcNumber $a_procnumber was not reused by any of $attempts " + . "connections; cannot exercise the race in this run", 2 + unless defined $B; + + # One more wait after the release, so a wrongly-applied reset (which + # would only be noticed at the *next* wait_end -- see + # t/003_reset_acl.pl) has every opportunity to show up here too. + $B->query_safe("SELECT pg_sleep(0.01);"); + + cmp_ok( + $node->safe_psql( + 'postgres', + "SELECT calls FROM pg_stat_wait_event_timing " + . "WHERE pid = $b_pid AND wait_event = 'PgSleep';" + ), + '>=', 3, + "B's PgSleep count reflects all three of its own waits"); + is( $node->safe_psql( + 'postgres', + "SELECT reset_count FROM pg_stat_wait_event_timing_overflow " + . "WHERE pid = $b_pid;" + ), + '0', + "the reset aimed at A's stale token was not consumed by B"); + + $B->quit; +} + +$node->safe_psql('postgres', "SELECT injection_points_detach('$point');"); + +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/006_server_processes.pl b/contrib/pg_wait_event_tracing/t/006_server_processes.pl new file mode 100644 index 00000000000..55961dccd04 --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/006_server_processes.pl @@ -0,0 +1,222 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Server-side processes (the checkpointer, background writer, WAL writer, +# I/O workers, and -- during recovery -- the startup process) never parse +# a query or run the executor, so they cannot attach through the same +# entry points a client backend uses. Plan section 4.2a's "option A": +# when pg_wait_event_tracing.capture is already non-off in the +# configuration at postmaster start, the module additionally reserves a +# fixed-size region with one slot per possible server-side ProcNumber, and +# each such process claims its own slot the first time it waits on +# anything -- so these processes collect from process start, with no +# configuration reload ever required. +# +# This test exercises that reserved-region path (node1, cases 1-3) and its +# fallback for a node that starts with capture off, where server-side +# processes instead pick up capture at the next reload the same way a +# client backend would on its next statement (node2, case 4) -- the +# scenario that depends on pwet_assign_capture() using the *incoming* +# capture value, not the not-yet-stored GUC variable, to decide whether it +# is safe to attach synchronously (see pwet_capture_effective in +# pg_wait_event_tracing.c). + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; +use Time::HiRes qw(usleep); + +# --------------------------------------------------------------------- +# node1: capture = stats already in postgresql.conf at postmaster start. +# --------------------------------------------------------------------- +my $node1 = PostgreSQL::Test::Cluster->new('node1'); +$node1->init(allows_streaming => 1); +$node1->append_conf( + 'postgresql.conf', qq( +shared_preload_libraries = 'pg_wait_event_tracing' +pg_wait_event_tracing.capture = 'stats' +debug_parallel_query = off +)); +$node1->start; + +$node1->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing'); + +# A little write activity, plus an explicit checkpoint, gives the +# checkpointer, background writer and WAL writer something to do promptly +# rather than relying on their default multi-second/multi-minute idle +# cycles (checkpoint_timeout defaults to 5 minutes). I/O workers need no +# such nudge: io_min_workers keeps at least two of them alive from server +# start, idling in their own main loop (wait event IO_WORKER_MAIN) even +# with no read/write demand at all. +$node1->safe_psql( + 'postgres', q( + CREATE TABLE wet_activity AS + SELECT i, repeat('x', 100) AS pad FROM generate_series(1, 10000) i; + CHECKPOINT; +)); + +# Case 1: rows for checkpointer, walwriter, background writer, and an I/O +# worker, despite this node never having reloaded its configuration. +for my $backend_type (qw(checkpointer walwriter), 'background writer') +{ + # None of these fixed literal values need SQL-escaping. + ok( $node1->poll_query_until( + 'postgres', + "SELECT EXISTS (SELECT 1 FROM pg_stat_wait_event_timing WHERE backend_type = '$backend_type')" + ), + "$backend_type has rows in pg_stat_wait_event_timing without a reload" + ); +} + +# I/O workers only exist under io_method = worker; several CI jobs force +# io_method = io_uring via PG_TEST_INITDB_EXTRA_OPTS, which has none, so +# this check would otherwise time out there instead of failing cleanly. +my $io_method = $node1->safe_psql('postgres', 'SHOW io_method'); +SKIP: +{ + skip "io_method is '$io_method', not 'worker': no I/O workers exist", 1 + unless $io_method eq 'worker'; + + ok( $node1->poll_query_until( + 'postgres', + q(SELECT EXISTS (SELECT 1 FROM pg_stat_wait_event_timing WHERE backend_type = 'io worker')) + ), + 'io worker has rows in pg_stat_wait_event_timing without a reload' + ); +} + +# Case 2: pg_shmem_allocations shows the reserved region, at least as +# large as |R| slots at a conservative lower bound for the per-slot +# stride. |R| = autovacuum_worker_slots + NUM_SPECIAL_WORKER_PROCS (2) + +# max_worker_processes + max_wal_senders + PWET_NON_IO_AUX_PROCS (6) + +# io_max_workers (plan section 4.2a; the "2" and "6" are proc.h constants, +# not GUCs, so they are literals here too). 200000 bytes/slot is +# comfortably below the ~206-212 KiB the C code actually computes at the +# default pg_wait_event_tracing.max_tranches (192) on every platform this +# has been checked on, without this test having to reproduce that +# platform-dependent struct-layout arithmetic itself. +my $num_server_slots = $node1->safe_psql( + 'postgres', q( + SELECT current_setting('autovacuum_worker_slots')::int + + 2 + + current_setting('max_worker_processes')::int + + current_setting('max_wal_senders')::int + + 6 + + current_setting('io_max_workers')::int +)); + +my $region_row = $node1->safe_psql( + 'postgres', q( + SELECT size FROM pg_shmem_allocations + WHERE name = 'pg_wait_event_tracing server processes' +)); + +ok(length($region_row), 'server-process region is present in pg_shmem_allocations'); +cmp_ok($region_row, '>=', $num_server_slots * 200000, + 'server-process region is at least |R| slots wide'); + +# Case 3: a standby created from a base backup of node1 (same +# configuration, capture already on) shows startup-process recovery waits +# without any reload on the standby either. +my $backup_name = 'node1_backup'; +$node1->backup($backup_name); + +my $node_standby = PostgreSQL::Test::Cluster->new('standby'); +$node_standby->init_from_backup($node1, $backup_name, has_streaming => 1); +$node_standby->start; + +# Give the standby's startup process WAL to keep applying/waiting on. +$node1->safe_psql( + 'postgres', q( + INSERT INTO wet_activity SELECT i, repeat('y', 100) FROM generate_series(1, 10000) i; +)); +$node1->wait_for_replay_catchup($node_standby); + +# A plain poll_query_until() here can time out unconditionally, no matter +# how long it waits: with deferred accounting, a completed wait's counters +# are written out only at the backend's own *next* wait_start, and once +# the standby is caught up its only further wait, +# WaitForWALToBecomeAvailable()'s streaming-source wait, has no timeout at +# all -- so with nothing later to trigger a flush, the one-shot INSERT +# above can leave the row never appearing at all. +# +# Keep sending small bursts of WAL from the primary while polling, so the +# startup process keeps re-entering that wait: each new wait's begin +# flushes the previous one, so the row appears within a couple of +# iterations regardless of runner speed. +my $standby_startup_has_rows = 0; +for (my $attempts = 0; + $attempts < 10 * $PostgreSQL::Test::Utils::timeout_default; + $attempts++) +{ + if ($node_standby->safe_psql( + 'postgres', + q(SELECT EXISTS (SELECT 1 FROM pg_stat_wait_event_timing WHERE backend_type = 'startup')) + ) eq 't') + { + $standby_startup_has_rows = 1; + last; + } + + # Nudge the startup process into another wait/flush cycle. + $node1->safe_psql('postgres', + q(INSERT INTO wet_activity SELECT i FROM generate_series(1, 10) i)); + $node1->wait_for_replay_catchup($node_standby); + usleep(100_000); +} + +ok($standby_startup_has_rows, + 'standby startup process has rows in pg_stat_wait_event_timing without a reload' +); + +# --------------------------------------------------------------------- +# node2: capture off at postmaster start -- no region is ever reserved, +# so server-side processes fall back to attaching via the DSA path at the +# next configuration reload, exactly like a client backend attaching on +# its next statement. +# --------------------------------------------------------------------- +my $node2 = PostgreSQL::Test::Cluster->new('node2'); +$node2->init; +$node2->append_conf( + 'postgresql.conf', qq( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +)); +$node2->start; + +$node2->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing'); + +is( $node2->safe_psql( + 'postgres', q( + SELECT count(*) FROM pg_shmem_allocations + WHERE name = 'pg_wait_event_tracing server processes' + )), + '0', + 'no server-process region exists when capture starts off'); + +$node2->safe_psql( + 'postgres', q( + ALTER SYSTEM SET pg_wait_event_tracing.capture = 'stats'; + SELECT pg_reload_conf(); +)); + +$node2->safe_psql( + 'postgres', q( + CREATE TABLE wet_activity2 AS SELECT i FROM generate_series(1, 1000) i; + CHECKPOINT; +)); + +ok( $node2->poll_query_until( + 'postgres', + q(SELECT EXISTS (SELECT 1 FROM pg_stat_wait_event_timing WHERE backend_type = 'checkpointer')) + ), + 'checkpointer has rows after capture is turned on by a reload' +); + +$node_standby->stop; +$node1->stop; +$node2->stop; + +done_testing(); diff --git a/contrib/pg_wait_event_tracing/t/007_lazy_hooks.pl b/contrib/pg_wait_event_tracing/t/007_lazy_hooks.pl new file mode 100644 index 00000000000..3f1b30e8889 --- /dev/null +++ b/contrib/pg_wait_event_tracing/t/007_lazy_hooks.pl @@ -0,0 +1,113 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# pg_wait_event_tracing: lazy, per-process wait-hook installation. A +# process installs its wait_event_begin_hook/ +# wait_event_end_hook the first time pg_wait_event_tracing.capture becomes +# non-off in that process, and never removes them again; a process that +# never enables capture never installs them at all. +# +# This node starts with capture off, so nothing installs its hooks at +# postmaster start (unlike t/006_server_processes.pl's node1). Session A +# enables stats and records a wait; session B never touches capture. B's +# pg_wait_event_tracing_hooks_installed() must be false, and B must have +# no rows in pg_stat_wait_event_timing, even though A does. A subsequent +# reload that turns capture on cluster-wide then makes B install its own +# hooks too, at its next safe point -- exactly the "capture set by reload" +# scenario (d) from the pg_wait_event_tracing.c commit that added this +# lazy installation. + +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', qq( +shared_preload_libraries = 'pg_wait_event_tracing' +debug_parallel_query = off +)); +$node->start; + +$node->safe_psql('postgres', 'CREATE EXTENSION pg_wait_event_tracing'); + +# Two long-lived sessions, so each one's own hook-installation state (a +# process-local flag) can be probed on that same backend before and after +# the reload below. +my $a = $node->background_psql('postgres'); +my $b = $node->background_psql('postgres'); + +my $a_pid = $a->query_safe('SELECT pg_backend_pid();'); +my $b_pid = $b->query_safe('SELECT pg_backend_pid();'); + +# Session A enables stats and records a deterministic wait. +$a->query_safe('SET pg_wait_event_tracing.capture = stats;'); +$a->query_safe('SELECT pg_sleep(0.01);'); + +is($a->query_safe('SELECT pg_wait_event_tracing_hooks_installed();'), + 't', 'session A has installed its wait hooks after enabling stats'); + +is( $node->safe_psql( + 'postgres', + "SELECT count(*) > 0 FROM pg_stat_wait_event_timing WHERE pid = $a_pid;" + ), + 't', + 'session A has rows in pg_stat_wait_event_timing'); + +# Session B never enabled capture, so it never installed its hooks, and it +# has no rows of its own. +is($b->query_safe('SELECT pg_wait_event_tracing_hooks_installed();'), + 'f', 'session B has not installed its wait hooks'); + +is( $node->safe_psql( + 'postgres', + "SELECT count(*) FROM pg_stat_wait_event_timing WHERE pid = $b_pid;" + ), + '0', + 'session B has no rows in pg_stat_wait_event_timing'); + +# A cluster-wide reload turning capture on: every process, including B, +# installs from its own assign hook at its next safe point (scenario (d) +# in the pg_wait_event_tracing.c commit comment). +$node->safe_psql( + 'postgres', q( + ALTER SYSTEM SET pg_wait_event_tracing.capture = 'stats'; + SELECT pg_reload_conf(); +)); + +# pg_reload_conf() only asks the postmaster to signal every backend with +# SIGHUP; it does not wait for any of them to actually act on it. Each +# backend, including session B's, only re-reads its configuration (and so +# only runs pwet_assign_capture() again) the next time it checks for +# interrupts -- in practice, the next command it processes -- which can +# be an arbitrarily short but non-zero time after this call returns. A +# single immediate query_safe() can therefore observe the pre-reload 'f' +# on a slow or loaded runner even though B is about to install its hooks; +# poll instead, the same bounded way Cluster.pm's poll_query_until() does +# (up to $PostgreSQL::Test::Utils::timeout_default seconds, sleeping +# 0.1s between attempts), but running the query on B's own background +# session rather than a fresh connection, since the installed-hooks flag +# is process-local to B. +my $b_installed = 'f'; +for (my $attempts = 0; + $attempts < 10 * $PostgreSQL::Test::Utils::timeout_default; + $attempts++) +{ + $b_installed = + $b->query_safe('SELECT pg_wait_event_tracing_hooks_installed();'); + last if $b_installed eq 't'; + usleep(100_000); +} +ok( $b_installed eq 't', + 'session B installs its wait hooks once capture is turned on by a reload' +); + +$a->quit; +$b->quit; +$node->stop; + +done_testing(); diff --git a/doc/src/sgml/contrib.sgml b/doc/src/sgml/contrib.sgml index b9b03654aad..cd6fdc9ed7e 100644 --- a/doc/src/sgml/contrib.sgml +++ b/doc/src/sgml/contrib.sgml @@ -165,6 +165,7 @@ CREATE EXTENSION extension_name; &pgsurgery; &pgtrgm; &pgvisibility; + &pgwaiteventtracing; &pgwalinspect; &postgres-fdw; &seg; diff --git a/doc/src/sgml/filelist.sgml b/doc/src/sgml/filelist.sgml index 0797dcf96da..7248e0a1cab 100644 --- a/doc/src/sgml/filelist.sgml +++ b/doc/src/sgml/filelist.sgml @@ -158,6 +158,7 @@ + diff --git a/doc/src/sgml/pgwaiteventtracing.sgml b/doc/src/sgml/pgwaiteventtracing.sgml new file mode 100644 index 00000000000..a2050eb605e --- /dev/null +++ b/doc/src/sgml/pgwaiteventtracing.sgml @@ -0,0 +1,1608 @@ + + + + pg_wait_event_tracing — statistics and trace collection for explicitly instrumented wait events + + + pg_wait_event_tracing + + + + pg_wait_event_tracing records what individual + backends actually waited on, and for how long. It uses the + pgstat_report_wait_start_timed/pgstat_report_wait_end_timed + hook pair (see ) rather than + sampling pg_stat_activity, so it never misses a + wait, however short, and needs no separate sampling process. + + + + The module has three levels, controlled by + , each a strict + superset of the one before it: + + + + + + off (the default): no collection. + + + + + stats: exact per-backend wait statistics — + a call count, total duration, maximum duration, and a 32-bucket + duration histogram — kept separately for every distinct + wait event (and, for LWLock, every distinct + tranche) the backend has waited on. Because every wait is counted, + not sampled, these numbers are exact, not an estimate. + + + + + trace: additionally, an ordered, fixed-size ring + buffer per backend recording every individual completed wait + (timestamp, event, duration), interleaved with query-attribution + markers that record when statements, executor calls, utility + commands, and transactions start and end, so that waits can be + grouped by the statement that incurred them. + + + + + + Loading the Module + + + pg_wait_event_tracing needs additional shared + memory whenever collection is or might become active, so it must be + loaded via : + +shared_preload_libraries = 'pg_wait_event_tracing' + + which requires a server restart. If the module's functions are + installed (see below) without it having been preloaded, every + attempt to use them fails at load time with an error, the same + wording pg_stat_statements and + sepgsql use for the same situation + (pg_wait_event_tracing must be loaded via + "shared_preload_libraries"). + + + + Collection itself is cluster-wide and independent of which database, + if any, has the extension installed — every backend in the + cluster is a candidate for collection once + pg_wait_event_tracing.capture is not + off. CREATE EXTENSION + pg_wait_event_tracing only needs to be run once, in + whichever database will be used to query the views and functions + described below, to install those SQL objects into that database's + catalog. + + + + Being preloaded in every process is not the same as every process + paying for collection: a process installs its wait-event hooks the + first time pg_wait_event_tracing.capture becomes + non-off in that process, and + keeps them installed for the rest of its life even if capture is later + turned back off there. A backend that never enables capture, in a + cluster where most sessions never do, therefore runs with the hooks + absent and pays no per-wait overhead for this module at all; see + pg_wait_event_tracing_hooks_installed() to check + a given backend. + + + + The module defines three configuration parameters, described in + detail where each is most relevant below and summarized here: + + + + + + pg_wait_event_tracing.capture (enum) + + pg_wait_event_tracing.capture configuration parameter + + + + + Selects the collection level: off (default), + stats, or trace. Context + SUSET: it can be changed by a superuser, by a + role granted SET privilege on the parameter + (GRANT SET ON PARAMETER pg_wait_event_tracing.capture TO + ...), in postgresql.conf, or via + ALTER SYSTEM/ALTER + DATABASE/ALTER ROLE ... SET. An + ordinary client backend that issues SET + pg_wait_event_tracing.capture = ... directly takes + effect for that session at its next parse/executor safe point (in + practice, its very next statement); a change delivered only + through the configuration file takes effect for a given backend + only once that backend processes a configuration reload (or, for + a newly forked backend, at connection time). Read access to the + resulting statistics and trace data is controlled separately, + through the views and functions' own grants (see + ) and membership in + pg_read_all_stats, + not by this parameter. + + + + + + + pg_wait_event_tracing.max_tranches (integer) + + pg_wait_event_tracing.max_tranches configuration parameter + + + + + Maximum number of distinct LWLock tranches + tracked individually, per collecting backend. Context + POSTMASTER: it can only be set at server + start, since it determines the size of the per-backend payload + (see ). The default + is 192, with a minimum of 16 + and a maximum of 65534. A tranche encountered + once the per-backend table is already full is counted in + lwlock_overflow_count instead (see + ). + + + + + + + pg_wait_event_tracing.trace_ring_size (integer) + + pg_wait_event_tracing.trace_ring_size configuration parameter + + + + + Size of each backend's trace ring, used only at the + trace level. Context + POSTMASTER. If specified without units it is + taken as kilobytes; the value must be a power of two (each record + is 32 bytes, so this is equivalent to requiring a power-of-two + record count). The default is 4096 (4 MB, + 131072 records), the minimum 8, the maximum + 32768 (32 MB). A larger ring retains a + longer history before the oldest records are overwritten. + + + + + + + + Views and Functions + + + Every view listed here is defined directly in terms of a same-named + (or obviously related) function, which can also be called on its + own with an explicit argument; the function reference notes any + difference in the two forms' default arguments or permissions. + + + + The <structname>pg_stat_wait_event_timing</structname> View + + + One row per (collecting backend, wait event) pair with at least + one recorded wait, drawn from + pg_stat_get_wait_event_timing(pid integer DEFAULT + NULL). Passing an explicit pid + (to the function; the view always passes NULL) + restricts the result to that one backend. + + + + <structname>pg_stat_wait_event_timing</structname> Columns + + + + + Column Type + + + Description + + + + + + + pid integer + + + Process ID of the backend. + + + + + backend_type text + + + Type of backend, using the same strings as the + backend_type column of + pg_stat_activity (for example + client backend, checkpointer, + walsender, autovacuum worker). + + + + + procnumber integer + + + The backend's process number. Pass this to + pg_get_wait_event_trace to read the + backend's trace ring, including after the backend has exited + (see ). + + + + + wait_event_type text + + + Wait event class, as in pg_stat_activity. + + + + + wait_event text + + + Wait event name within that class. + + + + + calls bigint + + + Number of completed waits of this type since the backend + started collecting or was last reset. + + + + + total_time_ms double precision + + + Total time spent in this wait event, in milliseconds. + + + + + avg_time_us double precision + + + total_time_ms × 1000 / + calls, in microseconds; computed on + read, not separately stored. + + + + + max_time_us double precision + + + Longest single wait of this type, in microseconds. + + + + + histogram bigint[] + + + 32-element array of per-bucket counts, in ascending order; see + for the + bucket boundaries. + + + + +
+ + + pg_stat_wait_event_timing itself is + restricted (REVOKE ALL ... FROM PUBLIC plus + GRANT SELECT ... TO pg_read_all_stats), but the + underlying pg_stat_get_wait_event_timing() + function keeps its ordinary, unrevoked PUBLIC + execute privilege; each row it would return is checked individually + against the calling role's privileges on that row's own backend + (has_privs_of_role of the owning role, or + membership in pg_read_all_stats) and dropped on a + mismatch. So any role can call the function directly with its own + pg_backend_pid() (or no argument at all, since + a non-matching row is simply filtered rather than raising an error) + to see its own statistics without needing + pg_read_all_stats; only the convenience view, and + any other backend's rows, require it. + pg_stat_get_wait_event_timing_overflow() (see + below) is filtered and granted the same way. + + + + + The <structname>pg_stat_wait_event_timing_overflow</structname> View + + + One row per backend that currently has a collecting payload + (whether or not any wait event has actually occurred), drawn from + pg_stat_get_wait_event_timing_overflow(pid integer + DEFAULT NULL). Exposes the two truncation counters that + the fixed-size accounting structures maintain, plus how many times + this backend's own statistics have been reset. + + + + <structname>pg_stat_wait_event_timing_overflow</structname> Columns + + + + + Column Type + + + Description + + + + + + + pid integer + + + Process ID of the backend. + + + + + backend_type text + + + Type of backend. + + + + + procnumber integer + + + The backend's process number. + + + + + lwlock_overflow_count bigint + + + Number of LWLock waits on a tranche not + already in this backend's tranche table, encountered after that + table filled to pg_wait_event_tracing.max_tranches; + these are counted here rather than individually. + + + + + flat_overflow_count bigint + + + Number of waits in a non-LWLock class whose + event id fell outside that class's compiled-in capacity (see + ); in + practice this can only happen for the Extension + or InjectionPoint classes, whose custom wait + events are registered dynamically at runtime. + + + + + reset_count bigint + + + Number of times this backend's own counters have been reset + (self-reset or a completed cross-backend reset request); this + counter itself is never cleared by a reset. + + + + +
+ + + + The <structname>pg_wait_event_timing_histogram_buckets</structname> View + + + A fixed, 32-row taxonomy for the histogram + column of pg_stat_wait_event_timing: bucket + i of the histogram array corresponds to + row i here (join via unnest(histogram) + WITH ORDINALITY, subtracting one from the ordinality to get + bucket_idx). Bucket edges are powers of + two in nanoseconds; the last bucket is open-ended. + + + + <structname>pg_wait_event_timing_histogram_buckets</structname> Columns + + + + bucket_idx + lower_ns + upper_ns + label + + + + 001024<1us + 1102420481-2us + 2204840962-4us + 3409681924-8us + 48192163848-16us + 5163843276816-32us + 6327686553632-64us + 76553613107264-128us + 8131072262144128-256us + 9262144524288256-512us + 105242881048576512us-1ms + 11104857620971521-2ms + 12209715241943042-4ms + 13419430483886084-8ms + 148388608167772168-16ms + 15167772163355443216-32ms + 16335544326710886432-64ms + 176710886413421772864-128ms + 18134217728268435456128-256ms + 19268435456536870912256-512ms + 205368709121073741824512ms-1s + 21107374182421474836481-2s + 22214748364842949672962-4s + 23429496729685899345924-8s + 248589934592171798691848-16s + 25171798691843435973836816-32s + 26343597383686871947673632-64s + 276871947673613743895347264-128s + 28137438953472274877906944128-256s + 29274877906944549755813888256-512s + 305497558138881099511627776512s-1024s + 311099511627776NULL>=1024s + + +
+ + + This view carries no explicit GRANT or + REVOKE in the extension script, so it follows + the ordinary default privileges for a newly created view: readable + by its owner and by superusers, but not by PUBLIC + unless separately granted. + + + + + The <function>pg_wait_event_tracing_capacity</function> Function + + + pg_wait_event_tracing_capacity() returns setof record + (type text, capacity int4) reports the compiled-in + per-class capacity of the dense timing table, one row per class plus + one for LWLock (whose effective capacity is the + current value of pg_wait_event_tracing.max_tranches, + since LWLock waits are tracked through a + per-backend hash rather than a flat array). It is meant to be + compared against SELECT type, count(*) FROM pg_wait_events + GROUP BY type: a class whose in-tree event count has grown + to within a handful of its capacity here needs the module's internal + table enlarged in a future release. At the values current on this + branch: Lock 32, Buffer 16, + Activity 32, Client 32, + Extension 128, IPC 128, + Timeout 32, IO 128, + InjectionPoint 32. This function carries no + explicit grant either, so it keeps a plain function's default + PUBLIC execute privilege. + + + + + The <structname>pg_backend_wait_event_trace</structname> View and Cross-Backend Reading + + + pg_backend_wait_event_trace, backed by + pg_get_backend_wait_event_trace(), reads the + calling backend's own trace ring. + pg_get_wait_event_trace(procnumber int4) reads + any backend's ring (including an exited backend's orphaned ring; see + ) by process number, + and has no view wrapper of its own. Both share the same row shape + except that the cross-backend function leads with an extra + owner_pid column. + + + + <structname>pg_backend_wait_event_trace</structname> / <function>pg_get_wait_event_trace</function> Columns + + + + + Column Type + + + Description + + + + + + + owner_pid integer + (pg_get_wait_event_trace only) + + + Process ID of the ring's producer — live, or, for an + orphaned ring, its last-known pid. + + + + + seq bigint + + + Monotonically increasing position of this record in the ring + (not reset by wraparound); higher values are more recent. + + + + + timestamp_ns bigint + + + Timestamp of the record, in nanoseconds (same clock source as + the rest of the module's timing). + + + + + wait_event_type text + + + For a completed wait, its ordinary wait event class; for a + query-attribution marker, the fixed string Query + (see ). + + + + + wait_event text + + + For a completed wait, its ordinary wait event name; for a + marker, one of QueryStart, + ExecStart, ExecEnd, + UtilityStart, UtilityEnd, + TxnCommit, TxnAbort, or + Idle. + + + + + duration_us double precision + + + Duration of a completed wait, in microseconds; 0 + for a marker. + + + + + query_id bigint + + + Query identifier carried by QueryStart, + ExecStart, ExecEnd, + UtilityStart, or UtilityEnd; + 0 for TxnCommit, + TxnAbort, Idle, and every + wait record. See the limitations in + for when this is + 0 even on a start/end marker. + + + + + depth integer + + + Executor nesting depth in effect when the marker fired + (0 = top level); meaningful for + QueryStart, UtilityStart, + ExecStart, and ExecEnd; + 0 for everything else, including every wait + record. + + + + +
+ + + Because trace rows carry raw query identifiers and precise wait + sequences — information that can leak across a + SECURITY DEFINER call chain in a way that an + aggregate count or duration cannot — both the view and its + underlying functions are locked down more tightly than the stats + level: EXECUTE on + pg_get_backend_wait_event_trace() and + pg_get_wait_event_trace() is itself revoked + from PUBLIC and granted only to + pg_read_all_stats. Unlike the stats-level + functions, there is no per-row fallback: reading even a session's + own trace ring requires pg_read_all_stats + membership. + + + + + The <function>pg_wait_event_trace_by_statement</function> Function + + + pg_wait_event_trace_by_statement(procnumber int4) returns + setof record groups a backend's trace ring by statement, + using the query-attribution markers; see + for the exact + attribution rule. It is a plain SQL function over + pg_get_wait_event_trace(), granted the same way + (PUBLIC revoked, pg_read_all_stats + granted). + + + + <function>pg_wait_event_trace_by_statement</function> Columns + + + + + Column Type + + + Description + + + + + + + bucket text + + + The bucket's own opening seq as + text, or the synthetic value <idle> or + <unattributed>. + + + + + statement_seq bigint + + + seq of the QueryStart + or UtilityStart marker that opened this + bucket; NULL for + <idle>/<unattributed>. + + + + + query_id bigint + + + query_id carried by that start + marker; NULL for + <idle>/<unattributed>. + + + + + wait_event_type text + + + Wait event class of the waits summed into this row. + + + + + wait_event text + + + Wait event name of the waits summed into this row. + + + + + calls bigint + + + Number of waits of this type inside this bucket. + + + + + total_time_us double precision + + + Summed duration of those waits, in microseconds. + + + + +
+ + + + Other Functions + + + + + pg_stat_reset_wait_event_timing(pid integer DEFAULT + NULL) returns void + + pg_stat_reset_wait_event_timing + + + + + Resets a backend's own or another backend's statistics; see + for the full rules. + Keeps the default PUBLIC execute privilege; + its target-authorization rule is enforced in C, not by revoking + EXECUTE. + + + + + + + pg_stat_reset_wait_event_timing_all() returns + void + + pg_stat_reset_wait_event_timing_all + + + + + Resets every backend's statistics. EXECUTE is + revoked from PUBLIC in the extension script, + and the function additionally hard-requires + superuser() in C, so re-granting + EXECUTE to a non-superuser role does not + enable it. + + + + + + + pg_stat_clear_orphaned_wait_event_rings() returns + bigint + + pg_stat_clear_orphaned_wait_event_rings + + + + + Frees every orphaned trace ring cluster-wide and returns how many + were freed; see . + Superuser-only in the same way as + pg_stat_reset_wait_event_timing_all(): both + REVOKE EXECUTE FROM PUBLIC and a C-level + superuser() check. + + + + + + + pg_wait_event_tracing_hooks_installed() returns + boolean + + pg_wait_event_tracing_hooks_installed + + + + + Diagnostic: whether the calling backend has installed its own + wait-event hooks yet. See + for the lazy, + per-process installation rule this reports on. Reveals nothing + about any other backend or about what is being recorded, so it + keeps the default PUBLIC execute privilege. + + + + + + + + + Statistics Semantics + + + A row in pg_stat_wait_event_timing (or + _overflow) exists for exactly as long as its + backend is both alive and currently collecting: the row is keyed to + the live PgBackendStatus entry for that + process number, so it disappears the moment the backend exits or + turns capture off, and never survives a re-use of the same process + number by an unrelated successor process. + + + + A session's own statistics do not include the + waits of any parallel workers it launches. Each parallel worker is a + separate backend, with its own process number and its own row (or + rows) in pg_stat_wait_event_timing, tagged + with backend_type parallel + worker; those rows disappear as soon as the worker exits, + which typically happens before the leader's statement returns. To + see the total wait time a parallel query incurred across all its + workers, either enable capture in the workers and read their rows + while the query is still running, or use the trace level and read + each worker's own ring after the fact by its process number. + + + + Only wait events reported through + pgstat_report_wait_start_timed/pgstat_report_wait_end_timed + (see ) are visible to any + capture level; a call site still using the ordinary + pgstat_report_wait_start/pgstat_report_wait_end + pair is invisible to this module no matter what + pg_wait_event_tracing.capture is set to. On this + server, essentially every built-in wait event has been converted to + the timed pair — every LWLock and spinlock + wait, the great majority of I/O sites, WAL and replication waits, + the checkpointer/background writer/WAL writer/archiver/autovacuum/WAL + summarizer main loops, and ordinary client-protocol waits such as + ClientRead — so an installation that + preloads this module should expect to see essentially all of a + backend's wait time accounted for. An extension's own hand-annotated + wait events are visible only once that extension is itself changed to + call the timed pair; simply having this module loaded does not make + any other module's existing pgstat_report_wait_start() + calls instrumented. + + + + The counters behind these views (count, + total_time_ms-equivalent nanosecond total, + max_time_us-equivalent nanosecond maximum, + and each histogram bucket) are ordinary 64-bit integers, written by + their owning backend without any lock and read by a caller without + any lock or memory barrier beyond what the row-identity check itself + provides. On a platform where a 64-bit load or store is not atomic + (32-bit builds), a concurrent reader can therefore, in principle, + observe a momentarily torn value for one of these fields; this is a + deliberate trade-off in favor of a lock-free hot path, not something + a future release plans to change. + + + + Accounting a completed wait is deferred, not immediate: at the moment + a wait ends, the collector only reads the clock and stashes the + event, its duration, and that timestamp in a one-slot, backend-local + buffer; the count/total/maximum/histogram update (and, at the + trace level, the ring append) run later, at the + backend's own next timed wait, or at one of several other points where + ordering matters (a query/transaction boundary in trace mode, a + capture-level change, a reset, disabling capture, or process exit). + This is what keeps the collector's cost out of the interval a + contended lock's waiters are queued on: recording a wait's end used to + run to completion before returning control to the caller, which for an + LWLock wait is still inside the critical section + the lock protects. Two consequences follow, both bounded: + + + + + + Visibility latency. A backend reading its own + data (pg_stat_wait_event_timing, + pg_backend_wait_event_trace, + pg_wait_event_trace_by_statement() called with + its own process number) always flushes its own pending wait first, + so it never observes a delay: an own-session read always reflects + every wait that has already completed. A different session reading + that backend's row or ring, however, can see a wait appear only once + the owning backend's own next flush point is reached — + typically microseconds later, at its next wait, but possibly as late + as the end of the current statement, since a backend computing for a + long stretch with no further wait (a long CPU-bound query, for + instance) does not flush again until it does wait, or until that + statement ends. A server-side process that blocks without a + timeout (for example a caught-up standby's startup process waiting + for WAL) makes its most recent completed wait visible only when its + next wait begins. A cross-backend reader should treat what it sees + as current up to a small, bounded lag behind the owning backend's + own view, not as exactly real-time. + + + + + Crash loss. If a backend is terminated + abruptly (killed, or a crash that takes the whole cluster down) in + the narrow window between a wait ending and that backend's own next + flush, that one pending wait is lost: it was never applied to the + statistics payload and never appended to the trace ring. This is + strictly narrower than existing loss on a normal exit or crash + already implies — the statistics payload is released (and, on + a whole-cluster crash restart, every trace ring is discarded + regardless; see ) + — 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. + + + + + + Server-Side (Non-Client) Processes + + + The checkpointer, background writer, WAL writer, startup process + (including crash recovery), WAL receiver, archiver, WAL summarizer, + I/O workers, the autovacuum launcher and its workers, background + workers, and WAL senders never parse a query or run the executor, so + they have no ordinary opportunity to notice a change to + pg_wait_event_tracing.capture. To still collect + from process start rather than only from the next reload, the + module reserves a small, fixed-size slice of shared memory — + one statistics payload per possible such process — but only + when pg_wait_event_tracing.capture is already + something other than off in the configuration at + postmaster start. With capture off at start (the default), this + reservation is skipped entirely and costs nothing; with it already + on, the reservation is roughly 10 MiB at typical default + settings (see for the + exact figure and how it scales). If capture is instead turned on + later, by a configuration reload, these processes pick up statistics + collection starting at that reload — the same gap an ordinary + client backend has until its own next statement, just without a + "next statement" of its own to close it sooner. + + + + The trace level is never + covered by that reservation, regardless of the configuration at + postmaster start: a full trace ring per such process would cost + several additional megabytes each, which this module does not + reserve unconditionally. A server-side process therefore only ever + starts tracing at the first configuration reload that sets + capture = trace, exactly like the reload path a + client backend would use if it could not rely on its own next + statement. One consequence worth stating plainly: crash recovery run + by the startup process at postmaster start can appear in + statistics (if capture was already on in the + configuration before that start) but can never be captured at the + trace level, since recovery typically completes + before any operator has the opportunity to trigger a reload. + + + + + + Memory Usage + + + Three kinds of shared memory are involved, only one of which is + unconditional: + + + + + + Control table: one small, fixed-layout entry + per possible process number + (MaxBackends + 38 auxiliary-process slots), + allocated in ordinary (non-dynamic) shared memory regardless of + pg_wait_event_tracing.capture, since it is what + every other piece of this module addresses through. At typical + default settings (max_connections = 100, + autovacuum_worker_slots = 16, + max_worker_processes = 8, + max_wal_senders = 10, + io_max_workers = 8, giving + MaxBackends = 136) this table is on the order of + 10 KB, entirely independent of whether capture is ever turned + on. + + + + + Per-backend statistics payload: allocated from + a dynamic shared memory area, one payload per backend that is + actually collecting, sized from + pg_wait_event_tracing.max_tranches. At the + default of 192, one payload is 212,664 bytes (about 207.7 KiB) + on a common 64-bit platform; this is freed as soon as that backend + turns capture off or exits. The reserved server-process region + described in + is simply a run of this same per-payload size, one slice per + eligible process number in range, allocated up front instead of + lazily: at the settings above that range holds 50 process numbers, + for a total reservation of about 10.1 MiB. + + + + + Per-backend trace ring: allocated from its own + dynamic shared memory area, one ring per backend that has actually + enabled trace, sized by + pg_wait_event_tracing.trace_ring_size (4 MiB + at the default). Freed on an explicit step-down away from + trace; orphaned, not freed, on the owning + backend's exit (see + ). + + + + + + Nothing in this module scales with + max_connections beyond the small, fixed control + table: the two memory-hungry pieces are both proportional only to the + number of backends that have actually turned capture (respectively + trace) on, not to how many backends the server is configured to + allow. + + + + + Resetting Statistics and Permissions + + + pg_stat_reset_wait_event_timing(NULL), or with + the caller's own pg_backend_pid(), resets the + caller's own counters immediately and synchronously. + + + + Resetting another backend's statistics + (pg_stat_reset_wait_event_timing(pid) + with some other backend's pid) is subject to exactly the same + target-authorization rule + pg_signal_backend() uses: a target that is + superuser-owned or has no owning role at all (which, notably, + includes every autovacuum worker, since those are role-less) can only + be reset by a superuser; any other target can be reset by a caller + holding privileges of the target's role, or of the + pg_signal_backend role. Unlike + pg_signal_backend() itself, there is no separate + carve-out for autovacuum workers here — they simply fall under + the role-less case above and so already require superuser, which is + the more conservative (and, for a function whose entire effect is + erasing diagnostic state, arguably more appropriate) of the two + possible readings. An auxiliary process's pid (checkpointer, WAL + writer, and the like) can never be named this way at all: pid + resolution only recognizes ordinary backends, so such a pid produces + the same WARNING: PID %d is not a PostgreSQL backend + process that pg_signal_backend() would + give for an unknown pid, not an error — an auxiliary process's + statistics can still be reset, but only via + pg_stat_reset_wait_event_timing_all(). + + + + A cross-backend reset is asynchronous: the + requesting call only publishes a request (tied, under the same lock, + to the exact process identity it resolved, so it cannot land on an + unrelated successor that has since reused the same process number); + the target backend notices and actually clears its own counters the + next time it finishes any wait of its own. There is no way to force + an idle target to reset any sooner than its next wait. + + + + pg_stat_reset_wait_event_timing_all() is + superuser-only regardless of grants (see + ); it requests a + reset on every process number unconditionally, including ones with + no current owner, which is harmless. + + + + + The Trace Ring and Post-Mortem Reading + + + Before working through an example, the lifecycle contract for an + exited backend's trace ring needs to be stated up front, since it + changes what a query against + pg_get_wait_event_trace() can be expected to + return: + + + + + + On an orderly backend exit (a normal + disconnect, a completed background worker, a parallel worker + finishing its work, and so on), the ring is not + freed. It is marked orphaned, and stays fully readable — + tagged with the exited process's last-known pid via the + owner_pid column — until either a + successor process later reuses that same process number and itself + enables trace (which reclaims, i.e. frees, the orphaned ring before + installing its own), or an administrator explicitly calls + pg_stat_clear_orphaned_wait_event_rings(). + + + + + This orphan preservation does not survive a + crash restart. If any backend anywhere in the cluster crashes, + the postmaster resets and recreates all of shared memory from + scratch as part of ordinary crash recovery, which discards every + ring — active or already orphaned — along with + everything else in shared memory. Orphan preservation only ever + helps across an individual process's own orderly exit, never across + a whole-cluster crash-and-restart cycle. + + + + + + With that contract in mind, + pg_get_wait_event_trace(procnumber) is the + general-purpose way to read any backend's ring, including one that + has already exited: find the process number first (for a still-live + backend, from pg_stat_wait_event_timing's + procnumber column; for one that has + exited, from having recorded it earlier, or from the + owner_pid of an already-known orphan), then: + +SELECT * FROM pg_get_wait_event_trace(42) ORDER BY seq; + + A backend can also read its own ring more directly through the + pg_backend_wait_event_trace view (equivalently, + pg_get_backend_wait_event_trace()), which needs + no process number argument. + + + + pg_stat_clear_orphaned_wait_event_rings() exists + for the case where a process number is never going to be reused soon + enough on its own — for example, a long-lived connection pool + whose member connections rarely disconnect, where trace was briefly + enabled and then turned back off, leaving an orphan pinned + indefinitely. It frees every currently orphaned ring cluster-wide and + returns the count freed; being both cluster-scope and destructive of + diagnostic data, it is superuser-only in the same way + pg_stat_reset_wait_event_timing_all() is. + + + + + Query Markers and Statement Attribution + + + At the trace level, the ring buffer holds two + kinds of records interleaved by the order they were written: ordinary + completed-wait records, and query-attribution markers. Every marker + is reported with wait_event_type = + Query, so WHERE wait_event_type = + 'Query' isolates them from real waits. + + + + Query-Attribution Markers + + + + wait_event + Emitted from + Meaning + + + + + QueryStart + post_parse_analyze_hook + + A statement (including a utility statement, which is parsed the + same way) has just been parsed and analyzed. + depth is the executor nesting depth + already in effect when this fires — not always + 0, since parsing can itself happen from inside + an already-open outer statement, for example a dynamically built + query executed via SPI from a SQL or PL function. + + + + ExecStart + ExecutorStart_hook + + The executor is starting a plan, at whatever nesting depth is + currently in effect (0 = top-level query). + Depth is incremented immediately afterward, so a nested + invocation's own ExecStart/ExecEnd + pair is correctly bracketed inside the outer one's. + + + + ExecEnd + ExecutorEnd_hook + + The executor is finishing that plan; depth is decremented first, + so the record's own depth is the + nesting level after this invocation returns. + + + + UtilityStart + ProcessUtility_hook (before chaining) + + A utility statement (one that never goes through the executor) is + about to run. + + + + UtilityEnd + ProcessUtility_hook (after chaining returns) + + That utility statement has finished. If it raises an error + instead of returning normally, this marker is simply never + written, exactly as an executor error skips + ExecEnd. + + + + TxnCommit + Transaction-end callback, on commit (including a two-phase PREPARE TRANSACTION) or parallel-worker commit + + The current transaction (or transaction block) has committed. + Any end-of-transaction wait, such as a WAL flush, precedes this + marker and is therefore attributed to the statement that + triggered the commit, not to whatever comes after. + + + + TxnAbort + Transaction-end callback, on abort or parallel-worker abort + + The current transaction (or transaction block) has aborted. Also + defensively resets the nesting-depth counter to 0, + since an error can unwind through any number of nested executor + invocations without each one's own ExecEnd + ever running. + + + + Idle + The wait-begin hook itself + + Synthesized, not tied to any parse/executor/utility/transaction + hook, because none of those fire while a backend is simply + waiting for its next client message. Emitted the first time a + backend blocks in a ClientRead wait after a + statement or transaction has already closed (see the state + machine below); marks the unambiguous start of client think time. + + + + +
+ + + query_id is whatever + queryId the parser or planner has already computed + by the time the corresponding marker fires: this module deliberately + never calls EnableQueryId() itself, so as not to + force query-identifier computation, and its cost, onto every server + that merely preloads it. Unless + is on, or some other loaded + module (for example pg_stat_statements) has + already turned it on, every marker's query_id + reads as 0; that value means "no identifier was + available", not "no statement was open". + + + + The Marker State Machine + + + Each backend tracks one small piece of state, entirely separate from + the ring itself, that decides whether an upcoming + QueryStart/UtilityStart/ExecStart + should be preceded by a synthetic Idle marker: + + + +IDLE --(QueryStart | UtilityStart | ExecStart)--> OPEN +OPEN --(ExecEnd at depth 0 | UtilityEnd | TxnCommit | TxnAbort)--> AFTER_STATEMENT +AFTER_STATEMENT --(first ClientRead wait)--> IDLE (emits Idle) +AFTER_STATEMENT --(QueryStart | UtilityStart)--> OPEN (no Idle emitted) + + + + The last transition is what makes a pipelined batch, a + multi-statement simple-query string, or an already-buffered next + statement inside an explicit transaction read as back-to-back + statement intervals with no intervening Idle: the + backend never actually blocked waiting for the client between them, + so there is nothing for Idle to mark. + + + + + The Attribution Rule + + + pg_wait_event_trace_by_statement() assigns + every ordinary wait record to exactly one bucket, using only three + kinds of marker as boundaries: + + + + + + A QueryStart or UtilityStart + at nesting depth 0 opens a new statement + bucket, labelled by that marker's own seq + and query_id. Gating on depth + 0 specifically keeps a nested start (SPI from a + SQL or PL function) from appearing to close the outer statement's + own bucket. + + + + + An Idle or a TxnAbort marker + opens the synthetic <idle> bucket. + TxnAbort is treated the same as + Idle here on the reasoning that, from an + attribution standpoint, whatever follows an abort before the next + real statement is the same kind of gap as ordinary client think + time, rather than a third, separately named bucket. + + + + + Any wait recorded before the ring's very first boundary marker of + either kind — for instance, because trace was enabled + partway through an already-running session — falls into the + synthetic <unattributed> bucket. + + + + + + + Worked Timelines + + + Every sequence below is the literal, regression-tested + wait_event array a session's own ring + produces for that scenario (Idle omitted, since + whether it appears depends on protocol-level timing, not statement + structure; see the note after the table). + + + + Marker Sequences by Scenario + + + + Scenario + Markers + + + + + A single autocommit statement (SELECT 1;) + QueryStart, ExecStart, ExecEnd, TxnCommit + + + + An explicit transaction with two statements, each on its own + line (BEGIN; SELECT 1; SELECT 2; COMMIT;) + + +QueryStart, UtilityStart, UtilityEnd, + QueryStart, ExecStart, ExecEnd, + QueryStart, ExecStart, ExecEnd, + QueryStart, UtilityStart, UtilityEnd, TxnCommit + + + + + Two statements sent in one simple-query protocol message + (SELECT 1; SELECT 2; on one input line) + + QueryStart, ExecStart, ExecEnd, TxnCommit, + QueryStart, ExecStart, ExecEnd, TxnCommit + + + A utility statement (CREATE TABLE t (a int);) + QueryStart, UtilityStart, UtilityEnd, TxnCommit + + + + An error raised during planning, before execution ever starts + (SELECT 1/0;, folded and evaluated by the + planner's constant-folding pass) + + QueryStart, TxnAbort + + + + A nested call, one level deep (a plpgsql + function whose body issues PERFORM, which + always goes through SPI's normal execute path) + + QueryStart, ExecStart, ExecStart, ExecEnd, ExecEnd, + TxnCommit with depths + 0, 0, 1, 1, 0, 0 + + + +
+ + + Two further scenarios are not exercised by the regression tests + (a genuinely mid-execution error is hard to construct + deterministically; a truly pipelined extended-protocol batch cannot + be sent from a plain SQL script) but follow directly from the state + machine and hook placements above: + + + + + + An error raised during execution (after + ExecutorStart has already run, unlike the + constant-folding case in the table) produces + QueryStart, ExecStart, TxnAbort — no + matching ExecEnd, since an error unwinds past + ExecutorEnd_hook without calling it, exactly + as an erroring utility statement never reaches + UtilityEnd. + + + + + A pipelined extended-query-protocol batch + (several Parse/Bind/Execute + messages queued without an intervening Sync) + reads exactly like the same-line multi-statement case above: each + queued statement gets its own complete + QueryStart ... TxnCommit sequence, one after + another, with no Idle between them. There is no + dedicated end-of-message marker for the extended protocol (no + existing core hook fires at that boundary), so a queued + statement's end is inferred the same way as in the multi-statement + case: by the appearance of the next statement's own + QueryStart. + + + + + + + Limitations + + + + + No end-of-message marker for the pipelined extended + protocol. There is no core hook that fires when one + pipelined Bind/Execute + message's processing ends and the next begins, so a queued + statement's boundary can only be inferred from the next + statement's own QueryStart, as shown above. + + + + + Parallel workers are recorded under their own + backend. A parallel worker's waits and markers go into + its own ring, keyed to its own process number; the query leader's + trace never contains them (see + ). + + + + + Waits before the first marker are + unattributed. If a ring is read from a point before its + very first boundary marker — typically because trace was + turned on partway through an already-open session — those + earlier waits have no statement to attach to and land in the + <unattributed> bucket (see + ). + + + + + query_id is + 0 unless query identifier computation is + enabled. This module never calls + EnableQueryId() on its own; see the note + after . + + + + + ClientRead inside COPY + ... FROM STDIN belongs to the + COPY. While a + COPY ... FROM STDIN is reading its data stream, + the marker state machine is still OPEN (the + matching ExecEnd has not fired yet), so the + condition that would synthesize an Idle marker + never matches: every ClientRead wait incurred + while waiting for more COPY data is recorded as + an ordinary wait attributed to the COPY + statement itself, not treated as client think time between + statements. + + + + + + + + Reading from Other Extensions + + + Every shared data structure this module uses — the control + table, the per-backend statistics payloads, and the trace rings + themselves — is private to + pg_wait_event_tracing.c; none of it is exported + through any header another module could include. The SQL functions + documented in are the only + supported way to read this module's data, from SQL or from any other + language or extension that can issue SQL (including + SPI from inside a C extension). There is + deliberately no C-level API for reaching into this module's shared + memory directly. + + + + + Overhead + + + + Overhead differs by how deeply the module is engaged: the library not + loaded at all; loaded via + with + pg_wait_event_tracing.capture = off + (paid by every backend regardless of whether any session ever raises + the level, since every timed wait-reporting call site now runs one + extra, normally-not-taken branch); stats (two + timestamp reads and one small in-memory update per completed wait); + and trace (stats, plus one 32-byte record append + per completed wait and one more per query-attribution marker). + Concrete per-level measurements are not included in this revision of + the documentation; they will be re-measured on dedicated, + non-virtualized hardware and added here before this module is + proposed for inclusion. + + + + diff --git a/doc/src/sgml/xfunc.sgml b/doc/src/sgml/xfunc.sgml index bc04d9dfc13..be14474e243 100644 --- a/doc/src/sgml/xfunc.sgml +++ b/doc/src/sgml/xfunc.sgml @@ -3883,6 +3883,26 @@ uint32 WaitEventExtensionNew(const char *wait_event_name) (1 row) + + A custom wait event, like any other, is reported with + pgstat_report_wait_start and + pgstat_report_wait_end (see the injection point + example below). Starting in this release, add-ins may instead use + pgstat_report_wait_start_timed and + pgstat_report_wait_end_timed, an explicitly + instrumented variant of the same pair with the identical calling + convention. The only difference is that the timed pair also invokes a + pair of begin/end hooks + (wait_event_begin_hook/wait_event_end_hook) + that a loaded timing consumer, such as + pg_wait_event_tracing, can install to observe + exactly when this wait started and ended. When no such consumer is + loaded, the hooks are null and the timed pair costs the same as the + ordinary one; add-ins that want their own custom wait events to be + visible to a timing consumer should prefer the timed pair for any new + code, and may convert existing call sites to it at no cost to + installations that do not load such a consumer. + @@ -3951,14 +3971,23 @@ custom_injection_callback(const char *name, { uint32 wait_event_info = WaitEventInjectionPointNew(name); +#if PG_VERSION_NUM >= 200000 + pgstat_report_wait_start_timed(wait_event_info); + elog(NOTICE, "%s: executed custom callback", name); + pgstat_report_wait_end_timed(); +#else pgstat_report_wait_start(wait_event_info); elog(NOTICE, "%s: executed custom callback", name); pgstat_report_wait_end(); +#endif } This callback prints a message to server error log with severity NOTICE, but callbacks may implement more complex - logic. + logic. The timed pair is used here (with a fallback to the ordinary + pair for servers older than this release) so that a loaded timing + consumer can observe the injection point's own wait; see + . diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list index 5d432074c2c..a5ad5a85d36 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -2462,6 +2462,13 @@ PullFilterOps PushFilter PushFilterOps PushFunction +PwetCaptureLevel +PwetLWLockHash +PwetLWLockHashEntry +PwetRegionHeader +PwetSlot +PwetStats +PwetTimingEntry PyCFunction PyMethodDef PyModuleDef -- 2.49.0