From 1b84f1215269f91f7eef02ca6237fb8355fba3da Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Sun, 5 Apr 2026 05:08:23 -0700 Subject: [PATCH v13 03/12] instrumentation: Use Instrumentation instead of manual buffer tracking This replaces different repeated code blocks that read pgBufferUsage / pgWalUsage, and may have also been running a timer to measure activity, with the new Instrumentation struct and associated helpers. Author: Lukas Fittl Reviewed-by: Discussion: --- .../pg_stat_statements/pg_stat_statements.c | 67 +++++-------------- src/backend/access/heap/vacuumlazy.c | 15 ++--- src/backend/commands/analyze.c | 31 +++++---- src/backend/commands/explain.c | 44 ++++++------ src/backend/commands/explain_dr.c | 56 +++++++--------- src/backend/commands/prepare.c | 28 +++----- src/include/commands/explain_dr.h | 5 +- 7 files changed, 94 insertions(+), 152 deletions(-) diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index fbf32f0e72c..63975706b87 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -911,22 +911,11 @@ pgss_planner(Query *parse, && pgss_track_planning && query_string && parse->queryId != INT64CONST(0)) { - instr_time start; - instr_time duration; - BufferUsage bufusage_start, - bufusage; - WalUsage walusage_start, - walusage; + Instrumentation instr = {0}; - /* We need to track buffer usage as the planner can access them. */ - bufusage_start = pgBufferUsage; - - /* - * Similarly the planner could write some WAL records in some cases - * (e.g. setting a hint bit with those being WAL-logged) - */ - walusage_start = pgWalUsage; - INSTR_TIME_SET_CURRENT(start); + /* Track time and buffer/WAL usage as the planner can access them. */ + InstrInitOptions(&instr, INSTRUMENT_ALL); + InstrStart(&instr); nesting_level++; PG_TRY(); @@ -940,30 +929,20 @@ pgss_planner(Query *parse, } PG_FINALLY(); { + InstrStop(&instr); nesting_level--; } PG_END_TRY(); - INSTR_TIME_SET_CURRENT(duration); - INSTR_TIME_SUBTRACT(duration, start); - - /* calc differences of buffer counters. */ - memset(&bufusage, 0, sizeof(BufferUsage)); - BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start); - - /* calc differences of WAL counters. */ - memset(&walusage, 0, sizeof(WalUsage)); - WalUsageAccumDiff(&walusage, &pgWalUsage, &walusage_start); - pgss_store(query_string, parse->queryId, parse->stmt_location, parse->stmt_len, PGSS_PLAN, - INSTR_TIME_GET_MILLISEC(duration), + INSTR_TIME_GET_MILLISEC(instr.total), 0, - &bufusage, - &walusage, + &instr.bufusage, + &instr.walusage, NULL, NULL, 0, @@ -1156,17 +1135,11 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, !IsA(parsetree, ExecuteStmt) && !IsA(parsetree, PrepareStmt)) { - instr_time start; - instr_time duration; uint64 rows; - BufferUsage bufusage_start, - bufusage; - WalUsage walusage_start, - walusage; + Instrumentation instr = {0}; - bufusage_start = pgBufferUsage; - walusage_start = pgWalUsage; - INSTR_TIME_SET_CURRENT(start); + InstrInitOptions(&instr, INSTRUMENT_ALL); + InstrStart(&instr); nesting_level++; PG_TRY(); @@ -1182,6 +1155,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, } PG_FINALLY(); { + InstrStop(&instr); nesting_level--; } PG_END_TRY(); @@ -1196,9 +1170,6 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, * former value, which'd otherwise be a good idea. */ - INSTR_TIME_SET_CURRENT(duration); - INSTR_TIME_SUBTRACT(duration, start); - /* * Track the total number of rows retrieved or affected by the utility * statements of COPY, FETCH, CREATE TABLE AS, CREATE MATERIALIZED @@ -1210,23 +1181,15 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, qc->commandTag == CMDTAG_REFRESH_MATERIALIZED_VIEW)) ? qc->nprocessed : 0; - /* calc differences of buffer counters. */ - memset(&bufusage, 0, sizeof(BufferUsage)); - BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start); - - /* calc differences of WAL counters. */ - memset(&walusage, 0, sizeof(WalUsage)); - WalUsageAccumDiff(&walusage, &pgWalUsage, &walusage_start); - pgss_store(queryString, saved_queryId, saved_stmt_location, saved_stmt_len, PGSS_EXEC, - INSTR_TIME_GET_MILLISEC(duration), + INSTR_TIME_GET_MILLISEC(instr.total), rows, - &bufusage, - &walusage, + &instr.bufusage, + &instr.walusage, NULL, NULL, 0, diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 88c71cd85b6..30f589c9207 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -637,8 +637,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, TimestampTz starttime = 0; PgStat_Counter startreadtime = 0, startwritetime = 0; - WalUsage startwalusage = pgWalUsage; - BufferUsage startbufferusage = pgBufferUsage; + Instrumentation *instr = NULL; ErrorContextCallback errcallback; char **indnames = NULL; Size dead_items_max_bytes = 0; @@ -654,6 +653,8 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, startreadtime = pgStatBlockReadTime; startwritetime = pgStatBlockWriteTime; } + instr = InstrAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); + InstrStart(instr); } /* Used for instrumentation and stats report */ @@ -984,14 +985,14 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, { TimestampTz endtime = GetCurrentTimestamp(); + InstrStop(instr); + if (verbose || params->log_vacuum_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_vacuum_min_duration)) { long secs_dur; int usecs_dur; - WalUsage walusage; - BufferUsage bufferusage; StringInfoData buf; char *msgfmt; int32 diff; @@ -1000,12 +1001,10 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, int64 total_blks_hit; int64 total_blks_read; int64 total_blks_dirtied; + BufferUsage bufferusage = instr->bufusage; + WalUsage walusage = instr->walusage; TimestampDifference(starttime, endtime, &secs_dur, &usecs_dur); - memset(&walusage, 0, sizeof(WalUsage)); - WalUsageAccumDiff(&walusage, &pgWalUsage, &startwalusage); - memset(&bufferusage, 0, sizeof(BufferUsage)); - BufferUsageAccumDiff(&bufferusage, &pgBufferUsage, &startbufferusage); total_blks_hit = bufferusage.shared_blks_hit + bufferusage.local_blks_hit; diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 49a5cdf579c..8472fc0c280 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -309,9 +309,7 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, Oid save_userid; int save_sec_context; int save_nestlevel; - WalUsage startwalusage = pgWalUsage; - BufferUsage startbufferusage = pgBufferUsage; - BufferUsage bufferusage; + Instrumentation *instr = NULL; PgStat_Counter startreadtime = 0; PgStat_Counter startwritetime = 0; @@ -362,6 +360,9 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, } pg_rusage_init(&ru0); + + instr = InstrAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); + InstrStart(instr); } /* Used for instrumentation and stats report */ @@ -742,12 +743,13 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, { TimestampTz endtime = GetCurrentTimestamp(); + InstrStop(instr); + if (verbose || params->log_analyze_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_analyze_min_duration)) { long delay_in_ms; - WalUsage walusage; double read_rate = 0; double write_rate = 0; char *msgfmt; @@ -755,18 +757,15 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, int64 total_blks_hit; int64 total_blks_read; int64 total_blks_dirtied; - - memset(&bufferusage, 0, sizeof(BufferUsage)); - BufferUsageAccumDiff(&bufferusage, &pgBufferUsage, &startbufferusage); - memset(&walusage, 0, sizeof(WalUsage)); - WalUsageAccumDiff(&walusage, &pgWalUsage, &startwalusage); - - total_blks_hit = bufferusage.shared_blks_hit + - bufferusage.local_blks_hit; - total_blks_read = bufferusage.shared_blks_read + - bufferusage.local_blks_read; - total_blks_dirtied = bufferusage.shared_blks_dirtied + - bufferusage.local_blks_dirtied; + BufferUsage bufusage = instr->bufusage; + WalUsage walusage = instr->walusage; + + total_blks_hit = bufusage.shared_blks_hit + + bufusage.local_blks_hit; + total_blks_read = bufusage.shared_blks_read + + bufusage.local_blks_read; + total_blks_dirtied = bufusage.shared_blks_dirtied + + bufusage.local_blks_dirtied; /* * We do not expect an analyze to take > 25 days and it simplifies diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index e73dc129132..e7550a8ac46 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -324,13 +324,16 @@ standard_ExplainOneQuery(Query *query, int cursorOptions, QueryEnvironment *queryEnv) { PlannedStmt *plan; - instr_time planstart, - planduration; - BufferUsage bufusage_start, - bufusage; + Instrumentation plan_instr = {0}; MemoryContextCounters mem_counters; MemoryContext planner_ctx = NULL; MemoryContext saved_ctx = NULL; + int instrument_options = INSTRUMENT_TIMER; + + if (es->buffers) + instrument_options |= INSTRUMENT_BUFFERS; + + InstrInitOptions(&plan_instr, instrument_options); if (es->memory) { @@ -348,15 +351,12 @@ standard_ExplainOneQuery(Query *query, int cursorOptions, saved_ctx = MemoryContextSwitchTo(planner_ctx); } - if (es->buffers) - bufusage_start = pgBufferUsage; - INSTR_TIME_SET_CURRENT(planstart); + InstrStart(&plan_instr); /* plan the query */ plan = pg_plan_query(query, queryString, cursorOptions, params, es); - INSTR_TIME_SET_CURRENT(planduration); - INSTR_TIME_SUBTRACT(planduration, planstart); + InstrStop(&plan_instr); if (es->memory) { @@ -364,16 +364,9 @@ standard_ExplainOneQuery(Query *query, int cursorOptions, MemoryContextMemConsumed(planner_ctx, &mem_counters); } - /* calc differences of buffer counters. */ - if (es->buffers) - { - memset(&bufusage, 0, sizeof(BufferUsage)); - BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start); - } - /* run it (if needed) and produce output */ ExplainOnePlan(plan, into, es, queryString, params, queryEnv, - &planduration, (es->buffers ? &bufusage : NULL), + &plan_instr.total, (es->buffers ? &plan_instr.bufusage : NULL), es->memory ? &mem_counters : NULL); } @@ -590,7 +583,12 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, /* grab serialization metrics before we destroy the DestReceiver */ if (es->serialize != EXPLAIN_SERIALIZE_NONE) - serializeMetrics = GetSerializationMetrics(dest); + { + SerializeMetrics *metrics = GetSerializationMetrics(dest); + + if (metrics) + memcpy(&serializeMetrics, metrics, sizeof(SerializeMetrics)); + } /* call the DestReceiver's destroy method even during explain */ dest->rDestroy(dest); @@ -1019,7 +1017,7 @@ ExplainPrintSerialize(ExplainState *es, SerializeMetrics *metrics) ExplainIndentText(es); if (es->timing) appendStringInfo(es->str, "Serialization: time=%.3f ms output=" UINT64_FORMAT "kB format=%s\n", - 1000.0 * INSTR_TIME_GET_DOUBLE(metrics->timeSpent), + 1000.0 * INSTR_TIME_GET_DOUBLE(metrics->instr.total), BYTES_TO_KILOBYTES(metrics->bytesSent), format); else @@ -1027,10 +1025,10 @@ ExplainPrintSerialize(ExplainState *es, SerializeMetrics *metrics) BYTES_TO_KILOBYTES(metrics->bytesSent), format); - if (es->buffers && peek_buffer_usage(es, &metrics->bufferUsage)) + if (es->buffers && peek_buffer_usage(es, &metrics->instr.bufusage)) { es->indent++; - show_buffer_usage(es, &metrics->bufferUsage); + show_buffer_usage(es, &metrics->instr.bufusage); es->indent--; } } @@ -1038,13 +1036,13 @@ ExplainPrintSerialize(ExplainState *es, SerializeMetrics *metrics) { if (es->timing) ExplainPropertyFloat("Time", "ms", - 1000.0 * INSTR_TIME_GET_DOUBLE(metrics->timeSpent), + 1000.0 * INSTR_TIME_GET_DOUBLE(metrics->instr.total), 3, es); ExplainPropertyUInteger("Output Volume", "kB", BYTES_TO_KILOBYTES(metrics->bytesSent), es); ExplainPropertyText("Format", format, es); if (es->buffers) - show_buffer_usage(es, &metrics->bufferUsage); + show_buffer_usage(es, &metrics->instr.bufusage); } ExplainCloseGroup("Serialization", "Serialization", true, es); diff --git a/src/backend/commands/explain_dr.c b/src/backend/commands/explain_dr.c index 3c96061cf32..34fe4f8f6dd 100644 --- a/src/backend/commands/explain_dr.c +++ b/src/backend/commands/explain_dr.c @@ -110,15 +110,11 @@ serializeAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self) MemoryContext oldcontext; StringInfo buf = &myState->buf; int natts = typeinfo->natts; - instr_time start, - end; - BufferUsage instr_start; + Instrumentation *instr = &myState->metrics.instr; /* only measure time, buffers if requested */ - if (myState->es->timing) - INSTR_TIME_SET_CURRENT(start); - if (myState->es->buffers) - instr_start = pgBufferUsage; + if (instr->need_timer || instr->need_bufusage) + InstrStart(instr); /* Set or update my derived attribute info, if needed */ if (myState->attrinfo != typeinfo || myState->nattrs != natts) @@ -186,18 +182,9 @@ serializeAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self) MemoryContextSwitchTo(oldcontext); MemoryContextReset(myState->tmpcontext); - /* Update timing data */ - if (myState->es->timing) - { - INSTR_TIME_SET_CURRENT(end); - INSTR_TIME_ACCUM_DIFF(myState->metrics.timeSpent, end, start); - } - - /* Update buffer metrics */ - if (myState->es->buffers) - BufferUsageAccumDiff(&myState->metrics.bufferUsage, - &pgBufferUsage, - &instr_start); + /* Stop per-tuple measurement */ + if (instr->need_timer || instr->need_bufusage) + InstrStop(instr); return true; } @@ -233,9 +220,17 @@ serializeAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo) /* The output buffer is re-used across rows, as in printtup.c */ initStringInfo(&receiver->buf); - /* Initialize results counters */ + /* Initialize metrics and per-tuple instrumentation */ memset(&receiver->metrics, 0, sizeof(SerializeMetrics)); - INSTR_TIME_SET_ZERO(receiver->metrics.timeSpent); + { + int instrument_options = 0; + + if (receiver->es->timing) + instrument_options |= INSTRUMENT_TIMER; + if (receiver->es->buffers) + instrument_options |= INSTRUMENT_BUFFERS; + InstrInitOptions(&receiver->metrics.instr, instrument_options); + } } /* @@ -290,22 +285,17 @@ CreateExplainSerializeDestReceiver(ExplainState *es) } /* - * GetSerializationMetrics - collect metrics + * GetSerializationMetrics - get serialization metrics * - * We have to be careful here since the receiver could be an IntoRel - * receiver if the subject statement is CREATE TABLE AS. In that - * case, return all-zeroes stats. + * Returns a pointer to the SerializeMetrics inside the dest receiver, + * or NULL if the receiver is not a SerializeDestReceiver (e.g. an IntoRel + * receiver for CREATE TABLE AS). */ -SerializeMetrics +SerializeMetrics * GetSerializationMetrics(DestReceiver *dest) { - SerializeMetrics empty; - if (dest->mydest == DestExplainSerialize) - return ((SerializeDestReceiver *) dest)->metrics; - - memset(&empty, 0, sizeof(SerializeMetrics)); - INSTR_TIME_SET_ZERO(empty.timeSpent); + return &((SerializeDestReceiver *) dest)->metrics; - return empty; + return NULL; } diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c index 876aad2100a..bf9f2eb6149 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -22,6 +22,7 @@ #include "catalog/pg_type.h" #include "commands/createas.h" #include "commands/explain.h" +#include "executor/instrument.h" #include "commands/explain_format.h" #include "commands/explain_state.h" #include "commands/prepare.h" @@ -580,14 +581,17 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, ListCell *p; ParamListInfo paramLI = NULL; EState *estate = NULL; - instr_time planstart; - instr_time planduration; - BufferUsage bufusage_start, - bufusage; + Instrumentation plan_instr = {0}; + int instrument_options = INSTRUMENT_TIMER; MemoryContextCounters mem_counters; MemoryContext planner_ctx = NULL; MemoryContext saved_ctx = NULL; + if (es->buffers) + instrument_options |= INSTRUMENT_BUFFERS; + + InstrInitOptions(&plan_instr, instrument_options); + if (es->memory) { /* See ExplainOneQuery about this */ @@ -598,9 +602,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, saved_ctx = MemoryContextSwitchTo(planner_ctx); } - if (es->buffers) - bufusage_start = pgBufferUsage; - INSTR_TIME_SET_CURRENT(planstart); + InstrStart(&plan_instr); /* Look it up in the hash table */ entry = FetchPreparedStatement(execstmt->name, true); @@ -635,8 +637,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, cplan = GetCachedPlan(entry->plansource, paramLI, CurrentResourceOwner, pstate->p_queryEnv); - INSTR_TIME_SET_CURRENT(planduration); - INSTR_TIME_SUBTRACT(planduration, planstart); + InstrStop(&plan_instr); if (es->memory) { @@ -644,13 +645,6 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, MemoryContextMemConsumed(planner_ctx, &mem_counters); } - /* calc differences of buffer counters. */ - if (es->buffers) - { - memset(&bufusage, 0, sizeof(BufferUsage)); - BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start); - } - plan_list = cplan->stmt_list; /* Explain each query */ @@ -660,7 +654,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, if (pstmt->commandType != CMD_UTILITY) ExplainOnePlan(pstmt, into, es, query_string, paramLI, pstate->p_queryEnv, - &planduration, (es->buffers ? &bufusage : NULL), + &plan_instr.total, (es->buffers ? &plan_instr.bufusage : NULL), es->memory ? &mem_counters : NULL); else ExplainOneUtility(pstmt->utilityStmt, into, es, pstate, paramLI); diff --git a/src/include/commands/explain_dr.h b/src/include/commands/explain_dr.h index f98eaae1864..ab5c53023e1 100644 --- a/src/include/commands/explain_dr.h +++ b/src/include/commands/explain_dr.h @@ -23,11 +23,10 @@ typedef struct ExplainState ExplainState; typedef struct SerializeMetrics { uint64 bytesSent; /* # of bytes serialized */ - instr_time timeSpent; /* time spent serializing */ - BufferUsage bufferUsage; /* buffers accessed during serialization */ + Instrumentation instr; /* time and buffer usage */ } SerializeMetrics; extern DestReceiver *CreateExplainSerializeDestReceiver(ExplainState *es); -extern SerializeMetrics GetSerializationMetrics(DestReceiver *dest); +extern SerializeMetrics *GetSerializationMetrics(DestReceiver *dest); #endif -- 2.47.1