From c00c545ed8da5c37d5590018df30b633b32b2ed7 Mon Sep 17 00:00:00 2001 From: Bertrand Drouvot Date: Mon, 6 Jan 2025 10:00:00 +0000 Subject: [PATCH v6 3/3] per backend WAL statistics Now that commit 9aea73fc61 added backend-level statistics to pgstats (and per backend IO statistics) we can more easily add per backend statistics. This commit adds per backend WAL statistics using the same layer as pg_stat_wal, except that it is now possible to know how much WAL activity is happening in each backend rather than an overall aggregate of all the activity. A function called pg_stat_get_backend_wal() is added to access this data depending on the PID of a backend. The same limitation as in 9aea73fc61 persists, meaning that Auxiliary processes are not included in this set of statistics. XXX: bump catalog version --- doc/src/sgml/config.sgml | 4 +- doc/src/sgml/monitoring.sgml | 19 +++++ src/backend/access/transam/xlog.c | 35 +++++++- src/backend/utils/activity/pgstat_backend.c | 91 ++++++++++++++++++++- src/backend/utils/activity/pgstat_wal.c | 2 + src/backend/utils/adt/pgstatfuncs.c | 53 +++++++++++- src/include/catalog/pg_proc.dat | 7 ++ src/include/pgstat.h | 48 +++++++---- src/include/utils/pgstat_internal.h | 3 +- src/test/regress/expected/stats.out | 14 ++++ src/test/regress/sql/stats.sql | 6 ++ 11 files changed, 253 insertions(+), 29 deletions(-) 12.5% doc/src/sgml/ 11.2% src/backend/access/transam/ 37.5% src/backend/utils/activity/ 17.3% src/backend/utils/adt/ 6.1% src/include/catalog/ 6.3% src/include/ 5.0% src/test/regress/expected/ 3.8% src/test/regress/sql/ diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index a8866292d46..5a48b427609 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8292,7 +8292,9 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; measure the overhead of timing on your system. I/O timing information is displayed in - pg_stat_wal. + pg_stat_wal and in the output of the + + pg_stat_get_backend_wal() function. Only superusers and users with the appropriate SET privilege can change this setting. diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index e5888fae2b5..8fdf7d13f21 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -4824,6 +4824,25 @@ description | Waiting for a newly initialized WAL file to reach durable storage + + + + pg_stat_get_backend_wal + + pg_stat_get_backend_wal ( integer ) + record + + + Returns WAL statistics about the backend with the specified + process ID. The output fields are exactly the same as the ones in the + pg_stat_wal view. + + + The function does not return WAL statistics for the checkpointer, + the background writer, the startup process and the autovacuum launcher. + + + diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index bf3dbda901d..f7c5b1e5e3b 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -2058,6 +2058,11 @@ AdvanceXLInsertBuffer(XLogRecPtr upto, TimeLineID tli, bool opportunistic) XLogWrite(WriteRqst, tli, false); LWLockRelease(WALWriteLock); PendingWalStats.wal_buffers_full++; + + /* Add the per-backend related statistic */ + if (pgstat_tracks_backend_bktype(MyBackendType)) + PendingBackendStats.pending_wal.wal_buffers_full++; + TRACE_POSTGRESQL_WAL_BUFFER_WRITE_DIRTY_DONE(); } /* Re-acquire WALBufMappingLock and retry */ @@ -2426,11 +2431,14 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID tli, bool flexible) Size nleft; ssize_t written; instr_time start; + instr_time end; /* OK to write the page(s) */ from = XLogCtl->pages + startidx * (Size) XLOG_BLCKSZ; nbytes = npages * (Size) XLOG_BLCKSZ; nleft = nbytes; + /* keep compiler quiet */ + INSTR_TIME_SET_ZERO(end); do { errno = 0; @@ -2451,14 +2459,22 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID tli, bool flexible) */ if (track_wal_io_timing) { - instr_time end; - INSTR_TIME_SET_CURRENT(end); INSTR_TIME_ACCUM_DIFF(PendingWalStats.wal_write_time, end, start); } PendingWalStats.wal_write++; + /* Add the per-backend related statistic */ + if (pgstat_tracks_backend_bktype(MyBackendType)) + { + PendingBackendStats.pending_wal.wal_write++; + + if (track_wal_io_timing) + INSTR_TIME_ACCUM_DIFF(PendingBackendStats.pending_wal.wal_write_time, + end, start); + } + if (written <= 0) { char xlogfname[MAXFNAMELEN]; @@ -8684,8 +8700,11 @@ issue_xlog_fsync(int fd, XLogSegNo segno, TimeLineID tli) { char *msg = NULL; instr_time start; + instr_time end; Assert(tli != 0); + /* keep compiler quiet */ + INSTR_TIME_SET_ZERO(end); /* * Quick exit if fsync is disabled or write() has already synced the WAL @@ -8751,13 +8770,21 @@ issue_xlog_fsync(int fd, XLogSegNo segno, TimeLineID tli) */ if (track_wal_io_timing) { - instr_time end; - INSTR_TIME_SET_CURRENT(end); INSTR_TIME_ACCUM_DIFF(PendingWalStats.wal_sync_time, end, start); } PendingWalStats.wal_sync++; + + /* Add the per-backend related statistic */ + if (pgstat_tracks_backend_bktype(MyBackendType)) + { + PendingBackendStats.pending_wal.wal_sync++; + + if (track_wal_io_timing) + INSTR_TIME_ACCUM_DIFF(PendingBackendStats.pending_wal.wal_sync_time, + end, start); + } } /* diff --git a/src/backend/utils/activity/pgstat_backend.c b/src/backend/utils/activity/pgstat_backend.c index bcf9e4b1487..90fb5f72bc1 100644 --- a/src/backend/utils/activity/pgstat_backend.c +++ b/src/backend/utils/activity/pgstat_backend.c @@ -33,11 +33,18 @@ * reported within critical sections so we use static memory in order to avoid * memory allocation. */ -static PgStat_BackendPending PendingBackendStats; +PgStat_BackendPending PendingBackendStats; /* - * Utility routines to report I/O stats for backends, kept here to avoid - * exposing PendingBackendStats to the outside world. + * WAL usage counters saved from pgWalUsage at the previous call to + * pgstat_report_wal(). This is used to calculate how much WAL usage + * happens between pgstat_report_wal() calls, by subtracting + * the previous counters from the current ones. + */ +static WalUsage prevBackendWalUsage; + +/* + * Utility routines to report I/O stats for backends. */ void pgstat_count_backend_io_op_time(IOObject io_object, IOContext io_context, @@ -131,6 +138,79 @@ pgstat_flush_backend_entry_io(PgStat_EntryRef *entry_ref) MemSet(&PendingBackendStats.pending_io, 0, sizeof(PgStat_PendingIO)); } +/* + * To determine whether any WAL activity has occurred since last time, not + * only the number of generated WAL records but also the numbers of WAL + * writes and syncs need to be checked. Because even transaction that + * generates no WAL records can write or sync WAL data when flushing the + * data pages. + */ +static bool +pgstat_backend_wal_have_pending(void) +{ + PgStat_PendingWalStats pending_wal; + + pending_wal = PendingBackendStats.pending_wal; + + return pgWalUsage.wal_records != prevBackendWalUsage.wal_records || + pending_wal.wal_write != 0 || pending_wal.wal_sync != 0; +} + +/* + * Flush out locally pending backend WAL statistics. Locking is managed + * by the caller. + */ +static void +pgstat_flush_backend_entry_wal(PgStat_EntryRef *entry_ref) +{ + PgStatShared_Backend *shbackendent; + PgStat_WalCounters *bktype_shstats; + PgStat_PendingWalStats pending_wal = PendingBackendStats.pending_wal; + WalUsage wal_usage_diff = {0}; + + /* + * This function can be called even if nothing at all has happened. Avoid + * taking lock for nothing in that case. + */ + if (!pgstat_backend_wal_have_pending()) + return; + + shbackendent = (PgStatShared_Backend *) entry_ref->shared_stats; + bktype_shstats = &shbackendent->stats.wal_stats; + + /* + * We don't update the WAL usage portion of the local WalStats elsewhere. + * Calculate how much WAL usage counters were increased by subtracting the + * previous counters from the current ones. + */ + WalUsageAccumDiff(&wal_usage_diff, &pgWalUsage, &prevBackendWalUsage); + +#define WALSTAT_ACC(fld, var_to_add) \ + (bktype_shstats->fld += var_to_add.fld) +#define WALSTAT_ACC_INSTR_TIME(fld) \ + (bktype_shstats->fld += INSTR_TIME_GET_MICROSEC(pending_wal.fld)) + WALSTAT_ACC(wal_buffers_full, pending_wal); + WALSTAT_ACC(wal_write, pending_wal); + WALSTAT_ACC(wal_sync, pending_wal); + WALSTAT_ACC(wal_records, wal_usage_diff); + WALSTAT_ACC(wal_fpi, wal_usage_diff); + WALSTAT_ACC(wal_bytes, wal_usage_diff); + WALSTAT_ACC_INSTR_TIME(wal_write_time); + WALSTAT_ACC_INSTR_TIME(wal_sync_time); +#undef WALSTAT_ACC_INSTR_TIME +#undef WALSTAT_ACC + + /* + * Save the current counters for the subsequent calculation of WAL usage. + */ + prevBackendWalUsage = pgWalUsage; + + /* + * Clear out the statistics buffer, so it can be re-used. + */ + MemSet(&PendingBackendStats.pending_wal, 0, sizeof(PendingWalStats)); +} + /* * Flush out locally pending backend statistics * @@ -158,6 +238,9 @@ pgstat_flush_backend(bool nowait, bits32 flags) if (flags & PGSTAT_BACKEND_FLUSH_IO) pgstat_flush_backend_entry_io(entry_ref); + if (flags & PGSTAT_BACKEND_FLUSH_WAL) + pgstat_flush_backend_entry_wal(entry_ref); + pgstat_unlock_entry(entry_ref); return false; @@ -205,6 +288,8 @@ pgstat_create_backend(ProcNumber procnum) pgstat_unlock_entry(entry_ref); MemSet(&PendingBackendStats, 0, sizeof(PgStat_BackendPending)); + + prevBackendWalUsage = pgWalUsage; } /* diff --git a/src/backend/utils/activity/pgstat_wal.c b/src/backend/utils/activity/pgstat_wal.c index bfc06178a68..33627642261 100644 --- a/src/backend/utils/activity/pgstat_wal.c +++ b/src/backend/utils/activity/pgstat_wal.c @@ -55,6 +55,8 @@ pgstat_report_wal(bool force) /* flush wal stats */ pgstat_flush_wal(nowait); + pgstat_flush_backend(nowait, PGSTAT_BACKEND_FLUSH_WAL); + /* flush IO stats */ pgstat_flush_io(nowait); } diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 97510d48eef..6da98bafbf2 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -1606,8 +1606,8 @@ pg_stat_get_backend_io(PG_FUNCTION_ARGS) /* * pg_stat_wal_build_tuple * - * Helper routine for pg_stat_get_wal() returning one tuple based on the contents - * of wal_counters. + * Helper routine for pg_stat_get_wal() and pg_stat_get_backend_wal() returning + * one tuple based on the contents of wal_counters. */ static Datum pg_stat_wal_build_tuple(PgStat_WalCounters wal_counters, @@ -1670,6 +1670,55 @@ pg_stat_wal_build_tuple(PgStat_WalCounters wal_counters, PG_RETURN_DATUM(HeapTupleGetDatum(heap_form_tuple(tupdesc, values, nulls))); } +/* + * Returns WAL statistics for a backend with given PID. + */ +Datum +pg_stat_get_backend_wal(PG_FUNCTION_ARGS) +{ + int pid; + PGPROC *proc; + ProcNumber procNumber; + PgStat_Backend *backend_stats; + PgStat_WalCounters bktype_stats; + PgBackendStatus *beentry; + + pid = PG_GETARG_INT32(0); + proc = BackendPidGetProc(pid); + + /* + * This could be an auxiliary process but these do not report backend + * statistics due to pgstat_tracks_backend_bktype(), so there is no need + * for an extra call to AuxiliaryPidGetProc(). + */ + if (!proc) + PG_RETURN_NULL(); + + procNumber = GetNumberFromPGProc(proc); + + beentry = pgstat_get_beentry_by_proc_number(procNumber); + if (!beentry) + PG_RETURN_NULL(); + + backend_stats = pgstat_fetch_stat_backend(procNumber); + if (!backend_stats) + PG_RETURN_NULL(); + + /* if PID does not match, leave */ + if (beentry->st_procpid != pid) + PG_RETURN_NULL(); + + /* backend may be gone, so recheck in case */ + if (beentry->st_backendType == B_INVALID) + PG_RETURN_NULL(); + + bktype_stats = backend_stats->wal_stats; + + /* save tuples with data from this PgStat_BktypeIO */ + return (pg_stat_wal_build_tuple(bktype_stats, backend_stats->stat_reset_timestamp)); +} + + /* * Returns statistics of WAL activity */ diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 18560755d26..ca60af1e434 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5929,6 +5929,13 @@ proargmodes => '{o,o,o,o,o,o,o,o,o}', proargnames => '{wal_records,wal_fpi,wal_bytes,wal_buffers_full,wal_write,wal_sync,wal_write_time,wal_sync_time,stats_reset}', prosrc => 'pg_stat_get_wal' }, +{ oid => '8037', descr => 'statistics: backend WAL activity', + proname => 'pg_stat_get_backend_wal', provolatile => 'v', + proparallel => 'r', prorettype => 'record', proargtypes => 'int4', + proallargtypes => '{int4,int8,int8,numeric,int8,int8,int8,float8,float8,timestamptz}', + proargmodes => '{i,o,o,o,o,o,o,o,o,o}', + proargnames => '{backend_pid,wal_records,wal_fpi,wal_bytes,wal_buffers_full,wal_write,wal_sync,wal_write_time,wal_sync_time,stats_reset}', + prosrc => 'pg_stat_get_backend_wal' }, { oid => '6248', descr => 'statistics: information about WAL prefetching', proname => 'pg_stat_get_recovery_prefetch', prorows => '1', proretset => 't', provolatile => 'v', prorettype => 'record', proargtypes => '', diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 9bbba883685..27a0053ea21 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -338,24 +338,6 @@ typedef struct PgStat_IO PgStat_BktypeIO stats[BACKEND_NUM_TYPES]; } PgStat_IO; -typedef struct PgStat_Backend -{ - TimestampTz stat_reset_timestamp; - PgStat_BktypeIO io_stats; -} PgStat_Backend; - -/* --------- - * PgStat_BackendPending Non-flushed backend stats. - * --------- - */ -typedef struct PgStat_BackendPending -{ - /* - * Backend statistics store the same amount of IO data as PGSTAT_KIND_IO. - */ - PgStat_PendingIO pending_io; -} PgStat_BackendPending; - typedef struct PgStat_StatDBEntry { PgStat_Counter xact_commit; @@ -500,6 +482,30 @@ typedef struct PgStat_PendingWalStats instr_time wal_sync_time; } PgStat_PendingWalStats; +/* --------- + * PgStat_BackendPending Non-flushed backend stats. + * --------- + */ +typedef struct PgStat_BackendPending +{ + /* + * Backend statistics store the same amount of IO data as PGSTAT_KIND_IO. + */ + PgStat_PendingIO pending_io; + + /* + * Backend statistics store the same amount of WAL data as + * PGSTAT_KIND_WAL. + */ + PgStat_PendingWalStats pending_wal; +} PgStat_BackendPending; + +typedef struct PgStat_Backend +{ + TimestampTz stat_reset_timestamp; + PgStat_BktypeIO io_stats; + PgStat_WalCounters wal_stats; +} PgStat_Backend; /* * Functions in pgstat.c @@ -840,5 +846,11 @@ extern PGDLLIMPORT SessionEndType pgStatSessionEndCause; /* updated directly by backends and background processes */ extern PGDLLIMPORT PgStat_PendingWalStats PendingWalStats; +/* + * Variables in pgstat_backend.c + */ + +/* updated directly by backends */ +extern PGDLLIMPORT PgStat_BackendPending PendingBackendStats; #endif /* PGSTAT_H */ diff --git a/src/include/utils/pgstat_internal.h b/src/include/utils/pgstat_internal.h index a3d39d2b725..6155a3fc983 100644 --- a/src/include/utils/pgstat_internal.h +++ b/src/include/utils/pgstat_internal.h @@ -622,7 +622,8 @@ extern void pgstat_archiver_snapshot_cb(void); /* flags for pgstat_flush_backend() */ #define PGSTAT_BACKEND_FLUSH_IO (1 << 0) /* Flush I/O statistics */ -#define PGSTAT_BACKEND_FLUSH_ALL (PGSTAT_BACKEND_FLUSH_IO) +#define PGSTAT_BACKEND_FLUSH_WAL (1 << 1) /* Flush WAL statistics */ +#define PGSTAT_BACKEND_FLUSH_ALL (PGSTAT_BACKEND_FLUSH_IO | PGSTAT_BACKEND_FLUSH_WAL) extern bool pgstat_flush_backend(bool nowait, bits32 flags); extern bool pgstat_backend_flush_cb(bool nowait); diff --git a/src/test/regress/expected/stats.out b/src/test/regress/expected/stats.out index a0317b7208e..cc01fdf2741 100644 --- a/src/test/regress/expected/stats.out +++ b/src/test/regress/expected/stats.out @@ -832,6 +832,8 @@ SELECT sessions > :db_stat_sessions FROM pg_stat_database WHERE datname = (SELEC SELECT num_requested AS rqst_ckpts_before FROM pg_stat_checkpointer \gset -- Test pg_stat_wal (and make a temp table so our temp schema exists) SELECT wal_bytes AS wal_bytes_before FROM pg_stat_wal \gset +-- Test pg_stat_get_backend_wal (and make a temp table so our temp schema exists) +SELECT wal_bytes AS backend_wal_bytes_before from pg_stat_get_backend_wal(pg_backend_pid()) \gset CREATE TEMP TABLE test_stats_temp AS SELECT 17; DROP TABLE test_stats_temp; -- Checkpoint twice: The checkpointer reports stats after reporting completion @@ -851,6 +853,18 @@ SELECT wal_bytes > :wal_bytes_before FROM pg_stat_wal; t (1 row) +SELECT pg_stat_force_next_flush(); + pg_stat_force_next_flush +-------------------------- + +(1 row) + +SELECT wal_bytes > :backend_wal_bytes_before FROM pg_stat_get_backend_wal(pg_backend_pid()); + ?column? +---------- + t +(1 row) + -- Test pg_stat_get_backend_idset() and some allied functions. -- In particular, verify that their notion of backend ID matches -- our temp schema index. diff --git a/src/test/regress/sql/stats.sql b/src/test/regress/sql/stats.sql index 399c72bbcf7..28fe0a1a7d0 100644 --- a/src/test/regress/sql/stats.sql +++ b/src/test/regress/sql/stats.sql @@ -423,6 +423,9 @@ SELECT num_requested AS rqst_ckpts_before FROM pg_stat_checkpointer \gset -- Test pg_stat_wal (and make a temp table so our temp schema exists) SELECT wal_bytes AS wal_bytes_before FROM pg_stat_wal \gset +-- Test pg_stat_get_backend_wal (and make a temp table so our temp schema exists) +SELECT wal_bytes AS backend_wal_bytes_before from pg_stat_get_backend_wal(pg_backend_pid()) \gset + CREATE TEMP TABLE test_stats_temp AS SELECT 17; DROP TABLE test_stats_temp; @@ -435,6 +438,9 @@ CHECKPOINT; SELECT num_requested > :rqst_ckpts_before FROM pg_stat_checkpointer; SELECT wal_bytes > :wal_bytes_before FROM pg_stat_wal; +SELECT pg_stat_force_next_flush(); +SELECT wal_bytes > :backend_wal_bytes_before FROM pg_stat_get_backend_wal(pg_backend_pid()); + -- Test pg_stat_get_backend_idset() and some allied functions. -- In particular, verify that their notion of backend ID matches -- our temp schema index. -- 2.34.1