From a5cc07e1b9972f5480ce5c465678fcdaddc1b7eb Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Fri, 2 Oct 2026 21:52:08 -0700 Subject: [PATCH v18 9/9] pgstat: Derive pg_stat_database I/O timings from instrumentation pg_stat_database's blk_read_time and blk_write_time were accumulated in the backend-local counters pgStatBlockReadTime and pgStatBlockWriteTime, which pgstat_count_io_op_time() incremented alongside the equivalent fields of the current instrumentation stack entry. With the stack-based instrumentation the session-level totals are available in instr_top, so the separate counters are redundant. Remove the counters and the pgstat_count_buffer_read_time() and pgstat_count_buffer_write_time() macros, and instead have pgstat_update_dbstats() compute the increase of the shared and local block read/write times in instr_top since the previous report. This covers the same activity as before: relation and temp relation reads, writes and extends, but not temporary file I/O or WAL I/O. instr_top is only updated when an instrumentation stack entry is finalized, but pgstat_report_stat() is only called between transactions, when a backend is idle or at process exit. The stack is empty at the first two, but a FATAL error exits without unwinding the C stack and leaves entries behind, so finalize anything still on the stack before the final report. Parallel workers report their own activity themselves, like before, which requires each worker's instr_top to be complete. The switch to stack-based instrumentation left a gap, where per-node instrumentation does not accumulate upwards on the worker, to avoid double-counting in the leader import. Resolve by adding an additional walker that skips over the parent nodes and the query level instrumentation, directly accumulating to the top instrumentation in parallel workers. The leader additionally imports the workers' usage into its stack for query-level consumers such as EXPLAIN and pg_stat_statements, and thus into its instr_top. To count each activity exactly once, track everything imported from workers in the new instr_from_workers, updated at the same points as the import, and subtract it from instr_top when reporting. Since the amounts are now computed as a difference of the session totals, these totals must never be reset. Author: Lukas Fittl Reviewed-by: Discussion: https://postgr.es/m/CAP53PkzdBK8VJ1fS4AZ481LgMN8f9mJiC39ZRHqkFUSYq6KWmg%40mail.gmail.com --- src/backend/commands/analyze.c | 17 ++--- src/backend/executor/README.instrument | 17 ++++- src/backend/executor/execMain.c | 16 +++-- src/backend/executor/execProcnode.c | 49 +++++++++++++ src/backend/executor/instrument.c | 30 +++++++- src/backend/utils/activity/pgstat.c | 8 +++ src/backend/utils/activity/pgstat_database.c | 75 +++++++++++++++++--- src/backend/utils/activity/pgstat_io.c | 16 ++--- src/include/executor/executor.h | 2 + src/include/executor/instrument.h | 8 +++ src/include/pgstat.h | 8 --- 11 files changed, 203 insertions(+), 43 deletions(-) diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 371b56b339d..af3b67a3852 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -355,8 +355,6 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, int save_sec_context; int save_nestlevel; QueryInstrumentation *instr = NULL; - PgStat_Counter startreadtime = 0; - PgStat_Counter startwritetime = 0; verbose = (params->options & VACOPT_VERBOSE) != 0; instrument = (verbose || (AmAutoVacuumWorkerProcess() && @@ -394,16 +392,11 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, /* * When verbose or autovacuum logging is used, initialize a resource usage - * snapshot and optionally track I/O timing. + * snapshot and start instrumentation to track buffer usage (including I/O + * timing, if track_io_timing is enabled) and WAL usage. */ if (instrument) { - if (track_io_timing) - { - startreadtime = pgStatBlockReadTime; - startwritetime = pgStatBlockWriteTime; - } - pg_rusage_init(&ru0); instr = InstrQueryAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); @@ -851,8 +844,10 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, } if (track_io_timing) { - double read_ms = (double) (pgStatBlockReadTime - startreadtime) / 1000; - double write_ms = (double) (pgStatBlockWriteTime - startwritetime) / 1000; + double read_ms = INSTR_TIME_GET_MILLISEC(bufusage.shared_blk_read_time) + + INSTR_TIME_GET_MILLISEC(bufusage.local_blk_read_time); + double write_ms = INSTR_TIME_GET_MILLISEC(bufusage.shared_blk_write_time) + + INSTR_TIME_GET_MILLISEC(bufusage.local_blk_write_time); appendStringInfo(&buf, _("I/O timings: read: %.3f ms, write: %.3f ms\n"), read_ms, write_ms); diff --git a/src/backend/executor/README.instrument b/src/backend/executor/README.instrument index 51b0f72c29c..288131c0b5f 100644 --- a/src/backend/executor/README.instrument +++ b/src/backend/executor/README.instrument @@ -198,6 +198,12 @@ There are two mechanisms for achieving abort safety: even after an error, the base Instrumentation can be used with a PG_TRY/PG_FINALLY block that calls InstrStopFinalize(). +A FATAL error exits the process without unwinding the C stack, so the +PG_FINALLY path never runs for entries still open at that point. Since their +stack frames are left in place, InstrStackFinalizeAll() accumulates whatever +is still on the stack into instr_top right before the session totals are +reported for the last time (see pgstat_shutdown_hook). + Both mechanisms add overhead, so neither is suitable for high-frequency instrumentation like per-node measurements in the executor. Instead, plan node and trigger children rely on their parent QueryInstrumentation @@ -220,7 +226,16 @@ When per-node instrumentation is active, the worker's per-node stats are additionally copied into dynamic shared memory and aggregated into the leader's nodes through InstrAggNode(), which the leader then rolls up as usual. To avoid double counting, the worker does not roll up its own nodes -into its query entry. +into its query entry. Instead it adds each node's own stats directly to its +instr_top (ExecFinalizeNodeInstrumentationFlat), so that the worker's session +totals remain complete. + +As a result, a worker's instr_top accounts for everything the worker did, +also in case of errors, since its unfinalized entries end up in its instr_top +through the abort handling. The leader's instr_top additionally contains +what it imported from workers, which a session-level consumer that must count +activity exactly once, such as the cumulative statistics system, needs to +exclude. Memory Handling diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c index dd71e8028e5..232247df4c6 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -468,18 +468,26 @@ standard_ExecutorFinish(QueryDesc *queryDesc) * Accumulate per-node and trigger statistics to their respective * parent instrumentation stacks. * - * Parallel workers skip this: their per-node stats are reported + * Parallel workers instead add each node's own stats directly to + * their session totals (instr_top), without rolling them up into + * parent nodes or the query entry: their per-node stats are reported * individually via ExecParallelReportInstrumentation and the leader's * own ExecFinalizeNodeInstrumentation rolls them up after aggregating * them. If we rolled them up here, the leader would double-count, * both through the query-level stats and through worker parent nodes * already including their children's stats. */ - if (!IsParallelWorker() && estate->es_instrument) + if (estate->es_instrument) { - ExecFinalizeNodeInstrumentation(queryDesc->planstate); + if (!IsParallelWorker()) + { + ExecFinalizeNodeInstrumentation(queryDesc->planstate); - ExecFinalizeTriggerInstrumentation(estate); + ExecFinalizeTriggerInstrumentation(estate); + } + else + ExecFinalizeNodeInstrumentationFlat(queryDesc->planstate, + &instr_top); } InstrQueryStopFinalize(estate->es_query_instr); diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index 57a78325f47..311df126478 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -866,6 +866,55 @@ ExecFinalizeNodeInstrumentation_walker(PlanState *node, void *context) return false; } +static bool +ExecFinalizeNodeInstrumentationFlat_walker(PlanState *node, void *context) +{ + if (node == NULL) + return false; + + Assert(node->instrument != NULL); + + InstrFinalizeChild(&node->instrument->instr, (Instrumentation *) context); + + /* + * IndexScan/IndexOnlyScan have a separate entry to track table access, + * which also needs to be accounted for in the target. (The leader gets + * the per-worker copy of this entry via SharedIndexScanInstrumentation.) + */ + if (IsA(node, IndexScanState)) + { + IndexScanState *iss = castNode(IndexScanState, node); + + InstrFinalizeChild(&iss->iss_Instrument->table_instr, + (Instrumentation *) context); + } + else if (IsA(node, IndexOnlyScanState)) + { + IndexOnlyScanState *ioss = castNode(IndexOnlyScanState, node); + + InstrFinalizeChild(&ioss->ioss_Instrument->table_instr, + (Instrumentation *) context); + } + + return planstate_tree_walker(node, + ExecFinalizeNodeInstrumentationFlat_walker, + context); +} + +/* + * Like ExecFinalizeNodeInstrumentation, but accumulates each node's own stats + * directly to the target, without rolling them up into parent nodes. + * + * Used by parallel workers to account for their per-node activity in their + * session totals (instr_top), while leaving the per-node stats exclusive for + * the leader to aggregate and roll up. + */ +void +ExecFinalizeNodeInstrumentationFlat(PlanState *node, Instrumentation *target) +{ + (void) ExecFinalizeNodeInstrumentationFlat_walker(node, target); +} + /* * ExecFinalizeWorkerInstrumentation * diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index db93562a8fc..d2484e03f18 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -26,6 +26,7 @@ WalUsage pgWalUsage; Instrumentation instr_top; +Instrumentation instr_from_workers; InstrStackState instr_stack = { .stack_space = 0, .stack_size = 0, @@ -193,6 +194,24 @@ InstrStopFinalize(Instrumentation *instr) InstrStopFinalizeInternal(instr, false); } +/* + * Finalize whatever is still on the stack into instr_top, at process exit. + * + * A FATAL error exits without unwinding the C stack, so the PG_FINALLY blocks + * that would normally finalize plain Instrumentation entries never run. Such + * entries still live in their (abandoned) stack frames, so their activity can + * be accumulated before the session totals are reported for the last time. + * QueryInstrumentation entries have been released by the transaction abort + * that precedes this, and after a clean exit the stack is empty anyway. + */ +void +InstrStackFinalizeAll(void) +{ + while (instr_stack.stack_size > 0) + InstrStopFinalizeInternal(instr_stack.entries[instr_stack.stack_size - 1], + true); +} + /* * Finalize a child entry registered with InstrQueryRememberChild, by * accumulating its buffer/WAL usage to the provided instrumentation, which may @@ -398,8 +417,12 @@ InstrStartParallelQuery(void) } /* - * Report usage after parallel worker shutdown, to be handed to the leader - * (which accumulates it into its own stack, see InstrAccumParallelQuery). + * Report usage after parallel worker shutdown. + * + * The usage is both handed to the leader (which accumulates it into its own + * stack, see InstrAccumParallelQuery) and, through the finalization, added to + * the worker's own session totals in instr_top, so that each process' instr_top + * fully accounts for what the process itself did. */ void InstrEndParallelQuery(QueryInstrumentation *qinstr, BufferUsage *bufusage, WalUsage *walusage) @@ -415,6 +438,9 @@ InstrEndParallelQuery(QueryInstrumentation *qinstr, BufferUsage *bufusage, WalUs void InstrAccumWorkerUsage(const BufferUsage *bufusage, const WalUsage *walusage) { + BufferUsageAdd(&instr_from_workers.bufusage, bufusage); + WalUsageAdd(&instr_from_workers.walusage, walusage); + WalUsageAdd(&pgWalUsage, walusage); } diff --git a/src/backend/utils/activity/pgstat.c b/src/backend/utils/activity/pgstat.c index d31c0b48a1d..f7d83eeef4f 100644 --- a/src/backend/utils/activity/pgstat.c +++ b/src/backend/utils/activity/pgstat.c @@ -104,6 +104,7 @@ #include #include "access/xact.h" +#include "executor/instrument.h" #include "lib/dshash.h" #include "pgstat.h" #include "storage/fd.h" @@ -658,6 +659,13 @@ pgstat_shutdown_hook(int code, Datum arg) if (OidIsValid(MyDatabaseId)) pgstat_report_disconnect(MyDatabaseId); + /* + * Make sure the session totals we report from (instr_top) include what + * any instrumentation stack entries still open at this point measured; a + * FATAL error leaves the ones not tied to a resource owner behind. + */ + InstrStackFinalizeAll(); + pgstat_report_stat(true); /* there shouldn't be any pending changes left */ diff --git a/src/backend/utils/activity/pgstat_database.c b/src/backend/utils/activity/pgstat_database.c index 7f3bc016593..a006c889169 100644 --- a/src/backend/utils/activity/pgstat_database.c +++ b/src/backend/utils/activity/pgstat_database.c @@ -17,21 +17,30 @@ #include "postgres.h" +#include "executor/instrument.h" #include "storage/standby.h" #include "utils/pgstat_internal.h" #include "utils/timestamp.h" static bool pgstat_should_report_connstat(void); +static PgStat_Counter pgstat_block_io_time(const instr_time *shared_time, + const instr_time *local_time); -PgStat_Counter pgStatBlockReadTime = 0; -PgStat_Counter pgStatBlockWriteTime = 0; PgStat_Counter pgStatActiveTime = 0; PgStat_Counter pgStatTransactionIdleTime = 0; SessionEndType pgStatSessionEndCause = DISCONNECT_NORMAL; +/* + * Block I/O timings (in microseconds) of this process' own activity already + * reported to pg_stat_database, so that pgstat_update_dbstats() can compute + * how much they have increased since the previous report. + */ +static PgStat_Counter prevBlockReadTime = 0; +static PgStat_Counter prevBlockWriteTime = 0; + static int pgStatXactCommit = 0; static int pgStatXactRollback = 0; static PgStat_Counter pgLastSessionReportTime = 0; @@ -344,13 +353,52 @@ pgstat_update_dbstats(TimestampTz ts) dbentry = pgstat_prep_database_pending(MyDatabaseId); /* - * Accumulate xact commit/rollback and I/O timings to stats entry of the - * current database. + * Accumulate xact commit/rollback to stats entry of the current database. */ dbentry->xact_commit += pgStatXactCommit; dbentry->xact_rollback += pgStatXactRollback; - dbentry->blk_read_time += pgStatBlockReadTime; - dbentry->blk_write_time += pgStatBlockWriteTime; + + /* + * Accumulate block I/O timings from the session-level buffer usage totals + * in instr_top, which only count shared and local blocks (not temporary + * files). These totals are updated whenever an instrumentation stack + * entry is finalized, and the stack is empty at the points where + * pgstat_report_stat() gets called, so this reflects all activity so far. + * + * In a parallel query leader, instr_top also includes the usage imported + * from parallel workers, which the workers report themselves, so subtract + * instr_from_workers to only count this process' own activity. + * + * Imports are recorded in instr_from_workers right away, but only reach + * instr_top once the enclosing stack entry is finalized. Should a report + * ever happen in between, the own activity computed here can temporarily + * be lower than at the previous report. Simply don't advance in that + * case, the next report will catch up. + */ + { + PgStat_Counter read_us, + write_us; + + read_us = pgstat_block_io_time(&instr_top.bufusage.shared_blk_read_time, + &instr_top.bufusage.local_blk_read_time) - + pgstat_block_io_time(&instr_from_workers.bufusage.shared_blk_read_time, + &instr_from_workers.bufusage.local_blk_read_time); + write_us = pgstat_block_io_time(&instr_top.bufusage.shared_blk_write_time, + &instr_top.bufusage.local_blk_write_time) - + pgstat_block_io_time(&instr_from_workers.bufusage.shared_blk_write_time, + &instr_from_workers.bufusage.local_blk_write_time); + + if (read_us >= prevBlockReadTime) + { + dbentry->blk_read_time += read_us - prevBlockReadTime; + prevBlockReadTime = read_us; + } + if (write_us >= prevBlockWriteTime) + { + dbentry->blk_write_time += write_us - prevBlockWriteTime; + prevBlockWriteTime = write_us; + } + } if (pgstat_should_report_connstat()) { @@ -370,8 +418,6 @@ pgstat_update_dbstats(TimestampTz ts) pgStatXactCommit = 0; pgStatXactRollback = 0; - pgStatBlockReadTime = 0; - pgStatBlockWriteTime = 0; pgStatActiveTime = 0; pgStatTransactionIdleTime = 0; } @@ -389,6 +435,19 @@ pgstat_should_report_connstat(void) return MyBackendType == B_BACKEND; } +/* + * Total of the given shared and local block I/O times in microseconds, which + * is what pg_stat_database counts as block read/write time. + */ +static PgStat_Counter +pgstat_block_io_time(const instr_time *shared_time, const instr_time *local_time) +{ + instr_time total = *shared_time; + + INSTR_TIME_ADD(total, *local_time); + return INSTR_TIME_GET_MICROSEC(total); +} + /* * Find or create a local PgStat_StatDBEntry entry for dboid. */ diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c index 8c02cd2d40f..d37cebc52a7 100644 --- a/src/backend/utils/activity/pgstat_io.c +++ b/src/backend/utils/activity/pgstat_io.c @@ -102,13 +102,13 @@ pgstat_prepare_io_time(bool track_io_guc) /* * Like pgstat_count_io_op() except it also accumulates time. * - * The calls related to pgstat_count_buffer_*() are for pgstat_database. As - * pg_stat_database only counts block read and write times, these are done for - * IOOP_READ, IOOP_WRITE and IOOP_EXTEND. - * - * Executor instrumentation is used for EXPLAIN. Buffer usage tracked there has - * write and read stats for shared, local and temporary blocks. pg_stat_io - * does not track the activity of temporary blocks, so these are ignored here. + * Buffer usage instrumentation tracks read and write times for shared and + * local blocks (IOOP_EXTEND counts as a write). Besides EXPLAIN and + * pg_stat_statements, this also feeds pg_stat_database, which derives its + * blk_read_time/blk_write_time from the session-level totals in instr_top at + * flush time, see pgstat_update_dbstats(). Buffer usage additionally tracks + * temporary file blocks, but pg_stat_io does not track those, so they are + * ignored here. */ void pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, @@ -125,7 +125,6 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, { if (io_op == IOOP_WRITE || io_op == IOOP_EXTEND) { - pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time)); if (io_object == IOOBJECT_RELATION) INSTR_BUFUSAGE_TIME_ADD(shared_blk_write_time, io_time); else if (io_object == IOOBJECT_TEMP_RELATION) @@ -133,7 +132,6 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, } else if (io_op == IOOP_READ) { - pgstat_count_buffer_read_time(INSTR_TIME_GET_MICROSEC(io_time)); if (io_object == IOOBJECT_RELATION) INSTR_BUFUSAGE_TIME_ADD(shared_blk_read_time, io_time); else if (io_object == IOOBJECT_TEMP_RELATION) diff --git a/src/include/executor/executor.h b/src/include/executor/executor.h index f6fad6a6e68..16e4cb4663d 100644 --- a/src/include/executor/executor.h +++ b/src/include/executor/executor.h @@ -304,6 +304,8 @@ extern Node *MultiExecProcNode(PlanState *node); extern void ExecEndNode(PlanState *node); extern void ExecShutdownNode(PlanState *node); extern void ExecFinalizeNodeInstrumentation(PlanState *node); +extern void ExecFinalizeNodeInstrumentationFlat(PlanState *node, + Instrumentation *target); extern void ExecFinalizeWorkerInstrumentation(PlanState *node); extern void ExecSetTupleBound(int64 tuples_needed, PlanState *child_node); diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 17d560fb982..df76271d09b 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -226,6 +226,13 @@ extern PGDLLIMPORT WalUsage pgWalUsage; */ extern PGDLLIMPORT Instrumentation instr_top; +/* + * Running total of the WAL/buffer usage imported from parallel workers into + * this process' instrumentation stack (and thus eventually into instr_top). + * Updated through InstrAccumWorkerUsage, only the usage fields are used. + */ +extern PGDLLIMPORT Instrumentation instr_from_workers; + /* * The instrumentation stack state. The 'current' field points to the * currently active stack entry that is getting updated as activity happens, @@ -279,6 +286,7 @@ extern void InstrInitOptions(Instrumentation *instr, int instrument_options); extern void InstrStart(Instrumentation *instr); extern void InstrStop(Instrumentation *instr); extern void InstrStopFinalize(Instrumentation *instr); +extern void InstrStackFinalizeAll(void); extern void InstrFinalizeChild(Instrumentation *instr, Instrumentation *parent); extern void InstrAccumStack(Instrumentation *dst, Instrumentation *add); diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 9b99062f853..4d01a8702ed 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -739,10 +739,6 @@ extern void pgstat_report_connect(Oid dboid); extern void pgstat_update_parallel_workers_stats(PgStat_Counter workers_to_launch, PgStat_Counter workers_launched); -#define pgstat_count_buffer_read_time(n) \ - (pgStatBlockReadTime += (n)) -#define pgstat_count_buffer_write_time(n) \ - (pgStatBlockWriteTime += (n)) #define pgstat_count_conn_active_time(n) \ (pgStatActiveTime += (n)) #define pgstat_count_conn_txn_idle_time(n) \ @@ -981,10 +977,6 @@ extern PGDLLIMPORT PgStat_CheckpointerStats PendingCheckpointerStats; * Variables in pgstat_database.c */ -/* Updated by pgstat_count_buffer_*_time macros */ -extern PGDLLIMPORT PgStat_Counter pgStatBlockReadTime; -extern PGDLLIMPORT PgStat_Counter pgStatBlockWriteTime; - /* * Updated by pgstat_count_conn_*_time macros, called by * pgstat_report_activity(). -- 2.47.1