From 8d8eb51f722073826f879c8b1c3b50a7cd7bb68b Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Sun, 5 Apr 2026 05:08:23 -0700 Subject: [PATCH v18 1/9] 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 Instrumentation struct and associated helpers. Author: Lukas Fittl Reviewed-by: Discussion: https://postgr.es/m/CAP53PkzdBK8VJ1fS4AZ481LgMN8f9mJiC39ZRHqkFUSYq6KWmg%40mail.gmail.com --- .../pg_stat_statements/pg_stat_statements.c | 62 +++++-------------- src/backend/access/heap/vacuumlazy.c | 17 ++--- src/backend/commands/analyze.c | 31 +++++----- src/backend/commands/explain.c | 44 +++++++------ src/backend/commands/explain_dr.c | 53 ++++++---------- src/backend/commands/prepare.c | 28 ++++----- src/include/commands/explain_dr.h | 5 +- 7 files changed, 93 insertions(+), 147 deletions(-) diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index 8db4b3d6e24..3f3604cda84 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -920,22 +920,16 @@ 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; - - /* We need to track buffer usage as the planner can access them. */ - bufusage_start = pgBufferUsage; + Instrumentation instr = {0}; /* + * We need to track buffer usage as the planner can access them. + * * 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); + InstrInitOptions(&instr, INSTRUMENT_ALL); + InstrStart(&instr); nesting_level++; PG_TRY(); @@ -953,16 +947,7 @@ pgss_planner(Query *parse, } 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); + InstrStop(&instr); pgss_store(query_string, parse->queryId, @@ -970,10 +955,10 @@ pgss_planner(Query *parse, parse->stmt_len, nesting_level == 0, PGSS_PLAN, - INSTR_TIME_GET_MILLISEC(duration), + INSTR_TIME_GET_MILLISEC(instr.total), 0, - &bufusage, - &walusage, + &instr.bufusage, + &instr.walusage, NULL, NULL, 0, @@ -1172,17 +1157,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(); @@ -1213,8 +1192,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, */ pstmt = NULL; - INSTR_TIME_SET_CURRENT(duration); - INSTR_TIME_SUBTRACT(duration, start); + InstrStop(&instr); /* * Track the total number of rows retrieved or affected by the utility @@ -1227,24 +1205,16 @@ 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, nesting_level == 0, 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 3e2fc8f0b24..f2ee5dccc9f 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -636,8 +636,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, new_rel_allfrozen; PGRUsage ru0; TimestampTz starttime = 0; - WalUsage startwalusage = pgWalUsage; - BufferUsage startbufferusage = pgBufferUsage; + Instrumentation *instr = NULL; ErrorContextCallback errcallback; char **indnames = NULL; Size dead_items_max_bytes = 0; @@ -646,7 +645,11 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, instrument = (verbose || (AmAutoVacuumWorkerProcess() && params->log_vacuum_min_duration >= 0)); if (instrument) + { pg_rusage_init(&ru0); + instr = InstrAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); + InstrStart(instr); + } /* Used for instrumentation and stats report */ starttime = GetCurrentTimestamp(); @@ -986,14 +989,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; @@ -1002,12 +1005,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 518d7526255..382b3181374 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -354,9 +354,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; @@ -407,6 +405,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 */ @@ -769,12 +770,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; @@ -782,18 +784,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 4b1ad4227ac..ca8c071ec04 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -327,14 +327,17 @@ standard_ExplainOneQuery(Query *query, int cursorOptions, QueryEnvironment *queryEnv) { PlannedStmt *plan; - instr_time planstart, - 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) { /* @@ -351,15 +354,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) { @@ -367,16 +367,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); } @@ -595,7 +588,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); @@ -1024,7 +1022,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 @@ -1032,10 +1030,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--; } } @@ -1043,13 +1041,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 97166f9c06c..9f9e73f14a3 100644 --- a/src/backend/commands/explain_dr.c +++ b/src/backend/commands/explain_dr.c @@ -110,15 +110,10 @@ 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; + /* Start per-tuple measurement */ + InstrStart(instr); /* Set or update my derived attribute info, if needed */ if (myState->attrinfo != typeinfo || myState->nattrs != natts) @@ -186,18 +181,8 @@ 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 */ + InstrStop(instr); return true; } @@ -209,6 +194,7 @@ static void serializeAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo) { SerializeDestReceiver *receiver = (SerializeDestReceiver *) self; + int instrument_options = 0; Assert(receiver->es != NULL); @@ -233,9 +219,13 @@ 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); + if (receiver->es->timing) + instrument_options |= INSTRUMENT_TIMER; + if (receiver->es->buffers) + instrument_options |= INSTRUMENT_BUFFERS; + InstrInitOptions(&receiver->metrics.instr, instrument_options); } /* @@ -290,22 +280,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