From 8d8eb51f722073826f879c8b1c3b50a7cd7bb68b Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Sun, 5 Apr 2026 05:08:23 -0700 Subject: [PATCH 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 8db4b3d6e24b9..3f3604cda84ba 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 3e2fc8f0b24cc..f2ee5dccc9fe2 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 518d7526255b5..382b318137456 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 4b1ad4227acb4..ca8c071ec0414 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 97166f9c06c5a..9f9e73f14a33e 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 876aad2100aeb..bf9f2eb614997 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 f98eaae186457..ab5c53023e1e6 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 From ec77115024c24e681cb3496eddb7e579476adc67 Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Thu, 26 Mar 2026 23:31:04 -0700 Subject: [PATCH 2/9] instrumentation: Replace direct changes of pgBufferUsage/pgWalUsage with INSTR_* macros This encapsulates the ownership of these globals better, and will allow a subsequent refactoring. Author: Lukas Fittl Reviewed-by: Andres Freund Reviewed-by: Zsolt Parragi Discussion: https://postgr.es/m/CAP53PkzZ3UotnRrrnXWAv%3DF4avRq9MQ8zU%2BbxoN9tpovEu6fGQ%40mail.gmail.com#fc7140e8af21e07a90a09d7e76b300c4 --- src/backend/access/transam/xlog.c | 10 +++++----- src/backend/storage/buffer/bufmgr.c | 20 ++++++++++---------- src/backend/storage/buffer/localbuf.c | 6 +++--- src/backend/storage/file/buffile.c | 8 ++++---- src/backend/utils/activity/pgstat_io.c | 8 ++++---- src/include/executor/instrument.h | 19 +++++++++++++++++++ 6 files changed, 45 insertions(+), 26 deletions(-) diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 8636ad9ab2c7b..df7239c718984 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -1172,10 +1172,10 @@ XLogInsertRecord(XLogRecData *rdata, /* Report WAL traffic to the instrumentation. */ if (inserted) { - pgWalUsage.wal_bytes += rechdr->xl_tot_len; - pgWalUsage.wal_records++; - pgWalUsage.wal_fpi += num_fpi; - pgWalUsage.wal_fpi_bytes += fpi_bytes; + INSTR_WALUSAGE_ADD(wal_bytes, rechdr->xl_tot_len); + INSTR_WALUSAGE_INCR(wal_records); + INSTR_WALUSAGE_ADD(wal_fpi, num_fpi); + INSTR_WALUSAGE_ADD(wal_fpi_bytes, fpi_bytes); /* Required for the flush of pending stats WAL data */ pgstat_report_fixed = true; @@ -2160,7 +2160,7 @@ AdvanceXLInsertBuffer(XLogRecPtr upto, TimeLineID tli, bool opportunistic) WriteRqst.Flush = InvalidXLogRecPtr; XLogWrite(WriteRqst, tli, false); LWLockRelease(WALWriteLock); - pgWalUsage.wal_buffers_full++; + INSTR_WALUSAGE_INCR(wal_buffers_full); TRACE_POSTGRESQL_WAL_BUFFER_WRITE_DIRTY_DONE(); /* diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c index c17fc3590f0cd..13327f5de8ee4 100644 --- a/src/backend/storage/buffer/bufmgr.c +++ b/src/backend/storage/buffer/bufmgr.c @@ -842,7 +842,7 @@ ReadRecentBuffer(RelFileLocator rlocator, ForkNumber forkNum, BlockNumber blockN { PinLocalBuffer(bufHdr, true); - pgBufferUsage.local_blks_hit++; + INSTR_BUFUSAGE_INCR(local_blks_hit); return true; } @@ -863,7 +863,7 @@ ReadRecentBuffer(RelFileLocator rlocator, ForkNumber forkNum, BlockNumber blockN { if (BufferTagsEqual(&tag, &bufHdr->tag)) { - pgBufferUsage.shared_blks_hit++; + INSTR_BUFUSAGE_INCR(shared_blks_hit); return true; } UnpinBuffer(bufHdr); @@ -1695,9 +1695,9 @@ TrackBufferHit(IOObject io_object, IOContext io_context, true); if (persistence == RELPERSISTENCE_TEMP) - pgBufferUsage.local_blks_hit += 1; + INSTR_BUFUSAGE_INCR(local_blks_hit); else - pgBufferUsage.shared_blks_hit += 1; + INSTR_BUFUSAGE_INCR(shared_blks_hit); pgstat_count_io_op(io_object, io_context, IOOP_HIT, 1, 0); @@ -2159,9 +2159,9 @@ AsyncReadBuffers(ReadBuffersOperation *operation, int *nblocks_progress) io_start, 1, io_buffers_len * BLCKSZ); if (persistence == RELPERSISTENCE_TEMP) - pgBufferUsage.local_blks_read += io_buffers_len; + INSTR_BUFUSAGE_ADD(local_blks_read, io_buffers_len); else - pgBufferUsage.shared_blks_read += io_buffers_len; + INSTR_BUFUSAGE_ADD(shared_blks_read, io_buffers_len); /* * Track vacuum cost when issuing IO, not after waiting for it. Otherwise @@ -3068,7 +3068,7 @@ ExtendBufferedRelShared(BufferManagerRelation bmr, TerminateBufferIO(buf_hdr, false, BM_VALID, true, false); } - pgBufferUsage.shared_blks_written += extend_by; + INSTR_BUFUSAGE_ADD(shared_blks_written, extend_by); *extended_by = extend_by; @@ -3214,7 +3214,7 @@ MarkBufferDirty(Buffer buffer) */ if (!(old_buf_state & BM_DIRTY)) { - pgBufferUsage.shared_blks_dirtied++; + INSTR_BUFUSAGE_INCR(shared_blks_dirtied); if (VacuumCostActive) VacuumCostBalance += VacuumCostPageDirty; } @@ -4630,7 +4630,7 @@ FlushBuffer(BufferDesc *buf, SMgrRelation reln, IOObject io_object, pgstat_count_io_op_time(io_object, io_context, IOOP_WRITE, io_start, 1, BLCKSZ); - pgBufferUsage.shared_blks_written++; + INSTR_BUFUSAGE_INCR(shared_blks_written); /* * Mark the buffer as clean and end the BM_IO_IN_PROGRESS state. @@ -5825,7 +5825,7 @@ MarkSharedBufferDirtyHint(Buffer buffer, BufferDesc *bufHdr, uint64 lockstate, UnlockBufHdr(bufHdr); } - pgBufferUsage.shared_blks_dirtied++; + INSTR_BUFUSAGE_INCR(shared_blks_dirtied); if (VacuumCostActive) VacuumCostBalance += VacuumCostPageDirty; } diff --git a/src/backend/storage/buffer/localbuf.c b/src/backend/storage/buffer/localbuf.c index dd5351552d1d4..261cbee7c1c15 100644 --- a/src/backend/storage/buffer/localbuf.c +++ b/src/backend/storage/buffer/localbuf.c @@ -218,7 +218,7 @@ FlushLocalBuffer(BufferDesc *bufHdr, SMgrRelation reln) /* Mark not-dirty */ TerminateLocalBufferIO(bufHdr, true, 0, false); - pgBufferUsage.local_blks_written++; + INSTR_BUFUSAGE_INCR(local_blks_written); } static Buffer @@ -487,7 +487,7 @@ ExtendBufferedRelLocal(BufferManagerRelation bmr, *extended_by = extend_by; - pgBufferUsage.local_blks_written += extend_by; + INSTR_BUFUSAGE_ADD(local_blks_written, extend_by); return first_block; } @@ -518,7 +518,7 @@ MarkLocalBufferDirty(Buffer buffer) buf_state = pg_atomic_read_u64(&bufHdr->state); if (!(buf_state & BM_DIRTY)) - pgBufferUsage.local_blks_dirtied++; + INSTR_BUFUSAGE_INCR(local_blks_dirtied); buf_state |= BM_DIRTY; diff --git a/src/backend/storage/file/buffile.c b/src/backend/storage/file/buffile.c index 9d4ea177ddb2e..5957c29c82c6c 100644 --- a/src/backend/storage/file/buffile.c +++ b/src/backend/storage/file/buffile.c @@ -477,13 +477,13 @@ BufFileLoadBuffer(BufFile *file) if (track_io_timing) { INSTR_TIME_SET_CURRENT(io_time); - INSTR_TIME_ACCUM_DIFF(pgBufferUsage.temp_blk_read_time, io_time, io_start); + INSTR_BUFUSAGE_TIME_ACCUM_DIFF(temp_blk_read_time, io_time, io_start); } /* we choose not to advance curOffset here */ if (file->nbytes > 0) - pgBufferUsage.temp_blks_read++; + INSTR_BUFUSAGE_INCR(temp_blks_read); } /* @@ -552,13 +552,13 @@ BufFileDumpBuffer(BufFile *file) if (track_io_timing) { INSTR_TIME_SET_CURRENT(io_time); - INSTR_TIME_ACCUM_DIFF(pgBufferUsage.temp_blk_write_time, io_time, io_start); + INSTR_BUFUSAGE_TIME_ACCUM_DIFF(temp_blk_write_time, io_time, io_start); } file->curOffset += rc; wpos += rc; - pgBufferUsage.temp_blks_written++; + INSTR_BUFUSAGE_INCR(temp_blks_written); } file->dirty = false; diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c index 3c8fcb20abac6..b6b1e7b0b061c 100644 --- a/src/backend/utils/activity/pgstat_io.c +++ b/src/backend/utils/activity/pgstat_io.c @@ -127,17 +127,17 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, { pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time)); if (io_object == IOOBJECT_RELATION) - INSTR_TIME_ADD(pgBufferUsage.shared_blk_write_time, io_time); + INSTR_BUFUSAGE_TIME_ADD(shared_blk_write_time, io_time); else if (io_object == IOOBJECT_TEMP_RELATION) - INSTR_TIME_ADD(pgBufferUsage.local_blk_write_time, io_time); + INSTR_BUFUSAGE_TIME_ADD(local_blk_write_time, io_time); } else if (io_op == IOOP_READ) { pgstat_count_buffer_read_time(INSTR_TIME_GET_MICROSEC(io_time)); if (io_object == IOOBJECT_RELATION) - INSTR_TIME_ADD(pgBufferUsage.shared_blk_read_time, io_time); + INSTR_BUFUSAGE_TIME_ADD(shared_blk_read_time, io_time); else if (io_object == IOOBJECT_TEMP_RELATION) - INSTR_TIME_ADD(pgBufferUsage.local_blk_read_time, io_time); + INSTR_BUFUSAGE_TIME_ADD(local_blk_read_time, io_time); } } diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index f093a52aae013..18c9542a3d453 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -155,4 +155,23 @@ extern void BufferUsageAccumDiff(BufferUsage *dst, extern void WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub); +#define INSTR_BUFUSAGE_INCR(fld) do { \ + pgBufferUsage.fld++; \ + } while(0) +#define INSTR_BUFUSAGE_ADD(fld,val) do { \ + pgBufferUsage.fld += (val); \ + } while(0) +#define INSTR_BUFUSAGE_TIME_ADD(fld,val) do { \ + INSTR_TIME_ADD(pgBufferUsage.fld, val); \ + } while (0) +#define INSTR_BUFUSAGE_TIME_ACCUM_DIFF(fld,endval,startval) do { \ + INSTR_TIME_ACCUM_DIFF(pgBufferUsage.fld, endval, startval); \ + } while (0) +#define INSTR_WALUSAGE_INCR(fld) do { \ + pgWalUsage.fld++; \ + } while(0) +#define INSTR_WALUSAGE_ADD(fld,val) do { \ + pgWalUsage.fld += (val); \ + } while(0) + #endif /* INSTRUMENT_H */ From 06559b7bab4a7ec9e38b5b4aaf804aa235ca77e1 Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Sun, 5 Apr 2026 03:48:32 -0700 Subject: [PATCH 3/9] instrumentation: Add additional regression tests covering buffer usage This adds regression tests that cover some of the expected behaviour around the buffer statistics reported in EXPLAIN ANALYZE, specifically how they behave in parallel query, nested function calls and abort situations. Testing this is challenging because there can be different sources of buffer activity, so we rely on temporary tables where we can to prove that activity was captured and not lost. This supports a future commit that will rework some of the instrumentation logic that could cause areas covered by these tests to fail. Author: Lukas Fittl Reviewed-by: Discussion: https://postgr.es/m/CAP53PkzdBK8VJ1fS4AZ481LgMN8f9mJiC39ZRHqkFUSYq6KWmg%40mail.gmail.com --- .../pg_stat_statements/expected/utility.out | 70 +++++++ contrib/pg_stat_statements/expected/wal.out | 48 +++++ contrib/pg_stat_statements/sql/utility.sql | 56 ++++++ contrib/pg_stat_statements/sql/wal.sql | 33 +++ src/test/regress/expected/explain.out | 188 ++++++++++++++++++ src/test/regress/sql/explain.sql | 188 ++++++++++++++++++ 6 files changed, 583 insertions(+) diff --git a/contrib/pg_stat_statements/expected/utility.out b/contrib/pg_stat_statements/expected/utility.out index 0762adbe94a76..2ff238b3e904e 100644 --- a/contrib/pg_stat_statements/expected/utility.out +++ b/contrib/pg_stat_statements/expected/utility.out @@ -289,6 +289,76 @@ SELECT calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C"; 1 | 1 | SELECT pg_stat_statements_reset() IS NOT NULL AS t (3 rows) +-- Buffer stats should flow through EXPLAIN ANALYZE +CREATE TEMP TABLE flow_through_test (a int, b char(200)); +INSERT INTO flow_through_test SELECT i, repeat('x', 200) FROM generate_series(1, 5000) AS i; +CREATE FUNCTION run_explain_buffers_test() RETURNS void AS $$ +DECLARE +BEGIN + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM flow_through_test'; +END; +$$ LANGUAGE plpgsql; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; + t +--- + t +(1 row) + +SELECT run_explain_buffers_test(); + run_explain_buffers_test +-------------------------- + +(1 row) + +-- EXPLAIN entries should have non-zero buffer stats +SELECT query, local_blks_hit + local_blks_read > 0 as has_buffer_stats +FROM pg_stat_statements +WHERE query LIKE 'SELECT run_explain_buffers_test%' +ORDER BY query COLLATE "C"; + query | has_buffer_stats +-----------------------------------+------------------ + SELECT run_explain_buffers_test() | t +(1 row) + +DROP FUNCTION run_explain_buffers_test; +DROP TABLE flow_through_test; +-- Validate buffer/WAL counting during abort +SET pg_stat_statements.track = 'all'; +CREATE TEMP TABLE pgss_call_tab (a int, b char(20)); +CREATE TEMP TABLE pgss_call_tab2 (a int, b char(20)); +INSERT INTO pgss_call_tab VALUES (0, 'zzz'); +CREATE PROCEDURE pgss_call_rollback_proc() AS $$ +DECLARE + v int; +BEGIN + EXPLAIN ANALYZE WITH ins AS (INSERT INTO pgss_call_tab2 SELECT * FROM pgss_call_tab RETURNING a) + SELECT a / 0 INTO v FROM ins; +EXCEPTION WHEN division_by_zero THEN +END; +$$ LANGUAGE plpgsql; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; + t +--- + t +(1 row) + +CALL pgss_call_rollback_proc(); +SELECT query, calls, +local_blks_hit + local_blks_read > 0 as local_hitread, +wal_bytes > 0 as wal_bytes_generated, +wal_records > 0 as wal_records_generated +FROM pg_stat_statements +WHERE query LIKE '%pgss_call_rollback_proc%' +ORDER BY query COLLATE "C"; + query | calls | local_hitread | wal_bytes_generated | wal_records_generated +--------------------------------+-------+---------------+---------------------+----------------------- + CALL pgss_call_rollback_proc() | 1 | t | t | t +(1 row) + +DROP TABLE pgss_call_tab2; +DROP TABLE pgss_call_tab; +DROP PROCEDURE pgss_call_rollback_proc; +SET pg_stat_statements.track = 'top'; -- CALL CREATE OR REPLACE PROCEDURE sum_one(i int) AS $$ DECLARE diff --git a/contrib/pg_stat_statements/expected/wal.out b/contrib/pg_stat_statements/expected/wal.out index 977e382d84894..611213daef6c2 100644 --- a/contrib/pg_stat_statements/expected/wal.out +++ b/contrib/pg_stat_statements/expected/wal.out @@ -28,3 +28,51 @@ SELECT pg_stat_statements_reset() IS NOT NULL AS t; t (1 row) +-- +-- Validate buffer/WAL counting with caught exception in PL/pgSQL +-- +CREATE TEMP TABLE pgss_error_tab (a int, b char(20)); +INSERT INTO pgss_error_tab VALUES (0, 'zzz'); +CREATE FUNCTION pgss_error_func() RETURNS void AS $$ +DECLARE + v int; +BEGIN + WITH ins AS (INSERT INTO pgss_error_tab VALUES (1, 'aaa') RETURNING a) + SELECT a / 0 INTO v FROM ins; +EXCEPTION WHEN division_by_zero THEN + NULL; +END; +$$ LANGUAGE plpgsql; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; + t +--- + t +(1 row) + +SELECT pgss_error_func(); + pgss_error_func +----------------- + +(1 row) + +-- Buffer/WAL usage from the wCTE INSERT should survive the exception +SELECT query, calls, +local_blks_hit + local_blks_read > 0 as local_hitread, +wal_bytes > 0 as wal_bytes_generated, +wal_records > 0 as wal_records_generated +FROM pg_stat_statements +WHERE query LIKE '%pgss_error_func%' +ORDER BY query COLLATE "C"; + query | calls | local_hitread | wal_bytes_generated | wal_records_generated +--------------------------+-------+---------------+---------------------+----------------------- + SELECT pgss_error_func() | 1 | t | t | t +(1 row) + +DROP TABLE pgss_error_tab; +DROP FUNCTION pgss_error_func; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; + t +--- + t +(1 row) + diff --git a/contrib/pg_stat_statements/sql/utility.sql b/contrib/pg_stat_statements/sql/utility.sql index b159c1de1aafa..bbc922ad4e706 100644 --- a/contrib/pg_stat_statements/sql/utility.sql +++ b/contrib/pg_stat_statements/sql/utility.sql @@ -152,6 +152,62 @@ EXPLAIN (costs off) SELECT a FROM generate_series(1,10) AS tab(a) WHERE a = 7; SELECT calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C"; +-- Buffer stats should flow through EXPLAIN ANALYZE +CREATE TEMP TABLE flow_through_test (a int, b char(200)); +INSERT INTO flow_through_test SELECT i, repeat('x', 200) FROM generate_series(1, 5000) AS i; + +CREATE FUNCTION run_explain_buffers_test() RETURNS void AS $$ +DECLARE +BEGIN + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM flow_through_test'; +END; +$$ LANGUAGE plpgsql; + +SELECT pg_stat_statements_reset() IS NOT NULL AS t; + +SELECT run_explain_buffers_test(); + +-- EXPLAIN entries should have non-zero buffer stats +SELECT query, local_blks_hit + local_blks_read > 0 as has_buffer_stats +FROM pg_stat_statements +WHERE query LIKE 'SELECT run_explain_buffers_test%' +ORDER BY query COLLATE "C"; + +DROP FUNCTION run_explain_buffers_test; +DROP TABLE flow_through_test; + +-- Validate buffer/WAL counting during abort +SET pg_stat_statements.track = 'all'; +CREATE TEMP TABLE pgss_call_tab (a int, b char(20)); +CREATE TEMP TABLE pgss_call_tab2 (a int, b char(20)); +INSERT INTO pgss_call_tab VALUES (0, 'zzz'); + +CREATE PROCEDURE pgss_call_rollback_proc() AS $$ +DECLARE + v int; +BEGIN + EXPLAIN ANALYZE WITH ins AS (INSERT INTO pgss_call_tab2 SELECT * FROM pgss_call_tab RETURNING a) + SELECT a / 0 INTO v FROM ins; +EXCEPTION WHEN division_by_zero THEN +END; +$$ LANGUAGE plpgsql; + +SELECT pg_stat_statements_reset() IS NOT NULL AS t; +CALL pgss_call_rollback_proc(); + +SELECT query, calls, +local_blks_hit + local_blks_read > 0 as local_hitread, +wal_bytes > 0 as wal_bytes_generated, +wal_records > 0 as wal_records_generated +FROM pg_stat_statements +WHERE query LIKE '%pgss_call_rollback_proc%' +ORDER BY query COLLATE "C"; + +DROP TABLE pgss_call_tab2; +DROP TABLE pgss_call_tab; +DROP PROCEDURE pgss_call_rollback_proc; +SET pg_stat_statements.track = 'top'; + -- CALL CREATE OR REPLACE PROCEDURE sum_one(i int) AS $$ DECLARE diff --git a/contrib/pg_stat_statements/sql/wal.sql b/contrib/pg_stat_statements/sql/wal.sql index 1dc1552a81ebc..467e321b2062e 100644 --- a/contrib/pg_stat_statements/sql/wal.sql +++ b/contrib/pg_stat_statements/sql/wal.sql @@ -18,3 +18,36 @@ wal_records > 0 as wal_records_generated, wal_records >= rows as wal_records_ge_rows FROM pg_stat_statements ORDER BY query COLLATE "C"; SELECT pg_stat_statements_reset() IS NOT NULL AS t; + +-- +-- Validate buffer/WAL counting with caught exception in PL/pgSQL +-- +CREATE TEMP TABLE pgss_error_tab (a int, b char(20)); +INSERT INTO pgss_error_tab VALUES (0, 'zzz'); + +CREATE FUNCTION pgss_error_func() RETURNS void AS $$ +DECLARE + v int; +BEGIN + WITH ins AS (INSERT INTO pgss_error_tab VALUES (1, 'aaa') RETURNING a) + SELECT a / 0 INTO v FROM ins; +EXCEPTION WHEN division_by_zero THEN + NULL; +END; +$$ LANGUAGE plpgsql; + +SELECT pg_stat_statements_reset() IS NOT NULL AS t; +SELECT pgss_error_func(); + +-- Buffer/WAL usage from the wCTE INSERT should survive the exception +SELECT query, calls, +local_blks_hit + local_blks_read > 0 as local_hitread, +wal_bytes > 0 as wal_bytes_generated, +wal_records > 0 as wal_records_generated +FROM pg_stat_statements +WHERE query LIKE '%pgss_error_func%' +ORDER BY query COLLATE "C"; + +DROP TABLE pgss_error_tab; +DROP FUNCTION pgss_error_func; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out index 74a4d87801e69..f464baea4c8e5 100644 --- a/src/test/regress/expected/explain.out +++ b/src/test/regress/expected/explain.out @@ -832,3 +832,191 @@ select explain_filter('explain (analyze,buffers off,costs off) select sum(n) ove (9 rows) reset work_mem; +-- EXPLAIN (ANALYZE, BUFFERS) should report buffer usage from PL/pgSQL +-- EXCEPTION blocks, even after subtransaction rollback. +CREATE TEMP TABLE explain_exc_tab (a int, b char(20)); +INSERT INTO explain_exc_tab VALUES (0, 'zzz'); +CREATE FUNCTION explain_exc_func() RETURNS void AS $$ +DECLARE + v int; +BEGIN + WITH ins AS (INSERT INTO explain_exc_tab VALUES (1, 'aaa') RETURNING a) + SELECT a / 0 INTO v FROM ins; +EXCEPTION WHEN division_by_zero THEN + NULL; +END; +$$ LANGUAGE plpgsql; +CREATE FUNCTION check_explain_exception_buffers() RETURNS boolean AS $$ +DECLARE + plan_json json; + node json; + total_buffers int; +BEGIN + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT explain_exc_func()' INTO plan_json; + node := plan_json->0->'Plan'; + total_buffers := + COALESCE((node->>'Local Hit Blocks')::int, 0) + + COALESCE((node->>'Local Read Blocks')::int, 0); + RETURN total_buffers > 0; +END; +$$ LANGUAGE plpgsql; +SELECT check_explain_exception_buffers() AS exception_buffers_visible; + exception_buffers_visible +--------------------------- + t +(1 row) + +-- Also test with nested EXPLAIN ANALYZE (two levels of instrumentation) +CREATE FUNCTION check_explain_exception_buffers_nested() RETURNS boolean AS $$ +DECLARE + plan_json json; + node json; + total_buffers int; +BEGIN + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT check_explain_exception_buffers()' INTO plan_json; + node := plan_json->0->'Plan'; + total_buffers := + COALESCE((node->>'Local Hit Blocks')::int, 0) + + COALESCE((node->>'Local Read Blocks')::int, 0); + RETURN total_buffers > 0; +END; +$$ LANGUAGE plpgsql; +SELECT check_explain_exception_buffers_nested() AS exception_buffers_nested_visible; + exception_buffers_nested_visible +---------------------------------- + t +(1 row) + +DROP FUNCTION check_explain_exception_buffers_nested; +DROP FUNCTION check_explain_exception_buffers; +DROP FUNCTION explain_exc_func; +DROP TABLE explain_exc_tab; +-- Cursor instrumentation test. +-- Verify that buffer usage is correctly tracked through cursor execution paths. +-- Non-scrollable cursors exercise ExecShutdownNode after each ExecutorRun +-- (EXEC_FLAG_BACKWARD is not set), while scrollable cursors only shut down +-- nodes in ExecutorFinish. In both cases, buffer usage from the inner cursor +-- scan should be correctly reported. +CREATE TEMP TABLE cursor_buf_test AS SELECT * FROM tenk1; +CREATE FUNCTION cursor_noscroll_scan() RETURNS bigint AS $$ +DECLARE + cur NO SCROLL CURSOR FOR SELECT * FROM cursor_buf_test; + rec RECORD; + cnt bigint := 0; +BEGIN + OPEN cur; + LOOP + FETCH NEXT FROM cur INTO rec; + EXIT WHEN NOT FOUND; + cnt := cnt + 1; + END LOOP; + CLOSE cur; + RETURN cnt; +END; +$$ LANGUAGE plpgsql; +CREATE FUNCTION cursor_scroll_scan() RETURNS bigint AS $$ +DECLARE + cur SCROLL CURSOR FOR SELECT * FROM cursor_buf_test; + rec RECORD; + cnt bigint := 0; +BEGIN + OPEN cur; + LOOP + FETCH NEXT FROM cur INTO rec; + EXIT WHEN NOT FOUND; + cnt := cnt + 1; + END LOOP; + CLOSE cur; + RETURN cnt; +END; +$$ LANGUAGE plpgsql; +CREATE FUNCTION check_cursor_explain_buffers() RETURNS TABLE(noscroll_ok boolean, scroll_ok boolean) AS $$ +DECLARE + plan_json json; + node json; + direct_buf int; + noscroll_buf int; + scroll_buf int; +BEGIN + -- Direct scan: get leaf Seq Scan node buffers as baseline + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT * FROM cursor_buf_test' INTO plan_json; + node := plan_json->0->'Plan'; + WHILE node->'Plans' IS NOT NULL LOOP + node := node->'Plans'->0; + END LOOP; + direct_buf := + COALESCE((node->>'Local Hit Blocks')::int, 0) + + COALESCE((node->>'Local Read Blocks')::int, 0); + + -- Non-scrollable cursor path: ExecShutdownNode runs after each ExecutorRun + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT cursor_noscroll_scan()' INTO plan_json; + node := plan_json->0->'Plan'; + noscroll_buf := + COALESCE((node->>'Local Hit Blocks')::int, 0) + + COALESCE((node->>'Local Read Blocks')::int, 0); + + -- Scrollable cursor path: ExecShutdownNode is skipped + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT cursor_scroll_scan()' INTO plan_json; + node := plan_json->0->'Plan'; + scroll_buf := + COALESCE((node->>'Local Hit Blocks')::int, 0) + + COALESCE((node->>'Local Read Blocks')::int, 0); + + -- Both cursor paths should report buffer counts about as high as + -- the direct scan (same data plus minor catalog overhead), and not + -- double-counted (< 2x the direct scan) + RETURN QUERY SELECT + (noscroll_buf >= direct_buf * 0.5 AND noscroll_buf < direct_buf * 2), + (scroll_buf >= direct_buf * 0.5 AND scroll_buf < direct_buf * 2); +END; +$$ LANGUAGE plpgsql; +SELECT * FROM check_cursor_explain_buffers(); + noscroll_ok | scroll_ok +-------------+----------- + t | t +(1 row) + +DROP FUNCTION check_cursor_explain_buffers; +DROP FUNCTION cursor_noscroll_scan; +DROP FUNCTION cursor_scroll_scan; +DROP TABLE cursor_buf_test; +-- Test trigger instrumentation. +CREATE TEMP TABLE trig_test_tab (a int); +CREATE TEMP TABLE trig_work_tab (a int); +INSERT INTO trig_work_tab VALUES (1); +CREATE FUNCTION trig_test_func() RETURNS trigger AS $$ +BEGIN + PERFORM * FROM trig_work_tab; + RETURN NEW; +END; +$$ LANGUAGE plpgsql; +CREATE TRIGGER trig_test_trig + BEFORE INSERT ON trig_test_tab + FOR EACH ROW EXECUTE FUNCTION trig_test_func(); +CREATE FUNCTION check_trigger_explain_buffers() RETURNS boolean AS $$ +DECLARE + plan_json json; + trig json; +BEGIN + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + INSERT INTO trig_test_tab VALUES (1)' INTO plan_json; + trig := plan_json->0->'Triggers'->0; + RETURN COALESCE((trig->>'Calls')::int, 0) > 0; +END; +$$ LANGUAGE plpgsql; +SELECT check_trigger_explain_buffers() AS trigger_buffers_visible; + trigger_buffers_visible +------------------------- + t +(1 row) + +DROP FUNCTION check_trigger_explain_buffers; +DROP TRIGGER trig_test_trig ON trig_test_tab; +DROP FUNCTION trig_test_func; +DROP TABLE trig_test_tab; +DROP TABLE trig_work_tab; diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql index 2f163c64bf6d3..101914b6d5b47 100644 --- a/src/test/regress/sql/explain.sql +++ b/src/test/regress/sql/explain.sql @@ -191,3 +191,191 @@ select explain_filter('explain (analyze,buffers off,costs off) select sum(n) ove -- Test tuplestore storage usage in Window aggregate (memory and disk case, final result is disk) select explain_filter('explain (analyze,buffers off,costs off) select sum(n) over(partition by m) from (SELECT n < 3 as m, n from generate_series(1,2500) a(n))'); reset work_mem; + +-- EXPLAIN (ANALYZE, BUFFERS) should report buffer usage from PL/pgSQL +-- EXCEPTION blocks, even after subtransaction rollback. +CREATE TEMP TABLE explain_exc_tab (a int, b char(20)); +INSERT INTO explain_exc_tab VALUES (0, 'zzz'); + +CREATE FUNCTION explain_exc_func() RETURNS void AS $$ +DECLARE + v int; +BEGIN + WITH ins AS (INSERT INTO explain_exc_tab VALUES (1, 'aaa') RETURNING a) + SELECT a / 0 INTO v FROM ins; +EXCEPTION WHEN division_by_zero THEN + NULL; +END; +$$ LANGUAGE plpgsql; + +CREATE FUNCTION check_explain_exception_buffers() RETURNS boolean AS $$ +DECLARE + plan_json json; + node json; + total_buffers int; +BEGIN + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT explain_exc_func()' INTO plan_json; + node := plan_json->0->'Plan'; + total_buffers := + COALESCE((node->>'Local Hit Blocks')::int, 0) + + COALESCE((node->>'Local Read Blocks')::int, 0); + RETURN total_buffers > 0; +END; +$$ LANGUAGE plpgsql; + +SELECT check_explain_exception_buffers() AS exception_buffers_visible; + +-- Also test with nested EXPLAIN ANALYZE (two levels of instrumentation) +CREATE FUNCTION check_explain_exception_buffers_nested() RETURNS boolean AS $$ +DECLARE + plan_json json; + node json; + total_buffers int; +BEGIN + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT check_explain_exception_buffers()' INTO plan_json; + node := plan_json->0->'Plan'; + total_buffers := + COALESCE((node->>'Local Hit Blocks')::int, 0) + + COALESCE((node->>'Local Read Blocks')::int, 0); + RETURN total_buffers > 0; +END; +$$ LANGUAGE plpgsql; + +SELECT check_explain_exception_buffers_nested() AS exception_buffers_nested_visible; + +DROP FUNCTION check_explain_exception_buffers_nested; +DROP FUNCTION check_explain_exception_buffers; +DROP FUNCTION explain_exc_func; +DROP TABLE explain_exc_tab; + +-- Cursor instrumentation test. +-- Verify that buffer usage is correctly tracked through cursor execution paths. +-- Non-scrollable cursors exercise ExecShutdownNode after each ExecutorRun +-- (EXEC_FLAG_BACKWARD is not set), while scrollable cursors only shut down +-- nodes in ExecutorFinish. In both cases, buffer usage from the inner cursor +-- scan should be correctly reported. + +CREATE TEMP TABLE cursor_buf_test AS SELECT * FROM tenk1; + +CREATE FUNCTION cursor_noscroll_scan() RETURNS bigint AS $$ +DECLARE + cur NO SCROLL CURSOR FOR SELECT * FROM cursor_buf_test; + rec RECORD; + cnt bigint := 0; +BEGIN + OPEN cur; + LOOP + FETCH NEXT FROM cur INTO rec; + EXIT WHEN NOT FOUND; + cnt := cnt + 1; + END LOOP; + CLOSE cur; + RETURN cnt; +END; +$$ LANGUAGE plpgsql; + +CREATE FUNCTION cursor_scroll_scan() RETURNS bigint AS $$ +DECLARE + cur SCROLL CURSOR FOR SELECT * FROM cursor_buf_test; + rec RECORD; + cnt bigint := 0; +BEGIN + OPEN cur; + LOOP + FETCH NEXT FROM cur INTO rec; + EXIT WHEN NOT FOUND; + cnt := cnt + 1; + END LOOP; + CLOSE cur; + RETURN cnt; +END; +$$ LANGUAGE plpgsql; + +CREATE FUNCTION check_cursor_explain_buffers() RETURNS TABLE(noscroll_ok boolean, scroll_ok boolean) AS $$ +DECLARE + plan_json json; + node json; + direct_buf int; + noscroll_buf int; + scroll_buf int; +BEGIN + -- Direct scan: get leaf Seq Scan node buffers as baseline + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT * FROM cursor_buf_test' INTO plan_json; + node := plan_json->0->'Plan'; + WHILE node->'Plans' IS NOT NULL LOOP + node := node->'Plans'->0; + END LOOP; + direct_buf := + COALESCE((node->>'Local Hit Blocks')::int, 0) + + COALESCE((node->>'Local Read Blocks')::int, 0); + + -- Non-scrollable cursor path: ExecShutdownNode runs after each ExecutorRun + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT cursor_noscroll_scan()' INTO plan_json; + node := plan_json->0->'Plan'; + noscroll_buf := + COALESCE((node->>'Local Hit Blocks')::int, 0) + + COALESCE((node->>'Local Read Blocks')::int, 0); + + -- Scrollable cursor path: ExecShutdownNode is skipped + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT cursor_scroll_scan()' INTO plan_json; + node := plan_json->0->'Plan'; + scroll_buf := + COALESCE((node->>'Local Hit Blocks')::int, 0) + + COALESCE((node->>'Local Read Blocks')::int, 0); + + -- Both cursor paths should report buffer counts about as high as + -- the direct scan (same data plus minor catalog overhead), and not + -- double-counted (< 2x the direct scan) + RETURN QUERY SELECT + (noscroll_buf >= direct_buf * 0.5 AND noscroll_buf < direct_buf * 2), + (scroll_buf >= direct_buf * 0.5 AND scroll_buf < direct_buf * 2); +END; +$$ LANGUAGE plpgsql; + +SELECT * FROM check_cursor_explain_buffers(); + +DROP FUNCTION check_cursor_explain_buffers; +DROP FUNCTION cursor_noscroll_scan; +DROP FUNCTION cursor_scroll_scan; +DROP TABLE cursor_buf_test; + +-- Test trigger instrumentation. +CREATE TEMP TABLE trig_test_tab (a int); +CREATE TEMP TABLE trig_work_tab (a int); +INSERT INTO trig_work_tab VALUES (1); + +CREATE FUNCTION trig_test_func() RETURNS trigger AS $$ +BEGIN + PERFORM * FROM trig_work_tab; + RETURN NEW; +END; +$$ LANGUAGE plpgsql; + +CREATE TRIGGER trig_test_trig + BEFORE INSERT ON trig_test_tab + FOR EACH ROW EXECUTE FUNCTION trig_test_func(); + +CREATE FUNCTION check_trigger_explain_buffers() RETURNS boolean AS $$ +DECLARE + plan_json json; + trig json; +BEGIN + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + INSERT INTO trig_test_tab VALUES (1)' INTO plan_json; + trig := plan_json->0->'Triggers'->0; + RETURN COALESCE((trig->>'Calls')::int, 0) > 0; +END; +$$ LANGUAGE plpgsql; + +SELECT check_trigger_explain_buffers() AS trigger_buffers_visible; + +DROP FUNCTION check_trigger_explain_buffers; +DROP TRIGGER trig_test_trig ON trig_test_tab; +DROP FUNCTION trig_test_func; +DROP TABLE trig_test_tab; +DROP TABLE trig_work_tab; From 339f3b1e0954401d8750d20193fb570ee170def8 Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Mon, 6 Apr 2026 01:20:45 -0700 Subject: [PATCH 4/9] instrumentation: Reduce overhead of measuring per-node buffer/WAL usage Previously, in order to determine the buffer/WAL usage of a given code section, we utilized continuously incrementing global counters that get updated when the actual activity (e.g. shared block read) occurred, and then calculated a diff when the code section ended. This resulted in a bottleneck for executor node instrumentation specifically, with profiles showing BufferUsageAccumDiff in EXPLAIN (ANALYZE, BUFFERS) runs. Instead, introduce a stack-based mechanism, where the actual activity writes into the current stack entry. In the case of executor nodes, this means that each node gets its own stack entry that is pushed at InstrStartNode, and popped at InstrStopNode. Stack entries are zero initialized (avoiding the diff mechanism) and get added to their parent entry when they are finalized, i.e. no more modifications can occur. To correctly handle abort situations, any use of instrumentation stacks must involve either a top-level QueryInstrumentation struct, and its associated InstrQueryStart/InstrQueryStop helpers (which use resource owners to handle aborts), or the Instrumentation struct itself with dedicated PG_TRY/PG_FINALLY calls that ensure the stack is in a consistent state after an abort. In tests, the stack-based instrumentation mechanism reduces the overhead of EXPLAIN (ANALYZE, BUFFERS ON, TIMING OFF) for a large COUNT(*) query from about 35% to about 20% on top of the actual runtime. Callers of the plain Instrumentation API (InstrAlloc/InstrInitOptions with InstrStart/InstrStop) keep measuring by diffing the global pgBufferUsage/pgWalUsage counters for now. The diff-mode handling lives only in InstrStart/InstrStop themselves: node instrumentation never measures by diffing, so InstrStartNode/InstrStopNode go through common helpers that handle just the timer and the stack, keeping the diff-mode branches out of the per-tuple ExecProcNodeInstr path (which would otherwise regress EXPLAIN (ANALYZE, TIMING OFF, BUFFERS OFF) slightly relative to master). Author: Lukas Fittl Reviewed-by: Zsolt Parragi (in an earlier version) Reviewed-by: Heikki Linnakangas (in an earlier version) Discussion: https://postgr.es/m/CAP53PkxrmpECzVFpeeEEHDGe6u625s%2BYkmVv5-gw3L_NDSfbiA%40mail.gmail.com#cb583a08e8e096aa1f093bb178906173 --- src/backend/access/brin/brin.c | 6 +- src/backend/access/gin/gininsert.c | 6 +- src/backend/access/nbtree/nbtsort.c | 6 +- src/backend/commands/repack.c | 2 +- src/backend/commands/tablecmds.c | 5 +- src/backend/commands/vacuumparallel.c | 6 +- src/backend/executor/README.instrument | 253 ++++++++++++ src/backend/executor/execMain.c | 116 +++++- src/backend/executor/execParallel.c | 27 +- src/backend/executor/execPartition.c | 5 +- src/backend/executor/execProcnode.c | 106 ++++- src/backend/executor/execUtils.c | 9 +- src/backend/executor/instrument.c | 491 ++++++++++++++++++++--- src/backend/replication/logical/worker.c | 2 +- src/include/executor/executor.h | 6 +- src/include/executor/instrument.h | 198 ++++++++- src/include/nodes/execnodes.h | 2 + src/include/utils/resowner.h | 1 + src/tools/pgindent/typedefs.list | 2 + 19 files changed, 1144 insertions(+), 105 deletions(-) create mode 100644 src/backend/executor/README.instrument diff --git a/src/backend/access/brin/brin.c b/src/backend/access/brin/brin.c index 5059da8dce7c5..8c2c69605ce0e 100644 --- a/src/backend/access/brin/brin.c +++ b/src/backend/access/brin/brin.c @@ -2887,6 +2887,7 @@ _brin_parallel_build_main(dsm_segment *seg, shm_toc *toc) Relation indexRel; LOCKMODE heapLockmode; LOCKMODE indexLockmode; + QueryInstrumentation *instr; WalUsage *walusage; BufferUsage *bufferusage; int sortmem; @@ -2936,7 +2937,7 @@ _brin_parallel_build_main(dsm_segment *seg, shm_toc *toc) tuplesort_attach_shared(sharedsort, seg); /* Prepare to track buffer usage during parallel execution */ - InstrStartParallelQuery(); + instr = InstrStartParallelQuery(); /* * Might as well use reliable figure when doling out maintenance_work_mem @@ -2951,7 +2952,8 @@ _brin_parallel_build_main(dsm_segment *seg, shm_toc *toc) /* Report WAL/buffer usage during parallel execution */ bufferusage = shm_toc_lookup(toc, PARALLEL_KEY_BUFFER_USAGE, false); walusage = shm_toc_lookup(toc, PARALLEL_KEY_WAL_USAGE, false); - InstrEndParallelQuery(&bufferusage[ParallelWorkerNumber], + InstrEndParallelQuery(instr, + &bufferusage[ParallelWorkerNumber], &walusage[ParallelWorkerNumber]); index_close(indexRel, indexLockmode); diff --git a/src/backend/access/gin/gininsert.c b/src/backend/access/gin/gininsert.c index 564b1509f1bf2..b3b90ee6685d4 100644 --- a/src/backend/access/gin/gininsert.c +++ b/src/backend/access/gin/gininsert.c @@ -2112,6 +2112,7 @@ _gin_parallel_build_main(dsm_segment *seg, shm_toc *toc) Relation indexRel; LOCKMODE heapLockmode; LOCKMODE indexLockmode; + QueryInstrumentation *instr; WalUsage *walusage; BufferUsage *bufferusage; int sortmem; @@ -2185,7 +2186,7 @@ _gin_parallel_build_main(dsm_segment *seg, shm_toc *toc) tuplesort_attach_shared(sharedsort, seg); /* Prepare to track buffer usage during parallel execution */ - InstrStartParallelQuery(); + instr = InstrStartParallelQuery(); /* * Might as well use reliable figure when doling out maintenance_work_mem @@ -2200,7 +2201,8 @@ _gin_parallel_build_main(dsm_segment *seg, shm_toc *toc) /* Report WAL/buffer usage during parallel execution */ bufferusage = shm_toc_lookup(toc, PARALLEL_KEY_BUFFER_USAGE, false); walusage = shm_toc_lookup(toc, PARALLEL_KEY_WAL_USAGE, false); - InstrEndParallelQuery(&bufferusage[ParallelWorkerNumber], + InstrEndParallelQuery(instr, + &bufferusage[ParallelWorkerNumber], &walusage[ParallelWorkerNumber]); index_close(indexRel, indexLockmode); diff --git a/src/backend/access/nbtree/nbtsort.c b/src/backend/access/nbtree/nbtsort.c index 756dfa3dcf47e..3d88c2556bb80 100644 --- a/src/backend/access/nbtree/nbtsort.c +++ b/src/backend/access/nbtree/nbtsort.c @@ -1753,6 +1753,7 @@ _bt_parallel_build_main(dsm_segment *seg, shm_toc *toc) Relation indexRel; LOCKMODE heapLockmode; LOCKMODE indexLockmode; + QueryInstrumentation *instr; WalUsage *walusage; BufferUsage *bufferusage; int sortmem; @@ -1828,7 +1829,7 @@ _bt_parallel_build_main(dsm_segment *seg, shm_toc *toc) } /* Prepare to track buffer usage during parallel execution */ - InstrStartParallelQuery(); + instr = InstrStartParallelQuery(); /* Perform sorting of spool, and possibly a spool2 */ sortmem = maintenance_work_mem / btshared->scantuplesortstates; @@ -1838,7 +1839,8 @@ _bt_parallel_build_main(dsm_segment *seg, shm_toc *toc) /* Report WAL/buffer usage during parallel execution */ bufferusage = shm_toc_lookup(toc, PARALLEL_KEY_BUFFER_USAGE, false); walusage = shm_toc_lookup(toc, PARALLEL_KEY_WAL_USAGE, false); - InstrEndParallelQuery(&bufferusage[ParallelWorkerNumber], + InstrEndParallelQuery(instr, + &bufferusage[ParallelWorkerNumber], &walusage[ParallelWorkerNumber]); #ifdef BTREE_BUILD_STATS diff --git a/src/backend/commands/repack.c b/src/backend/commands/repack.c index 1b1a82133583a..7def25655828f 100644 --- a/src/backend/commands/repack.c +++ b/src/backend/commands/repack.c @@ -3323,7 +3323,7 @@ initialize_change_context(ChangeContext *chgcxt, /* Set up our ResultRelInfo to use for index updates */ chgcxt->cc_rri = makeNode(ResultRelInfo); - InitResultRelInfo(chgcxt->cc_rri, tgt_relation, 1, NULL, 0); + InitResultRelInfo(chgcxt->cc_rri, tgt_relation, 1, NULL, 0, NULL); ExecOpenIndices(chgcxt->cc_rri, false); /* diff --git a/src/backend/commands/tablecmds.c b/src/backend/commands/tablecmds.c index 97e16f3eb47c9..0561bce27f840 100644 --- a/src/backend/commands/tablecmds.c +++ b/src/backend/commands/tablecmds.c @@ -2139,7 +2139,7 @@ ExecuteTruncateGuts(List *explicit_rels, rel, 0, /* dummy rangetable index */ NULL, - 0); + 0, NULL); estate->es_opened_result_relations = lappend(estate->es_opened_result_relations, resultRelInfo); resultRelInfo++; @@ -6350,7 +6350,8 @@ ATRewriteTable(AlteredTableInfo *tab, Oid OIDNewHeap) oldrel, 0, /* dummy rangetable index */ NULL, - estate->es_instrument); + estate->es_instrument, + estate->es_query_instr); MemoryContextSwitchTo(oldcontext); } diff --git a/src/backend/commands/vacuumparallel.c b/src/backend/commands/vacuumparallel.c index c29f62c5a9910..3f64934db8640 100644 --- a/src/backend/commands/vacuumparallel.c +++ b/src/backend/commands/vacuumparallel.c @@ -1268,6 +1268,7 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc) PVIndStats *indstats; PVShared *shared; TidStore *dead_items; + QueryInstrumentation *instr; BufferUsage *buffer_usage; WalUsage *wal_usage; int nindexes; @@ -1382,7 +1383,7 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc) error_context_stack = &errcallback; /* Prepare to track buffer usage during parallel execution */ - InstrStartParallelQuery(); + instr = InstrStartParallelQuery(); /* Register this worker for vacuum progress reporting */ pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, shared->relid); @@ -1393,7 +1394,8 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc) /* Report buffer/WAL usage during parallel execution */ buffer_usage = shm_toc_lookup(toc, PARALLEL_VACUUM_KEY_BUFFER_USAGE, false); wal_usage = shm_toc_lookup(toc, PARALLEL_VACUUM_KEY_WAL_USAGE, false); - InstrEndParallelQuery(&buffer_usage[ParallelWorkerNumber], + InstrEndParallelQuery(instr, + &buffer_usage[ParallelWorkerNumber], &wal_usage[ParallelWorkerNumber]); /* Report any remaining cost-based vacuum delay time */ diff --git a/src/backend/executor/README.instrument b/src/backend/executor/README.instrument new file mode 100644 index 0000000000000..51b0f72c29cd3 --- /dev/null +++ b/src/backend/executor/README.instrument @@ -0,0 +1,253 @@ +src/backend/executor/README.instrument + +Instrumentation +=============== + +The instrumentation subsystem measures time, buffer usage and WAL activity +during query execution and other similar activities. It is used by +EXPLAIN ANALYZE, pg_stat_statements, and other consumers that need +activity and/or timing metrics over a section of code. + +The design has two central goals: + +* Make it cheap to measure activity in a section of code, even when + that section is called many times and the aggregate is what is used + (as is the case with per-node instrumentation in the executor) + +* Ensure nested instrumentation accurately measures activity/timing, + even when execution is aborted due to errors being thrown. + +The key data structures are defined in src/include/executor/instrument.h +and the implementation lives in src/backend/executor/instrument.c. + + +Instrumentation Options +----------------------- + +Callers specify what to measure with a bitmask of InstrumentOption flags: + + INSTRUMENT_ROWS -- row counts only (used with NodeInstrumentation) + INSTRUMENT_TIMER -- wall-clock timing and row counts + INSTRUMENT_BUFFERS -- buffer hit/read/dirtied/written counts and I/O time + INSTRUMENT_WAL -- WAL records, FPI, bytes + +INSTRUMENT_BUFFERS and INSTRUMENT_WAL utilize the instrumentation stack +(described below) for efficient handling of counter values. + + +Struct Hierarchy +---------------- + +There are the following instrumentation structs, each specialized for a +different scope: + +Instrumentation Base struct. Holds timing and buffer/WAL counters. + +QueryInstrumentation Extends Instrumentation for query-level tracking. When + stack-based tracking is enabled, it owns a dedicated + MemoryContext and uses the ResourceOwner mechanism for + abort cleanup. + +NodeInstrumentation Extends Instrumentation for per-plan-node statistics + (startup time, tuple counts, loop counts, etc). + +TriggerInstrumentation Extends Instrumentation with a firing count. + + +Stack-based instrumentation +=========================== + +For tracking WAL or buffer usage counters, the specialized stack-based +instrumentation is used. + +A simple approach to measuring buffer/WAL activity in a code section could be +to have a set of global counters, snapshot all the counters at the start, and +diff them at the end. But, this is expensive in practice: BufferUsage alone +has many fields, and the diff must be computed for every InstrStartNode / +InstrStopNode cycle. + +An alternative is to write counter updates directly into the struct that +should receive them, avoiding the diff. But that has two complexities: Low-level +code such as the buffer manager, has no direct pointers to higher level +structs, such as plan nodes tracking buffer usage. And instrumentation is often +nested: We might both be interested in the aggregate buffer usage of a query, and +the individual per-node details. Stack-based instrumentation solves for that: + +At all times, there is a stack that tracks which Instrumentation is currently +active. The stack is represented by instr_stack, a per-backend global +that holds a dynamic array of Instrumentation pointers. The field +instr_stack.current always points to the current stack entry that should +be updated when activity occurs. When the stack array is empty, the +current stack points to instr_top. + +For example, if a backend has two portals open, the overall nesting of +Instrumentation and their respective InstrStart/InstrStop calls creates a +tree-like structure like this: + + Session (instr_top) + | + +-- Query A (QueryInstrumentation) + | | + | +-- NestLoop (NodeInstrumentation) + | | + | +-- Seq Scan A (NodeInstrumentation) + | +-- Seq Scan B (NodeInstrumentation) + | + +-- Query B (QueryInstrumentation) + | + +-- Seq Scan C (NodeInstrumentation) + +While executing Seq Scan B, the stack looks like: + + instr_top (implicit bottom, not in the entries array) + 0: Query A + 1: NestLoop + 2: Seq Scan B <-- instr_stack.current + +When no query is running, the stack is empty (stack_size == 0) and +instr_stack.current points to instr_top. + +Any buffer or WAL counter update (via the INSTR_BUFUSAGE_* and +INSTR_WALUSAGE_* macros in the buffer manager, WAL insertion code, etc.) +writes directly into instr_stack.current. Each instrumentation node starts +zeroed, so the values it accumulates while on top of the stack represent +exactly the activity that occurred during that time. + +Every Instrumentation node (except for instr_top) has a target, or parent, it +will be accumulated into, which is typically the Instrumentation that was the +current stack entry when it was created. + +For example, when Seq Scan A gets finalized in regular execution via ExecutorFinish, +its instrumentation data gets added to the immediate parent in +the execution tree, the NestLoop, which will then get added to Query A's +QueryInstrumentation, which then accumulates to the parent. + +While we can typically think of this as a tree, the NodeInstrumentation +underneath a particular QueryInstrumentation could behave differently -- +for example, it could propagate directly to the QueryInstrumentation, in +order to not show cumulative numbers in EXPLAIN ANALYZE. + +Note these relationships are partially implicit, especially when it comes +to NodeInstrumentation. Each QueryInstrumentation maintains a list of its +unfinalized child nodes. The parent of a QueryInstrumentation itself is +determined by the stack (see below): when a query is finalized or cleaned +up on abort, its counters are accumulated to whatever entry is then current +on the stack, which is typically instr_top. + + +Finalization and Abort Safety +============================= + +Finalization is the process of rolling up a node's buffer/WAL counters to +its parent. In normal execution, nodes are pushed onto the stack when they +start and popped when they stop; at finalization time their accumulated +counters are added to the parent. + +Due to the use of longjmp for error handling, functions can exit abruptly +without executing their normal cleanup code. On abort, two things need +to happen: + +1. The stack is reset to the level saved at the start of the aborting + (sub-)transaction level. This ensures that we don't later try to update + counters on a freed stack entry. We also need to ensure that the stack + entry that was current before a particular Instrumentation started, is + current again after it stops. + +2. Finalize all affected Instrumentation nodes, rolling up their counters + to the innermost surviving Instrumentation, so that data is not lost. + +For example, if Seq Scan B aborts while the stack is: + + instr_top (implicit bottom) + 0: Query A + 1: NestLoop + 2: Seq Scan B + +The abort handler for Query A accumulates all unfinalized children (Seq +Scan A, Seq Scan B, NestLoop) directly into Query A's counters, then +unwinds the instrumentation stack and accumulates Query A's counters to +instr_top. + +Note that on abort the children do not accumulate through each other (Seq +Scan B -> NestLoop -> Query A); they all accumulate directly to their +parent QueryInstrumentation. This means the order in which children are +released does not matter -- this is important because ResourceOwner cleanup +does not guarantee a particular release order. The per-node breakdown is lost, +but the instrumentation active when the query was started (instr_top in the +above example) survives the abort, and its counters include the activity. + +If multiple QueryInstrumentations are active on the stack (e.g. nested +portals), the abort handler of each uses InstrStopFinalize() to accumulate +the statistics to the parent entry of either the entry being released, or a +previously released entry if it was higher up in the stack, so they compose +correctly regardless of release order. + +There are two mechanisms for achieving abort safety: + +* Resource Owner (QueryInstrumentation): registers with the current + ResourceOwner at start. On transaction abort, the resource owner system + calls the release callback, which walks unfinalized child entries, + accumulates their data, unwinds the stack, and destroys the dedicated + memory context (freeing the QueryInstrumentation and all child + allocations as a unit). This is the recommended approach when the + instrumented code already has an appropriate resource owner (e.g. it + runs inside a portal). The query executor uses this path. + +* PG_FINALLY (base Instrumentation): when no suitable resource owner + exists, or when the caller wants to inspect the instrumentation data + even after an error, the base Instrumentation can be used with a + PG_TRY/PG_FINALLY block that calls InstrStopFinalize(). + +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 +for abort safety: they are allocated in the parent's memory context and +registered in its unfinalized-entries list, so the parent's abort handler +recovers their data automatically. In normal execution, children are +finalized explicitly by the caller. + +Parallel Query +-------------- + +Regardless of whether per-node instrumentation is active, each parallel +worker measures the buffer and WAL activity of its whole parallel section +with a QueryInstrumentation entry (InstrStartParallelQuery), and copies the +totals into dynamic shared memory at the end (InstrEndParallelQuery). The +leader accumulates these totals into its own stack, so that query-level +consumers such as EXPLAIN and pg_stat_statements see the complete activity. + +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. + + +Memory Handling +=============== + +Instrumentation objects that use the stack must survive until finalization +runs, including the abort case. To ensure this, QueryInstrumentation +creates a dedicated "Instrumentation" MemoryContext (instr_cxt). All child +instrumentation (nodes, triggers) should be allocated in this context. + +The parent of instr_cxt follows ownership. It is created as a child of the +context current at InstrQueryAlloc (the per-query context in the executor), +so that it is freed together with the caller's state if the caller is +abandoned before anything was measured, e.g. when ExecutorStart fails. The +first InstrQueryStart moves it under TopMemoryContext and registers it with +the current ResourceOwner, which stays responsible for it until +InstrQueryStopFinalize; this is necessary because the abort cleanup runs +after portal memory has already been released (see AtAbort_Portals), so the +context must not depend on it. Note that InstrQueryStop does not release +the registration, so an abort between two start/stop pairs, e.g. between +fetches from a cursor, still accumulates what was measured so far. + +On successful completion, InstrQueryStopFinalize releases the registration +and reparents instr_cxt to CurrentMemoryContext so its lifetime is tied to +the caller's context again. On abort, the ResourceOwner cleanup frees it +after accumulating the instrumentation data to the current stack entry +after resetting the stack. + +When the stack is not needed (timer/rows only), Instrumentation allocations +happen in CurrentMemoryContext and no dedicated context is created. diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c index d7a8f36ca1de1..dd71e8028e5a3 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -78,6 +78,7 @@ ExecutorCheckPerms_hook_type ExecutorCheckPerms_hook = NULL; /* decls for local routines only used within this module */ static void InitPlan(QueryDesc *queryDesc, int eflags); static void CheckValidRowMarkRel(Relation rel, RowMarkType markType); +static void ExecFinalizeTriggerInstrumentation(EState *estate); static void ExecPostprocessPlan(EState *estate); static void ExecEndPlan(PlanState *planstate, EState *estate); static void ExecutePlan(QueryDesc *queryDesc, @@ -254,10 +255,18 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags) * Set up query-level instrumentation if extensions have requested it via * query_instr_options. Ensure an extension has not allocated query_instr * itself. + * + * Alternatively, also set it up when running EXPLAIN (ANALYZE), as we + * utilize query_instr as the parent for node and trigger instrumentation. */ Assert(queryDesc->query_instr == NULL); - if (queryDesc->query_instr_options) - queryDesc->query_instr = InstrAlloc(queryDesc->query_instr_options); + if (queryDesc->query_instr_options || queryDesc->instrument_options) + { + estate->es_query_instr = InstrQueryAlloc(queryDesc->instrument_options | + queryDesc->query_instr_options); + + queryDesc->query_instr = &estate->es_query_instr->instr; + } /* * Set up an AFTER-trigger statement context, unless told not to, or @@ -340,9 +349,9 @@ standard_ExecutorRun(QueryDesc *queryDesc, */ oldcontext = MemoryContextSwitchTo(estate->es_query_cxt); - /* Allow instrumentation of Executor overall runtime */ - if (queryDesc->query_instr) - InstrStart(queryDesc->query_instr); + /* Start up instrumentation for this execution run */ + if (estate->es_query_instr) + InstrQueryStart(estate->es_query_instr); /* * extract information from the query descriptor and the query feature. @@ -393,8 +402,8 @@ standard_ExecutorRun(QueryDesc *queryDesc, if (sendTuples) dest->rShutdown(dest); - if (queryDesc->query_instr) - InstrStop(queryDesc->query_instr); + if (estate->es_query_instr) + InstrQueryStop(estate->es_query_instr); MemoryContextSwitchTo(oldcontext); } @@ -443,8 +452,8 @@ standard_ExecutorFinish(QueryDesc *queryDesc) oldcontext = MemoryContextSwitchTo(estate->es_query_cxt); /* Allow instrumentation of Executor overall runtime */ - if (queryDesc->query_instr) - InstrStart(queryDesc->query_instr); + if (estate->es_query_instr) + InstrQueryStart(estate->es_query_instr); /* Run ModifyTable nodes to completion */ ExecPostprocessPlan(estate); @@ -453,8 +462,28 @@ standard_ExecutorFinish(QueryDesc *queryDesc) if (!(estate->es_top_eflags & EXEC_FLAG_SKIP_TRIGGERS)) AfterTriggerEndQuery(estate); - if (queryDesc->query_instr) - InstrStop(queryDesc->query_instr); + if (estate->es_query_instr) + { + /* + * Accumulate per-node and trigger statistics to their respective + * parent instrumentation stacks. + * + * Parallel workers skip this: 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) + { + ExecFinalizeNodeInstrumentation(queryDesc->planstate); + + ExecFinalizeTriggerInstrumentation(estate); + } + + InstrQueryStopFinalize(estate->es_query_instr); + } MemoryContextSwitchTo(oldcontext); @@ -1287,7 +1316,8 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, Relation resultRelationDesc, Index resultRelationIndex, ResultRelInfo *partition_root_rri, - int instrument_options) + int instrument_options, + QueryInstrumentation *qinstr) { MemSet(resultRelInfo, 0, sizeof(ResultRelInfo)); resultRelInfo->type = T_ResultRelInfo; @@ -1308,8 +1338,19 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, palloc0_array(FmgrInfo, n); resultRelInfo->ri_TrigWhenExprs = (ExprState **) palloc0_array(ExprState *, n); + + /* + * Per-trigger instrumentation is only needed when per-node + * instrumentation (EXPLAIN ANALYZE) is requested. Query-level + * instrumentation alone (e.g. pg_stat_statements) accounts for + * trigger activity through the stack entry current while the trigger + * runs, so don't allocate anything in that case. + */ if (instrument_options) - resultRelInfo->ri_TrigInstrument = InstrAllocTrigger(n, instrument_options); + { + Assert(qinstr != NULL); + resultRelInfo->ri_TrigInstrument = InstrAllocTrigger(qinstr, instrument_options, n); + } } else { @@ -1381,6 +1422,10 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, * also provides a way for EXPLAIN ANALYZE to report the runtimes of such * triggers.) So we make additional ResultRelInfo's as needed, and save them * in es_trig_target_relations. + * + * Note: if new relation lists are searched here, they must also be added to + * ExecFinalizeTriggerInstrumentation so that trigger instrumentation data + * is properly accumulated. */ ResultRelInfo * ExecGetTriggerResultRel(EState *estate, Oid relid, @@ -1447,7 +1492,8 @@ ExecGetTriggerResultRel(EState *estate, Oid relid, rel, 0, /* dummy rangetable index */ rootRelInfo, - estate->es_instrument); + estate->es_instrument, + estate->es_query_instr); estate->es_trig_target_relations = lappend(estate->es_trig_target_relations, rInfo); MemoryContextSwitchTo(oldcontext); @@ -1508,9 +1554,14 @@ ExecGetAncestorResultRels(EState *estate, ResultRelInfo *resultRelInfo) ancRel = table_open(ancOid, NoLock); rInfo = makeNode(ResultRelInfo); - /* dummy rangetable index */ - InitResultRelInfo(rInfo, ancRel, 0, NULL, - estate->es_instrument); + /* + * Dummy rangetable index, and no trigger instrumentation: these + * ResultRelInfos are only used to queue AFTER triggers (see + * ExecCrossPartitionUpdateForeignKey). When those fire, the + * relation is looked up again via ExecGetTriggerResultRel, and + * the ResultRelInfo found there carries the instrumentation. + */ + InitResultRelInfo(rInfo, ancRel, 0, NULL, 0, NULL); ancResultRels = lappend(ancResultRels, rInfo); } ancResultRels = lappend(ancResultRels, rootRelInfo); @@ -1523,6 +1574,30 @@ ExecGetAncestorResultRels(EState *estate, ResultRelInfo *resultRelInfo) return resultRelInfo->ri_ancestorResultRels; } +static void +ExecFinalizeTriggerInstrumentation(EState *estate) +{ + List *rels = NIL; + + rels = list_concat(rels, estate->es_tuple_routing_result_relations); + rels = list_concat(rels, estate->es_opened_result_relations); + rels = list_concat(rels, estate->es_trig_target_relations); + + foreach_node(ResultRelInfo, rInfo, rels) + { + TriggerInstrumentation *ti = rInfo->ri_TrigInstrument; + + if (ti == NULL || rInfo->ri_TrigDesc == NULL) + continue; + + for (int nt = 0; nt < rInfo->ri_TrigDesc->numtriggers; nt++) + { + if (ti[nt].instr.need_stack) + InstrAccumStack(&estate->es_query_instr->instr, &ti[nt].instr); + } + } +} + /* ---------------------------------------------------------------- * ExecPostprocessPlan * @@ -3088,6 +3163,12 @@ EvalPlanQualStart(EPQState *epqstate, Plan *planTree) rcestate->es_output_cid = parentestate->es_output_cid; rcestate->es_queryEnv = parentestate->es_queryEnv; + /* + * es_instrument and es_query_instr must NOT be copied. EPQ is intended to + * be called from within other plan nodes, and we already track things on + * those plan nodes themselves, if needed. + */ + /* * ResultRelInfos needed by subplans are initialized from scratch when the * subplans themselves are initialized. @@ -3095,7 +3176,6 @@ EvalPlanQualStart(EPQState *epqstate, Plan *planTree) rcestate->es_result_relations = NULL; /* es_trig_target_relations must NOT be copied */ rcestate->es_top_eflags = parentestate->es_top_eflags; - rcestate->es_instrument = parentestate->es_instrument; /* es_auxmodifytables must NOT be copied */ /* diff --git a/src/backend/executor/execParallel.c b/src/backend/executor/execParallel.c index 316dd3f67c6e3..1ef88a951d540 100644 --- a/src/backend/executor/execParallel.c +++ b/src/backend/executor/execParallel.c @@ -1120,14 +1120,25 @@ ExecParallelRetrieveInstrumentation(PlanState *planstate, instrument = GetInstrumentationArray(instrumentation); instrument += i * instrumentation->num_workers; for (n = 0; n < instrumentation->num_workers; ++n) + { InstrAggNode(planstate->instrument, &instrument[n]); + /* + * The worker's per-node activity is not part of the query-level stats + * that InstrAccumParallelQuery receives (the worker does not roll up + * its nodes, to avoid double counting in EXPLAIN), so this is the + * point where it gets imported. + */ + InstrAccumWorkerUsage(&instrument[n].instr.bufusage, + &instrument[n].instr.walusage); + } + /* * Also store the per-worker detail. * - * Worker instrumentation should be allocated in the same context as the - * regular instrumentation information, which is the per-query context. - * Switch into per-query memory context. + * Ensure worker instrumentation is allocated in the per-query context. We + * don't need to place this in the instrumentation context since no more + * stack-based instrumentation work is being done. */ oldcontext = MemoryContextSwitchTo(planstate->state->es_query_cxt); ibytes = mul_size(instrumentation->num_workers, sizeof(NodeInstrumentation)); @@ -1286,9 +1297,13 @@ ExecParallelCleanup(ParallelExecutorInfo *pei) { /* Accumulate instrumentation, if any. */ if (pei->instrumentation) + { ExecParallelRetrieveInstrumentation(pei->planstate, pei->instrumentation); + ExecFinalizeWorkerInstrumentation(pei->planstate); + } + /* Accumulate JIT instrumentation, if any. */ if (pei->jit_instrumentation) ExecParallelRetrieveJitInstrumentation(pei->planstate, @@ -1529,6 +1544,7 @@ void ParallelQueryMain(dsm_segment *seg, shm_toc *toc) { FixedParallelExecutorState *fpes; + QueryInstrumentation *instr; BufferUsage *buffer_usage; WalUsage *wal_usage; DestReceiver *receiver; @@ -1589,7 +1605,7 @@ ParallelQueryMain(dsm_segment *seg, shm_toc *toc) * leader, which also doesn't count buffer accesses and WAL activity that * occur during executor startup. */ - InstrStartParallelQuery(); + instr = InstrStartParallelQuery(); /* * Run the plan. If we specified a tuple bound, be careful not to demand @@ -1605,7 +1621,8 @@ ParallelQueryMain(dsm_segment *seg, shm_toc *toc) /* Report buffer/WAL usage during parallel execution. */ buffer_usage = shm_toc_lookup(toc, PARALLEL_KEY_BUFFER_USAGE, false); wal_usage = shm_toc_lookup(toc, PARALLEL_KEY_WAL_USAGE, false); - InstrEndParallelQuery(&buffer_usage[ParallelWorkerNumber], + InstrEndParallelQuery(instr, + &buffer_usage[ParallelWorkerNumber], &wal_usage[ParallelWorkerNumber]); /* Report instrumentation data if any instrumentation options are set. */ diff --git a/src/backend/executor/execPartition.c b/src/backend/executor/execPartition.c index 4ec69f2bf993e..5acb76e145321 100644 --- a/src/backend/executor/execPartition.c +++ b/src/backend/executor/execPartition.c @@ -527,7 +527,8 @@ ExecInitPartitionInfo(ModifyTableState *mtstate, EState *estate, partrel, 0, rootResultRelInfo, - estate->es_instrument); + estate->es_instrument, + estate->es_query_instr); /* * Verify result relation is a valid target for an INSERT. An UPDATE of a @@ -1316,7 +1317,7 @@ ExecInitPartitionDispatchInfo(EState *estate, { ResultRelInfo *rri = makeNode(ResultRelInfo); - InitResultRelInfo(rri, rel, 0, rootResultRelInfo, 0); + InitResultRelInfo(rri, rel, 0, rootResultRelInfo, 0, NULL); proute->nonleaf_partitions[dispatchidx] = rri; } else diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index 7c4c66e323fed..5ca8d91344b87 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -122,6 +122,8 @@ static TupleTableSlot *ExecProcNodeFirst(PlanState *node); static bool ExecShutdownNode_walker(PlanState *node, void *context); +static bool ExecFinalizeNodeInstrumentation_walker(PlanState *node, void *context); +static bool ExecFinalizeWorkerInstrumentation_walker(PlanState *node, void *context); /* ------------------------------------------------------------------------ @@ -413,7 +415,8 @@ ExecInitNode(Plan *node, EState *estate, int eflags) /* Set up instrumentation for this node if requested */ if (estate->es_instrument) - result->instrument = InstrAllocNode(estate->es_instrument, + result->instrument = InstrAllocNode(estate->es_query_instr, + estate->es_instrument, result->async_capable); return result; @@ -768,10 +771,10 @@ ExecShutdownNode_walker(PlanState *node, void *context) * at least once already. We don't expect much CPU consumption during * node shutdown, but in the case of Gather or Gather Merge, we may shut * down workers at this stage. If so, their buffer usage will get - * propagated into pgBufferUsage at this point, and we want to make sure - * that it gets associated with the Gather node. We skip this if the node - * has never been executed, so as to avoid incorrectly making it appear - * that it has. + * propagated into the current instrumentation stack entry at this point, + * and we want to make sure that it gets associated with the Gather node. + * We skip this if the node has never been executed, so as to avoid + * incorrectly making it appear that it has. */ if (node->instrument && node->instrument->running) InstrStartNode(node->instrument); @@ -809,6 +812,99 @@ ExecShutdownNode_walker(PlanState *node, void *context) return false; } +/* + * ExecFinalizeNodeInstrumentation + * + * Accumulate instrumentation stats from all execution nodes to their respective + * parents (or the original parent instrumentation). + * + * This must run after the cleanup done by ExecShutdownNode, and not rely on any + * resources cleaned up by it. We also expect shutdown actions to have occurred, + * e.g. parallel worker instrumentation to have been added to the leader. + */ +void +ExecFinalizeNodeInstrumentation(PlanState *node) +{ + (void) ExecFinalizeNodeInstrumentation_walker(node, instr_stack.current); +} + +static bool +ExecFinalizeNodeInstrumentation_walker(PlanState *node, void *context) +{ + Instrumentation *parent = (Instrumentation *) context; + + Assert(parent != NULL); + + if (node == NULL) + return false; + + Assert(node->instrument != NULL); + + /* + * Recurse into children first (bottom-up accumulation), and accumulate to + * this node's instrumentation as the parent context. + */ + planstate_tree_walker(node, ExecFinalizeNodeInstrumentation_walker, + &node->instrument->instr); + + InstrFinalizeChild(&node->instrument->instr, parent); + + return false; +} + +/* + * ExecFinalizeWorkerInstrumentation + * + * Accumulate per-worker instrumentation stats from child nodes into their + * parents, mirroring what ExecFinalizeNodeInstrumentation does for the + * leader's own stats. Without this, per-worker buffer/WAL stats shown by + * EXPLAIN (ANALYZE, VERBOSE) would only reflect each node's own direct + * activity, not including children. + * + * This must run after ExecParallelRetrieveInstrumentation has populated + * worker_instrument for all nodes in the parallel subtree. + */ +void +ExecFinalizeWorkerInstrumentation(PlanState *node) +{ + (void) ExecFinalizeWorkerInstrumentation_walker(node, NULL); +} + +static bool +ExecFinalizeWorkerInstrumentation_walker(PlanState *node, void *context) +{ + PlanState *parent = (PlanState *) context; + int num_workers; + + if (node == NULL) + return false; + + /* + * Recurse into children first (bottom-up accumulation), passing this node + * as parent context if it has worker_instrument, otherwise pass through + * the previous parent. + */ + planstate_tree_walker(node, ExecFinalizeWorkerInstrumentation_walker, + node->worker_instrument ? (void *) node : context); + + if (!node->worker_instrument) + return false; + + num_workers = node->worker_instrument->num_workers; + + /* Accumulate this node's per-worker stats to parent's per-worker stats */ + if (parent && parent->worker_instrument) + { + int parent_workers = parent->worker_instrument->num_workers; + + for (int n = 0; n < Min(num_workers, parent_workers); n++) + InstrAccumStack(&parent->worker_instrument->instrument[n].instr, + &node->worker_instrument->instrument[n].instr); + } + + return false; +} + /* * ExecSetTupleBound * diff --git a/src/backend/executor/execUtils.c b/src/backend/executor/execUtils.c index c0c4276acbf0c..bb73f9d836dcc 100644 --- a/src/backend/executor/execUtils.c +++ b/src/backend/executor/execUtils.c @@ -151,6 +151,7 @@ CreateExecutorState(void) estate->es_top_eflags = 0; estate->es_instrument = 0; + estate->es_query_instr = NULL; estate->es_finished = false; estate->es_exprcontexts = NIL; @@ -229,7 +230,10 @@ FreeExecutorState(EState *estate) /* * Free the per-query memory context, thereby releasing all working - * memory, including the EState node itself. + * memory, including the EState node itself. This includes the + * instrumentation context (see InstrQueryAlloc), unless it is still + * registered with a resource owner, which cannot be the case here since + * ExecutorFinish has run or ExecutorRun was never called. */ MemoryContextDelete(estate->es_query_cxt); } @@ -912,7 +916,8 @@ ExecInitResultRelation(EState *estate, ResultRelInfo *resultRelInfo, resultRelationDesc, rti, NULL, - estate->es_instrument); + estate->es_instrument, + estate->es_query_instr); if (estate->es_result_relations == NULL) estate->es_result_relations = palloc0_array(ResultRelInfo *, diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index ffbcd57213396..9b660f6f210af 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -21,15 +21,45 @@ #include "nodes/execnodes.h" #include "portability/instr_time.h" #include "utils/guc_hooks.h" +#include "utils/memutils.h" +#include "utils/resowner.h" BufferUsage pgBufferUsage; -static BufferUsage save_pgBufferUsage; WalUsage pgWalUsage; -static WalUsage save_pgWalUsage; +Instrumentation instr_top; +InstrStackState instr_stack = { + .stack_space = 0, + .stack_size = 0, + .entries = NULL, + .current = &instr_top, +}; static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add); -static void WalUsageAdd(WalUsage *dst, WalUsage *add); +static void WalUsageAdd(WalUsage *dst, const WalUsage *add); +void +InstrStackGrow(void) +{ + int space = instr_stack.stack_space; + + Assert(instr_stack.stack_size >= instr_stack.stack_space); + + if (instr_stack.entries == NULL) + { + space = 10; /* Allocate sufficient initial space for + * typical activity */ + instr_stack.entries = MemoryContextAlloc(TopMemoryContext, + sizeof(Instrumentation *) * space); + } + else + { + space *= 2; + instr_stack.entries = repalloc_array(instr_stack.entries, Instrumentation *, space); + } + + /* Update stack space after allocation succeeded to protect against OOMs */ + instr_stack.stack_space = space; +} /* General purpose instrumentation handling */ Instrumentation * @@ -49,8 +79,22 @@ InstrInitOptions(Instrumentation *instr, int instrument_options) instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0; } -inline void -InstrStart(Instrumentation *instr) +static inline bool +InstrNeedStack(int instrument_options) +{ + return (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_WAL)) != 0; +} + +/* + * Common part of InstrStart and InstrStartNode: start the timer, and enter + * the entry onto the instrumentation stack. + * + * The diff-mode handling (see struct comment in instrument.h) lives only in + * InstrStart: node instrumentation never measures by diffing, so keeping the + * checks out of here keeps them out of the per-tuple ExecProcNodeInstr path. + */ +static inline void +InstrStartCommon(Instrumentation *instr) { if (instr->need_timer) { @@ -60,17 +104,30 @@ InstrStart(Instrumentation *instr) INSTR_TIME_SET_CURRENT_FAST(instr->starttime); } - /* save buffer usage totals at start, if needed */ - if (instr->need_bufusage) - instr->bufusage_start = pgBufferUsage; + if (instr->need_stack) + InstrPushStack(instr); +} + +inline void +InstrStart(Instrumentation *instr) +{ + InstrStartCommon(instr); - if (instr->need_walusage) - instr->walusage_start = pgWalUsage; + if (!instr->need_stack) + { + /* save buffer usage totals at start, if needed */ + if (instr->need_bufusage) + instr->bufusage_start = pgBufferUsage; + + if (instr->need_walusage) + instr->walusage_start = pgWalUsage; + } } /* * Helper for InstrStop() and InstrStopNode(), to avoid code duplication - * despite slightly different needs about how time is accumulated. + * despite slightly different needs about how time is accumulated. Like + * InstrStartCommon, this omits the diff-mode handling. */ static inline void InstrStopCommon(Instrumentation *instr, instr_time *accum_time) @@ -89,32 +146,360 @@ InstrStopCommon(Instrumentation *instr, instr_time *accum_time) INSTR_TIME_SET_ZERO(instr->starttime); } - /* Add delta of buffer usage since InstrStart to the totals */ - if (instr->need_bufusage) - BufferUsageAccumDiff(&instr->bufusage, - &pgBufferUsage, &instr->bufusage_start); - - if (instr->need_walusage) - WalUsageAccumDiff(&instr->walusage, - &pgWalUsage, &instr->walusage_start); + /* pop the stack, unless InstrStopFinalize previously cleaned up */ + if (instr->on_stack) + InstrPopStack(instr); } void InstrStop(Instrumentation *instr) { InstrStopCommon(instr, &instr->total); + + if (!instr->need_stack) + { + /* Add delta of buffer usage since InstrStart to the totals */ + if (instr->need_bufusage) + BufferUsageAccumDiff(&instr->bufusage, + &pgBufferUsage, &instr->bufusage_start); + + if (instr->need_walusage) + WalUsageAccumDiff(&instr->walusage, + &pgWalUsage, &instr->walusage_start); + } +} + +/* + * Workhorse for InstrStopFinalize and the abort cleanup. + * + * If 'allow_stopped' is set, the entry may already have been stopped (as + * happens for a QueryInstrumentation between two InstrQueryStart/InstrQueryStop + * pairs, e.g. between fetches from a cursor), in which case there is no timer + * to stop and only the accumulation to the parent remains. + */ +static void +InstrStopFinalizeInternal(Instrumentation *instr, bool allow_stopped) +{ + /* + * If our current node is on the stack, make sure we reset the stack to + * the parent of whichever of the released stack entries has the lowest + * index + */ + if (instr->on_stack) + { + int idx = -1; + + for (int i = instr_stack.stack_size - 1; i >= 0; i--) + { + if (instr_stack.entries[i] == instr) + { + idx = i; + break; + } + } + + if (idx < 0) + elog(ERROR, "instrumentation entry not found on stack"); + + /* Clear on_stack for any intermediate entries we're skipping over */ + for (int i = instr_stack.stack_size - 1; i > idx; i--) + instr_stack.entries[i]->on_stack = false; + + while (instr_stack.stack_size > idx + 1) + instr_stack.stack_size--; + } + + if (!(allow_stopped && instr->need_timer && + INSTR_TIME_IS_ZERO(instr->starttime))) + InstrStop(instr); + + /* + * Accumulate all instrumentation to the currently active instrumentation, + * so that callers get a complete picture of activity, even after an abort + */ + InstrAccumStack(instr_stack.current, instr); +} + +/* + * Stops instrumentation, finalizes the stack entry and accumulates to its parent. + * + * Note that this intentionally allows passing a stack that is not the current + * top, as can happen with PG_FINALLY, or resource owners, which don't have a + * guaranteed cleanup order. + */ +void +InstrStopFinalize(Instrumentation *instr) +{ + InstrStopFinalizeInternal(instr, false); +} + +/* + * Finalize a child entry registered with InstrQueryRememberChild, by + * accumulating its buffer/WAL usage to the provided instrumentation, which may + * be the current entry, or one the caller treats as a parent and will add to + * the totals later. + * + * The entry is removed from its parent's unfinalized list, so that the abort + * handling does not count it again, and marked as finalized: later calls are + * no-ops. The latter matters for the plan tree walkers in execProcnode.c, + * since planstate_tree_walker can reach the same PlanState more than once (a + * SubPlan appearing in several expressions of a plan node gets one + * SubPlanState per expression, all pointing at the same subplan PlanState). + * + * For entries that are not registered, e.g. copies of other processes' + * instrumentation, use InstrAccumStack instead. + */ +void +InstrFinalizeChild(Instrumentation *instr, Instrumentation *parent) +{ + if (!instr->need_stack || instr->finalized) + return; + + Assert(!dlist_node_is_detached(&instr->unfinalized_entry)); + dlist_delete_thoroughly(&instr->unfinalized_entry); + + InstrAccumStack(parent, instr); + instr->finalized = true; +} + + +/* Query instrumentation handling */ + +/* + * Use ResourceOwner mechanism to correctly reset instr_stack on abort. + */ +static void ResOwnerReleaseInstrumentation(Datum res); +static const ResourceOwnerDesc instrumentation_resowner_desc = +{ + .name = "instrumentation", + .release_phase = RESOURCE_RELEASE_AFTER_LOCKS, + .release_priority = RELEASE_PRIO_INSTRUMENTATION, + .ReleaseResource = ResOwnerReleaseInstrumentation, + .DebugPrint = NULL, /* default message is fine */ +}; + +static inline void +ResourceOwnerRememberInstrumentation(ResourceOwner owner, QueryInstrumentation *qinstr) +{ + ResourceOwnerRemember(owner, PointerGetDatum(qinstr), &instrumentation_resowner_desc); +} + +static inline void +ResourceOwnerForgetInstrumentation(ResourceOwner owner, QueryInstrumentation *qinstr) +{ + ResourceOwnerForget(owner, PointerGetDatum(qinstr), &instrumentation_resowner_desc); +} + +static void +ResOwnerReleaseInstrumentation(Datum res) +{ + QueryInstrumentation *qinstr = (QueryInstrumentation *) DatumGetPointer(res); + MemoryContext instr_cxt = qinstr->instr_cxt; + dlist_mutable_iter iter; + + /* Accumulate data from all unfinalized child entries (nodes, triggers) */ + dlist_foreach_modify(iter, &qinstr->unfinalized_entries) + { + Instrumentation *child = dlist_container(Instrumentation, unfinalized_entry, iter.cur); + + InstrAccumStack(&qinstr->instr, child); + } + + /* + * Ensure the stack is reset as expected, and we accumulate to the parent. + * The entry stays registered between InstrQueryStop and the next + * InstrQueryStart, so it may well not be running at this point. + */ + InstrStopFinalizeInternal(&qinstr->instr, true); + + /* + * Destroy the dedicated instrumentation context, which frees the + * QueryInstrumentation and all child allocations. + */ + MemoryContextDelete(instr_cxt); +} + +QueryInstrumentation * +InstrQueryAlloc(int instrument_options) +{ + QueryInstrumentation *instr; + MemoryContext instr_cxt; + + /* + * When the instrumentation stack is used, create a dedicated memory + * context for this query's instrumentation allocations. It starts out as + * a child of the current memory context, so that it is freed along with + * the caller's state if the caller is abandoned before InstrQueryStart, + * and is moved under TopMemoryContext while a ResourceOwner is + * responsible for it (see InstrQueryStart), since the abort cleanup needs + * to access it after the caller's memory may already be gone. + * + * For simpler cases (timer/rows only), use the current memory context. + * + * All child instrumentation allocations (nodes, triggers, etc) must be + * allocated within this context to ensure correct clean up on abort. + */ + if (InstrNeedStack(instrument_options)) + instr_cxt = AllocSetContextCreate(CurrentMemoryContext, + "Instrumentation", + ALLOCSET_SMALL_SIZES); + else + instr_cxt = CurrentMemoryContext; + + instr = MemoryContextAllocZero(instr_cxt, sizeof(QueryInstrumentation)); + instr->instrument_options = instrument_options; + instr->instr_cxt = instr_cxt; + + InstrInitOptions(&instr->instr, instrument_options); + instr->instr.need_stack = InstrNeedStack(instrument_options); + dlist_init(&instr->unfinalized_entries); + + return instr; +} + +void +InstrQueryStart(QueryInstrumentation *qinstr) +{ + /* + * On the first start, hand the entry over to the current ResourceOwner, + * which stays responsible for it until InstrQueryStopFinalize (or abort). + * It is intentionally not released at InstrQueryStop, so that an abort + * between two start/stop pairs (e.g. between fetches from a cursor) still + * accumulates what was measured so far. + */ + if (qinstr->instr.need_stack && qinstr->owner == NULL) + { + Assert(CurrentResourceOwner != NULL); + + /* + * Enlarge first, as that is the only step that can fail; once the + * context is under TopMemoryContext we must be sure to register it. + */ + ResourceOwnerEnlarge(CurrentResourceOwner); + MemoryContextSetParent(qinstr->instr_cxt, TopMemoryContext); + + qinstr->owner = CurrentResourceOwner; + ResourceOwnerRememberInstrumentation(qinstr->owner, qinstr); + } + + InstrStart(&qinstr->instr); +} + +void +InstrQueryStop(QueryInstrumentation *qinstr) +{ + InstrStop(&qinstr->instr); +} + +void +InstrQueryStopFinalize(QueryInstrumentation *qinstr) +{ + InstrStopFinalize(&qinstr->instr); + + if (!qinstr->instr.need_stack) + { + Assert(qinstr->owner == NULL); + return; + } + + Assert(qinstr->owner != NULL); + ResourceOwnerForgetInstrumentation(qinstr->owner, qinstr); + qinstr->owner = NULL; + + /* + * Reparent the dedicated instrumentation context under the current memory + * context, so that its lifetime is now tied to the caller's context + * rather than TopMemoryContext. + */ + MemoryContextSetParent(qinstr->instr_cxt, CurrentMemoryContext); +} + +/* + * Register a child Instrumentation entry for abort processing. + * + * On abort, ResOwnerReleaseInstrumentation will walk the parent's list to + * recover buffer/WAL data from entries that were never finalized, in order for + * aggregate totals to be accurate despite the query erroring out. + */ +void +InstrQueryRememberChild(QueryInstrumentation *parent, Instrumentation *child) +{ + if (child->need_stack) + dlist_push_head(&parent->unfinalized_entries, &child->unfinalized_entry); +} + +/* start instrumentation during parallel worker startup */ +QueryInstrumentation * +InstrStartParallelQuery(void) +{ + QueryInstrumentation *qinstr = InstrQueryAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); + + InstrQueryStart(qinstr); + return qinstr; +} + +/* + * Report usage after parallel worker shutdown, to be handed to the leader + * (which accumulates it into its own stack, see InstrAccumParallelQuery). + */ +void +InstrEndParallelQuery(QueryInstrumentation *qinstr, BufferUsage *bufusage, WalUsage *walusage) +{ + InstrQueryStopFinalize(qinstr); + memcpy(bufusage, &qinstr->instr.bufusage, sizeof(BufferUsage)); + memcpy(walusage, &qinstr->instr.walusage, sizeof(WalUsage)); +} + +/* + * Record WAL/buffer usage imported from a parallel worker. + */ +void +InstrAccumWorkerUsage(const BufferUsage *bufusage, const WalUsage *walusage) +{ + BufferUsageAdd(&pgBufferUsage, bufusage); + WalUsageAdd(&pgWalUsage, walusage); +} + +/* + * Accumulate work done by parallel workers in the leader's stats. + * + * Note that what gets added here effectively depends on whether per-node + * instrumentation is active. If it's active the parallel worker intentionally + * does not roll up its nodes into the query-level stats, because the leader + * aggregates the per-node stats separately (see ExecutorFinish). Instead, this + * only accumulates any extra activity outside of nodes. + * + * Otherwise this is responsible for making sure that the complete query + * activity is accumulated. + */ +void +InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage) +{ + InstrAccumWorkerUsage(bufusage, walusage); + + /* + * Unlike ExecParallelRetrieveInstrumentation, which merges worker usage + * into the leader's own node entries (and thus into the stack via + * finalization), there is no node to attribute query-level worker usage + * to, so add it to the current stack entry directly. + */ + BufferUsageAdd(&instr_stack.current->bufusage, bufusage); + WalUsageAdd(&instr_stack.current->walusage, walusage); } /* Node instrumentation handling */ /* Allocate new node instrumentation structure */ NodeInstrumentation * -InstrAllocNode(int instrument_options, bool async_mode) +InstrAllocNode(QueryInstrumentation *qinstr, int instrument_options, + bool async_mode) { - NodeInstrumentation *instr = palloc_object(NodeInstrumentation); + NodeInstrumentation *instr = MemoryContextAlloc(qinstr->instr_cxt, sizeof(NodeInstrumentation)); InstrInitNode(instr, instrument_options, async_mode); + InstrQueryRememberChild(qinstr, &instr->instr); + return instr; } @@ -124,6 +509,7 @@ InstrInitNode(NodeInstrumentation *instr, int instrument_options, bool async_mod { memset(instr, 0, sizeof(NodeInstrumentation)); InstrInitOptions(&instr->instr, instrument_options); + instr->instr.need_stack = InstrNeedStack(instrument_options); instr->async_mode = async_mode; } @@ -131,9 +517,10 @@ InstrInitNode(NodeInstrumentation *instr, int instrument_options, bool async_mod inline void InstrStartNode(NodeInstrumentation *instr) { - InstrStart(&instr->instr); + InstrStartCommon(&instr->instr); } + /* Exit from a plan node */ inline void InstrStopNode(NodeInstrumentation *instr, double nTuples) @@ -241,22 +628,34 @@ InstrAggNode(NodeInstrumentation *dst, NodeInstrumentation *add) dst->nfiltered1 += add->nfiltered1; dst->nfiltered2 += add->nfiltered2; - if (dst->instr.need_bufusage) - BufferUsageAdd(&dst->instr.bufusage, &add->instr.bufusage); - - if (dst->instr.need_walusage) - WalUsageAdd(&dst->instr.walusage, &add->instr.walusage); + if (dst->instr.need_stack) + { + Assert(!dst->instr.finalized); + InstrAccumStack(&dst->instr, &add->instr); + } } /* Trigger instrumentation handling */ TriggerInstrumentation * -InstrAllocTrigger(int n, int instrument_options) +InstrAllocTrigger(QueryInstrumentation *qinstr, int instrument_options, int n) { - TriggerInstrumentation *tginstr = palloc0_array(TriggerInstrumentation, n); + TriggerInstrumentation *tginstr; int i; + /* + * Allocate in the query's dedicated instrumentation context so all + * instrumentation data is grouped together and cleaned up as a unit. + */ + Assert(qinstr != NULL && qinstr->instr_cxt != NULL); + tginstr = MemoryContextAllocZero(qinstr->instr_cxt, + n * sizeof(TriggerInstrumentation)); + for (i = 0; i < n; i++) + { InstrInitOptions(&tginstr[i].instr, instrument_options); + tginstr[i].instr.need_stack = InstrNeedStack(instrument_options); + InstrQueryRememberChild(qinstr, &tginstr[i].instr); + } return tginstr; } @@ -270,34 +669,26 @@ InstrStartTrigger(TriggerInstrumentation *tginstr) void InstrStopTrigger(TriggerInstrumentation *tginstr, int64 firings) { + /* + * This trigger may be called again, so we don't finalize instrumentation + * here. Accumulation to the parent happens at ExecutorFinish through + * ExecFinalizeTriggerInstrumentation. + */ InstrStop(&tginstr->instr); tginstr->firings += firings; } -/* note current values during parallel executor startup */ void -InstrStartParallelQuery(void) +InstrAccumStack(Instrumentation *dst, Instrumentation *add) { - save_pgBufferUsage = pgBufferUsage; - save_pgWalUsage = pgWalUsage; -} + Assert(dst != NULL); + Assert(add != NULL); -/* report usage after parallel executor shutdown */ -void -InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage) -{ - memset(bufusage, 0, sizeof(BufferUsage)); - BufferUsageAccumDiff(bufusage, &pgBufferUsage, &save_pgBufferUsage); - memset(walusage, 0, sizeof(WalUsage)); - WalUsageAccumDiff(walusage, &pgWalUsage, &save_pgWalUsage); -} + if (!add->need_stack) + return; -/* accumulate work done by workers in leader's stats */ -void -InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage) -{ - BufferUsageAdd(&pgBufferUsage, bufusage); - WalUsageAdd(&pgWalUsage, walusage); + BufferUsageAdd(&dst->bufusage, &add->bufusage); + WalUsageAdd(&dst->walusage, &add->walusage); } /* dst += add */ @@ -354,7 +745,7 @@ BufferUsageAccumDiff(BufferUsage *dst, /* helper functions for WAL usage accumulation */ static inline void -WalUsageAdd(WalUsage *dst, WalUsage *add) +WalUsageAdd(WalUsage *dst, const WalUsage *add) { dst->wal_bytes += add->wal_bytes; dst->wal_records += add->wal_records; diff --git a/src/backend/replication/logical/worker.c b/src/backend/replication/logical/worker.c index 44d735cdc5555..bb3fd66a9ac59 100644 --- a/src/backend/replication/logical/worker.c +++ b/src/backend/replication/logical/worker.c @@ -915,7 +915,7 @@ create_edata_for_relation(LogicalRepRelMapEntry *rel) * Use Relation opened by logicalrep_rel_open() instead of opening it * again. */ - InitResultRelInfo(resultRelInfo, rel->localrel, 1, NULL, 0); + InitResultRelInfo(resultRelInfo, rel->localrel, 1, NULL, 0, NULL); /* * We put the ResultRelInfo in the es_opened_result_relations list, even diff --git a/src/include/executor/executor.h b/src/include/executor/executor.h index 152a1dfa568b0..e34dd2c805412 100644 --- a/src/include/executor/executor.h +++ b/src/include/executor/executor.h @@ -233,6 +233,7 @@ ExecGetJunkAttribute(TupleTableSlot *slot, AttrNumber attno, bool *isNull) /* * prototypes from functions in execMain.c */ +typedef struct QueryInstrumentation QueryInstrumentation; extern void ExecutorStart(QueryDesc *queryDesc, int eflags); extern void standard_ExecutorStart(QueryDesc *queryDesc, int eflags); extern void ExecutorRun(QueryDesc *queryDesc, @@ -254,7 +255,8 @@ extern void InitResultRelInfo(ResultRelInfo *resultRelInfo, Relation resultRelationDesc, Index resultRelationIndex, ResultRelInfo *partition_root_rri, - int instrument_options); + int instrument_options, + QueryInstrumentation *qinstr); extern ResultRelInfo *ExecGetTriggerResultRel(EState *estate, Oid relid, ResultRelInfo *rootRelInfo); extern List *ExecGetAncestorResultRels(EState *estate, ResultRelInfo *resultRelInfo); @@ -301,6 +303,8 @@ extern void ExecSetExecProcNode(PlanState *node, ExecProcNodeMtd function); extern Node *MultiExecProcNode(PlanState *node); extern void ExecEndNode(PlanState *node); extern void ExecShutdownNode(PlanState *node); +extern void ExecFinalizeNodeInstrumentation(PlanState *node); +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 18c9542a3d453..e63af41089f18 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -13,6 +13,7 @@ #ifndef INSTRUMENT_H #define INSTRUMENT_H +#include "lib/ilist.h" #include "portability/instr_time.h" @@ -69,10 +70,22 @@ typedef enum InstrumentOption } InstrumentOption; /* - * General purpose instrumentation that can capture time and WAL/buffer usage + * Instrumentation base class for capturing time and WAL/buffer usage * - * Initialized through InstrAlloc, followed by one or more calls to a pair of - * InstrStart/InstrStop (activity is measured in between). + * If used directly (InstrAlloc, or a zero initialized struct followed by + * InstrInitOptions), WAL/buffer usage is measured by diffing the global + * pgBufferUsage/pgWalUsage counters between InstrStart and InstrStop. This + * is independent of the instrumentation stack and needs no special handling + * for transaction aborts. + * + * Entries with need_stack set, as used by QueryInstrumentation and the node and + * trigger instrumentation, are instead pushed onto the instrumentation stack by + * InstrStart, so that all activity gets recorded directly in them (the diff + * flags are ignored). The last stop call must then be to InstrStopFinalize, to + * ensure parent stack entries get the accumulated totals. If there is risk of + * transaction aborts you must call InstrStopFinalize in a PG_TRY/PG_FINALLY + * block to avoid corrupting the instrumentation stack, or use + * QueryInstrumentation, which handles aborts using the resource owner logic. */ typedef struct Instrumentation { @@ -80,18 +93,79 @@ typedef struct Instrumentation bool need_timer; /* true if we need timer data */ bool need_bufusage; /* true if we need buffer usage data */ bool need_walusage; /* true if we need WAL usage data */ + bool need_stack; /* true if WAL/buffer usage is tracked via + * instr_stack instead */ /* Internal state keeping: */ + bool on_stack; /* true if currently on instr_stack */ + bool finalized; /* true once accumulated to a parent via + * InstrFinalizeChild */ instr_time starttime; /* start time of last InstrStart */ - BufferUsage bufusage_start; /* buffer usage at start */ - WalUsage walusage_start; /* WAL usage at start */ + BufferUsage bufusage_start; /* buffer usage at start (diff mode) */ + WalUsage walusage_start; /* WAL usage at start (diff mode) */ /* Accumulated statistics: */ instr_time total; /* total runtime */ BufferUsage bufusage; /* total buffer usage */ WalUsage walusage; /* total WAL usage */ + /* Abort handling: link in parent QueryInstrumentation's unfinalized list */ + dlist_node unfinalized_entry; } Instrumentation; +/* + * Query-related instrumentation tracking. + * + * Usage: + * - Allocate on the heap using InstrQueryAlloc (required for abort handling) + * - Call InstrQueryStart before the activity you want to measure + * - Call InstrQueryStop / InstrQueryStopFinalize afterwards to capture totals + * + * InstrQueryStart/InstrQueryStop may be called multiple times. The last stop + * call must be to InstrQueryStopFinalize to ensure parent stack entries get + * the accumulated totals. + * + * Uses resource owner mechanism for handling aborts: the first InstrQueryStart + * registers the entry with the current resource owner, and it stays registered + * (also across InstrQueryStop / InstrQueryStart pairs) until + * InstrQueryStopFinalize. In the case of an abort, logic equivalent to + * InstrQueryStopFinalize is run by the resource owner cleanup, so the caller + * must not release that resource owner without an abort before having called + * InstrQueryStopFinalize. + */ +struct ResourceOwnerData; +typedef struct QueryInstrumentation +{ + Instrumentation instr; + + /* Original instrument_options flags used to create this instrumentation */ + int instrument_options; + + /* Resource owner used for cleanup for aborts between InstrStart/InstrStop */ + struct ResourceOwnerData *owner; + + /* + * Dedicated memory context for all instrumentation allocations belonging + * to this query (node instrumentation, trigger instrumentation, etc.). + * Initially a child of the context current at InstrQueryAlloc, moved + * under TopMemoryContext by InstrQueryStart while the ResourceOwner is + * responsible for it (so it survives transaction abort for the cleanup), + * and reassigned to the current memory context on InstrQueryStopFinalize. + */ + MemoryContext instr_cxt; + + /* + * Child entries that need to be cleaned up on abort, since they are not + * registered as a resource owner themselves. Contains both node and + * trigger instrumentation entries linked via instr.unfinalized_entry. + */ + dlist_head unfinalized_entries; +} QueryInstrumentation; + /* * Specialized instrumentation for per-node execution statistics + * + * Relies on an outer QueryInstrumentation having been set up to handle the + * stack used for WAL/buffer usage statistics, and relies on it for managing + * aborts. Solely intended for the executor and anyone reporting about its + * activities (e.g. EXPLAIN ANALYZE). */ typedef struct NodeInstrumentation { @@ -112,6 +186,10 @@ typedef struct NodeInstrumentation double nfiltered2; /* # of tuples removed by "other" quals */ } NodeInstrumentation; +/* + * Care must be taken with any pointers contained within this struct, as this + * gets copied across processes during parallel query execution. + */ typedef struct WorkerNodeInstrumentation { int num_workers; /* # of structures that follow */ @@ -125,15 +203,110 @@ typedef struct TriggerInstrumentation * was fired */ } TriggerInstrumentation; +/* + * Dynamic array-based stack for tracking current WAL/buffer usage context. + * + * When the stack is empty, 'current' points to instr_top which accumulates + * session-level totals. + */ +typedef struct InstrStackState +{ + int stack_space; /* allocated capacity of entries array */ + int stack_size; /* current number of entries */ + + Instrumentation **entries; /* dynamic array of pointers */ + Instrumentation *current; /* top of stack, or &instr_top when empty */ +} InstrStackState; + +/* + * Running totals of the current backend's buffer/WAL usage, kept updated + * alongside the instrumentation stack. + */ extern PGDLLIMPORT BufferUsage pgBufferUsage; extern PGDLLIMPORT WalUsage pgWalUsage; +/* + * The top instrumentation represents a running total of the current backend + * WAL/buffer usage information. This will not be updated immediately, but + * rather when the current stack entry gets accumulated which typically happens + * at query end. + * + * In a parallel query leader this also includes the usage reported back by + * parallel workers, since that gets accumulated into the leader's stack. + */ +extern PGDLLIMPORT Instrumentation instr_top; + +/* + * The instrumentation stack state. The 'current' field points to the + * currently active stack entry that is getting updated as activity happens, + * and will be accumulated to parent stacks when it gets finalized by + * InstrStop (for non-executor use cases), ExecFinalizeNodeInstrumentation + * (executor finish) or ResOwnerReleaseInstrumentation on abort. + */ +extern PGDLLIMPORT InstrStackState instr_stack; + +extern void InstrStackGrow(void); + +/* + * Pushes the stack so that all WAL/buffer usage updates go to the passed in + * instrumentation entry. + * + * See note on InstrPopStack regarding safe use of these functions. + */ +static inline void +InstrPushStack(Instrumentation *instr) +{ + if (unlikely(instr_stack.stack_size == instr_stack.stack_space)) + InstrStackGrow(); + + instr_stack.entries[instr_stack.stack_size++] = instr; + instr_stack.current = instr; + instr->on_stack = true; +} + +/* + * Pops the stack entry back to the previous one that was effective at + * InstrPushStack. + * + * Callers must ensure that no intermediate stack entries are skipped, to + * handle aborts correctly. If you're thinking of calling this in a PG_FINALLY + * block, consider instead using InstrStart + InstrStopFinalize which can skip + * intermediate stack entries. + */ +static inline void +InstrPopStack(Instrumentation *instr) +{ + Assert(instr_stack.stack_size > 0); + Assert(instr_stack.entries[instr_stack.stack_size - 1] == instr); + instr_stack.stack_size--; + instr_stack.current = instr_stack.stack_size > 0 + ? instr_stack.entries[instr_stack.stack_size - 1] + : &instr_top; + instr->on_stack = false; +} + extern Instrumentation *InstrAlloc(int instrument_options); 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 InstrFinalizeChild(Instrumentation *instr, Instrumentation *parent); +extern void InstrAccumStack(Instrumentation *dst, Instrumentation *add); + +extern QueryInstrumentation *InstrQueryAlloc(int instrument_options); +extern void InstrQueryStart(QueryInstrumentation *instr); +extern void InstrQueryStop(QueryInstrumentation *instr); +extern void InstrQueryStopFinalize(QueryInstrumentation *instr); +extern void InstrQueryRememberChild(QueryInstrumentation *parent, Instrumentation *instr); + +pg_nodiscard extern QueryInstrumentation *InstrStartParallelQuery(void); +extern void InstrEndParallelQuery(QueryInstrumentation *qinstr, BufferUsage *bufusage, WalUsage *walusage); +extern void InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage); +extern void InstrAccumWorkerUsage(const BufferUsage *bufusage, + const WalUsage *walusage); -extern NodeInstrumentation *InstrAllocNode(int instrument_options, +extern NodeInstrumentation *InstrAllocNode(QueryInstrumentation *qinstr, + int instrument_options, bool async_mode); extern void InstrInitNode(NodeInstrumentation *instr, int instrument_options, bool async_mode); @@ -143,13 +316,11 @@ extern void InstrUpdateTupleCount(NodeInstrumentation *instr, double nTuples); extern void InstrEndLoop(NodeInstrumentation *instr); extern void InstrAggNode(NodeInstrumentation *dst, NodeInstrumentation *add); -extern TriggerInstrumentation *InstrAllocTrigger(int n, int instrument_options); +extern TriggerInstrumentation *InstrAllocTrigger(QueryInstrumentation *qinstr, + int instrument_options, int n); extern void InstrStartTrigger(TriggerInstrumentation *tginstr); extern void InstrStopTrigger(TriggerInstrumentation *tginstr, int64 firings); -extern void InstrStartParallelQuery(void); -extern void InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage); -extern void InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage); extern void BufferUsageAccumDiff(BufferUsage *dst, const BufferUsage *add, const BufferUsage *sub); extern void WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, @@ -157,21 +328,28 @@ extern void WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, #define INSTR_BUFUSAGE_INCR(fld) do { \ pgBufferUsage.fld++; \ + instr_stack.current->bufusage.fld++; \ } while(0) #define INSTR_BUFUSAGE_ADD(fld,val) do { \ pgBufferUsage.fld += (val); \ + instr_stack.current->bufusage.fld += (val); \ } while(0) #define INSTR_BUFUSAGE_TIME_ADD(fld,val) do { \ INSTR_TIME_ADD(pgBufferUsage.fld, val); \ + INSTR_TIME_ADD(instr_stack.current->bufusage.fld, val); \ } while (0) #define INSTR_BUFUSAGE_TIME_ACCUM_DIFF(fld,endval,startval) do { \ INSTR_TIME_ACCUM_DIFF(pgBufferUsage.fld, endval, startval); \ + INSTR_TIME_ACCUM_DIFF(instr_stack.current->bufusage.fld, endval, startval); \ } while (0) + #define INSTR_WALUSAGE_INCR(fld) do { \ pgWalUsage.fld++; \ + instr_stack.current->walusage.fld++; \ } while(0) #define INSTR_WALUSAGE_ADD(fld,val) do { \ pgWalUsage.fld += (val); \ + instr_stack.current->walusage.fld += (val); \ } while(0) #endif /* INSTRUMENT_H */ diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h index fe8681ba642e7..14e0d366fe374 100644 --- a/src/include/nodes/execnodes.h +++ b/src/include/nodes/execnodes.h @@ -53,6 +53,7 @@ typedef struct Instrumentation Instrumentation; typedef struct pairingheap pairingheap; typedef struct PlanState PlanState; typedef struct QueryEnvironment QueryEnvironment; +typedef struct QueryInstrumentation QueryInstrumentation; typedef struct RelationData *Relation; typedef Relation *RelationPtr; typedef struct ScanKeyData ScanKeyData; @@ -732,6 +733,7 @@ typedef struct EState int es_top_eflags; /* eflags passed to ExecutorStart */ int es_instrument; /* OR of InstrumentOption flags */ + QueryInstrumentation *es_query_instr; /* query-level instrumentation */ bool es_finished; /* true when ExecutorFinish is done */ List *es_exprcontexts; /* List of ExprContexts within EState */ diff --git a/src/include/utils/resowner.h b/src/include/utils/resowner.h index eb6033b4fdb65..5463bc921f06e 100644 --- a/src/include/utils/resowner.h +++ b/src/include/utils/resowner.h @@ -75,6 +75,7 @@ typedef uint32 ResourceReleasePriority; #define RELEASE_PRIO_SNAPSHOT_REFS 500 #define RELEASE_PRIO_FILES 600 #define RELEASE_PRIO_WAITEVENTSETS 700 +#define RELEASE_PRIO_INSTRUMENTATION 800 /* 0 is considered invalid */ #define RELEASE_PRIO_FIRST 1 diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list index b964e5ee90770..1970b6cf92c55 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -1351,6 +1351,7 @@ InjectionPointSharedState InjectionPointsCtl InlineCodeBlock InsertStmt +InstrStackState Instrumentation Int128AggState Int8TransTypeData @@ -2480,6 +2481,7 @@ QueryCompletion QueryDesc QueryEnvironment QueryInfo +QueryInstrumentation QueryItem QueryItemType QueryMode From 8a79fcb5ef7b2379855619b5e75a8b612f103ca2 Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Thu, 22 Oct 2026 15:21:56 +0200 Subject: [PATCH 5/9] instrumentation: Retire pgBufferUsage in favor of stack-based approach The stack-based instrumentation left the plain Instrumentation API (InstrAlloc/InstrInitOptions with InstrStart/InstrStop) measuring by diffing the global pgBufferUsage/pgWalUsage counters, and kept pgBufferUsage updated alongside the stack for that purpose. Convert the remaining users of that API to the stack: VACUUM and ANALYZE logging as well as the planning-time measurement of EXPLAIN and EXECUTE use QueryInstrumentation, which handles aborts through the resource owner, while pg_stat_statements wraps its planner and utility statement timing in PG_TRY/PG_FINALLY and the EXPLAIN (SERIALIZE) destination receiver registers its entry as a child of the query instrumentation. With that, Instrumentation entries always track WAL/buffer usage through the stack, so remove the diff mode along with the global pgBufferUsage and BufferUsageAccumDiff, and update comments that referred to it. Extensions that read pgBufferUsage directly should use InstrStart and InstrStop around the code section they want to measure instead. The related global pgWalUsage is kept for now due to its use in pgstat to track aggregate WAL activity and heap_page_prune_and_freeze for measuring FPIs. Author: Lukas Fittl Reviewed-by: Discussion: https://postgr.es/m/CAP53PkzdBK8VJ1fS4AZ481LgMN8f9mJiC39ZRHqkFUSYq6KWmg%40mail.gmail.com --- .../pg_stat_statements/pg_stat_statements.c | 6 +- src/backend/access/brin/brin.c | 4 +- src/backend/access/gin/gininsert.c | 4 +- src/backend/access/heap/vacuumlazy.c | 12 +-- src/backend/access/nbtree/nbtsort.c | 4 +- src/backend/commands/analyze.c | 12 +-- src/backend/commands/explain.c | 25 +++-- src/backend/commands/explain_dr.c | 29 +++++ src/backend/commands/prepare.c | 21 ++-- src/backend/commands/vacuumparallel.c | 4 +- src/backend/executor/execParallel.c | 2 +- src/backend/executor/instrument.c | 100 ++---------------- src/backend/storage/buffer/bufmgr.c | 6 +- src/backend/utils/activity/pgstat_io.c | 6 +- src/include/commands/explain_dr.h | 2 + src/include/executor/instrument.h | 47 +++----- 16 files changed, 114 insertions(+), 170 deletions(-) diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index 3f3604cda84ba..248cee584ffe4 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -943,12 +943,11 @@ pgss_planner(Query *parse, } PG_FINALLY(); { + InstrStopFinalize(&instr); nesting_level--; } PG_END_TRY(); - InstrStop(&instr); - pgss_store(query_string, parse->queryId, parse->stmt_location, @@ -1177,6 +1176,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, } PG_FINALLY(); { + InstrStopFinalize(&instr); nesting_level--; } PG_END_TRY(); @@ -1192,8 +1192,6 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, */ pstmt = NULL; - InstrStop(&instr); - /* * Track the total number of rows retrieved or affected by the utility * statements of COPY, FETCH, CREATE TABLE AS, CREATE MATERIALIZED diff --git a/src/backend/access/brin/brin.c b/src/backend/access/brin/brin.c index 8c2c69605ce0e..730b17d232fb5 100644 --- a/src/backend/access/brin/brin.c +++ b/src/backend/access/brin/brin.c @@ -2434,8 +2434,8 @@ _brin_begin_parallel(BrinBuildState *buildstate, Relation heap, Relation index, * and PARALLEL_KEY_BUFFER_USAGE. * * If there are no extensions loaded that care, we could skip this. We - * have no way of knowing whether anyone's looking at pgWalUsage or - * pgBufferUsage, so do it unconditionally. + * have no way of knowing whether anyone's looking at instrumentation, so + * do it unconditionally. */ shm_toc_estimate_chunk(&pcxt->estimator, mul_size(sizeof(WalUsage), pcxt->nworkers)); diff --git a/src/backend/access/gin/gininsert.c b/src/backend/access/gin/gininsert.c index b3b90ee6685d4..af04d8643b01c 100644 --- a/src/backend/access/gin/gininsert.c +++ b/src/backend/access/gin/gininsert.c @@ -991,8 +991,8 @@ _gin_begin_parallel(GinBuildState *buildstate, Relation heap, Relation index, * and PARALLEL_KEY_BUFFER_USAGE. * * If there are no extensions loaded that care, we could skip this. We - * have no way of knowing whether anyone's looking at pgWalUsage or - * pgBufferUsage, so do it unconditionally. + * have no way of knowing whether anyone's looking at instrumentation, so + * do it unconditionally. */ shm_toc_estimate_chunk(&pcxt->estimator, mul_size(sizeof(WalUsage), pcxt->nworkers)); diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index f2ee5dccc9fe2..169fd82aec2db 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -636,7 +636,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, new_rel_allfrozen; PGRUsage ru0; TimestampTz starttime = 0; - Instrumentation *instr = NULL; + QueryInstrumentation *instr = NULL; ErrorContextCallback errcallback; char **indnames = NULL; Size dead_items_max_bytes = 0; @@ -647,8 +647,8 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, if (instrument) { pg_rusage_init(&ru0); - instr = InstrAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); - InstrStart(instr); + instr = InstrQueryAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); + InstrQueryStart(instr); } /* Used for instrumentation and stats report */ @@ -989,7 +989,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, { TimestampTz endtime = GetCurrentTimestamp(); - InstrStop(instr); + InstrQueryStopFinalize(instr); if (verbose || params->log_vacuum_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, @@ -1005,8 +1005,8 @@ 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; + BufferUsage bufferusage = instr->instr.bufusage; + WalUsage walusage = instr->instr.walusage; TimestampDifference(starttime, endtime, &secs_dur, &usecs_dur); diff --git a/src/backend/access/nbtree/nbtsort.c b/src/backend/access/nbtree/nbtsort.c index 3d88c2556bb80..2d7b7cef91202 100644 --- a/src/backend/access/nbtree/nbtsort.c +++ b/src/backend/access/nbtree/nbtsort.c @@ -1466,8 +1466,8 @@ _bt_begin_parallel(BTBuildState *buildstate, bool isconcurrent, int request) * and PARALLEL_KEY_BUFFER_USAGE. * * If there are no extensions loaded that care, we could skip this. We - * have no way of knowing whether anyone's looking at pgWalUsage or - * pgBufferUsage, so do it unconditionally. + * have no way of knowing whether anyone's looking at instrumentation, so + * do it unconditionally. */ shm_toc_estimate_chunk(&pcxt->estimator, mul_size(sizeof(WalUsage), pcxt->nworkers)); diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 382b318137456..371b56b339ded 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -354,7 +354,7 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, Oid save_userid; int save_sec_context; int save_nestlevel; - Instrumentation *instr = NULL; + QueryInstrumentation *instr = NULL; PgStat_Counter startreadtime = 0; PgStat_Counter startwritetime = 0; @@ -406,8 +406,8 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, pg_rusage_init(&ru0); - instr = InstrAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); - InstrStart(instr); + instr = InstrQueryAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); + InstrQueryStart(instr); } /* Used for instrumentation and stats report */ @@ -770,7 +770,7 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, { TimestampTz endtime = GetCurrentTimestamp(); - InstrStop(instr); + InstrQueryStopFinalize(instr); if (verbose || params->log_analyze_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, @@ -784,8 +784,8 @@ do_analyze_rel(Relation onerel, const VacuumParams *params, int64 total_blks_hit; int64 total_blks_read; int64 total_blks_dirtied; - BufferUsage bufusage = instr->bufusage; - WalUsage walusage = instr->walusage; + BufferUsage bufusage = instr->instr.bufusage; + WalUsage walusage = instr->instr.walusage; total_blks_hit = bufusage.shared_blks_hit + bufusage.local_blks_hit; diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index ca8c071ec0414..97d56f2bd939e 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -327,7 +327,7 @@ standard_ExplainOneQuery(Query *query, int cursorOptions, QueryEnvironment *queryEnv) { PlannedStmt *plan; - Instrumentation plan_instr = {0}; + QueryInstrumentation *plan_instr = NULL; int instrument_options = INSTRUMENT_TIMER; MemoryContextCounters mem_counters; MemoryContext planner_ctx = NULL; @@ -336,7 +336,7 @@ standard_ExplainOneQuery(Query *query, int cursorOptions, if (es->buffers) instrument_options |= INSTRUMENT_BUFFERS; - InstrInitOptions(&plan_instr, instrument_options); + plan_instr = InstrQueryAlloc(instrument_options); if (es->memory) { @@ -354,22 +354,27 @@ standard_ExplainOneQuery(Query *query, int cursorOptions, saved_ctx = MemoryContextSwitchTo(planner_ctx); } - InstrStart(&plan_instr); + InstrQueryStart(plan_instr); /* plan the query */ plan = pg_plan_query(query, queryString, cursorOptions, params, es); - InstrStop(&plan_instr); - if (es->memory) - { MemoryContextSwitchTo(saved_ctx); + + /* + * Finalize only after switching back, so that the instrumentation's + * memory context gets reparented to our context rather than the planner + * one, where it would be counted as planner memory. + */ + InstrQueryStopFinalize(plan_instr); + + if (es->memory) MemoryContextMemConsumed(planner_ctx, &mem_counters); - } /* run it (if needed) and produce output */ ExplainOnePlan(plan, into, es, queryString, params, queryEnv, - &plan_instr.total, (es->buffers ? &plan_instr.bufusage : NULL), + &plan_instr->instr.total, (es->buffers ? &plan_instr->instr.bufusage : NULL), es->memory ? &mem_counters : NULL); } @@ -565,6 +570,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, /* call ExecutorStart to prepare the plan for execution */ ExecutorStart(queryDesc, eflags); + /* Point the SERIALIZE receiver at the now-created query instrumentation. */ + if (es->serialize != EXPLAIN_SERIALIZE_NONE) + SetExplainSerializeQueryInstr(dest, queryDesc->estate->es_query_instr); + /* Execute the plan for statistics if asked for */ if (es->analyze) { diff --git a/src/backend/commands/explain_dr.c b/src/backend/commands/explain_dr.c index 9f9e73f14a33e..9c90902cfaefe 100644 --- a/src/backend/commands/explain_dr.c +++ b/src/backend/commands/explain_dr.c @@ -41,6 +41,7 @@ typedef struct SerializeDestReceiver MemoryContext tmpcontext; /* per-row temporary memory context */ StringInfoData buf; /* buffer to hold the constructed message */ SerializeMetrics metrics; /* collected metrics */ + QueryInstrumentation *qinstr; /* parent instrumentation to accumulate to */ } SerializeDestReceiver; /* @@ -226,6 +227,14 @@ serializeAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo) if (receiver->es->buffers) instrument_options |= INSTRUMENT_BUFFERS; InstrInitOptions(&receiver->metrics.instr, instrument_options); + + /* + * Register the metrics as a child of the query instrumentation, so the + * usage measured below reaches the session totals even on error, when + * serializeAnalyzeShutdown (which finalizes it on success) is not called. + */ + Assert(receiver->qinstr != NULL); + InstrQueryRememberChild(receiver->qinstr, &receiver->metrics.instr); } /* @@ -236,6 +245,9 @@ serializeAnalyzeShutdown(DestReceiver *self) { SerializeDestReceiver *receiver = (SerializeDestReceiver *) self; + /* Accumulate what we measured to the query instrumentation. */ + InstrFinalizeChild(&receiver->metrics.instr, &receiver->qinstr->instr); + if (receiver->finfos) pfree(receiver->finfos); receiver->finfos = NULL; @@ -279,6 +291,23 @@ CreateExplainSerializeDestReceiver(ExplainState *es) return (DestReceiver *) self; } +/* + * Set the query instrumentation that a serialize receiver accumulates to. + * + * Must be called after ExecutorStart has created the instrumentation and + * before the query runs. A no-op for other receivers. + */ +void +SetExplainSerializeQueryInstr(DestReceiver *self, QueryInstrumentation *qinstr) +{ + SerializeDestReceiver *receiver = (SerializeDestReceiver *) self; + + if (receiver->pub.mydest != DestExplainSerialize) + return; + + receiver->qinstr = qinstr; +} + /* * GetSerializationMetrics - get serialization metrics * diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c index bf9f2eb614997..9a673a9971d3c 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -581,7 +581,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, ListCell *p; ParamListInfo paramLI = NULL; EState *estate = NULL; - Instrumentation plan_instr = {0}; + QueryInstrumentation *plan_instr = NULL; int instrument_options = INSTRUMENT_TIMER; MemoryContextCounters mem_counters; MemoryContext planner_ctx = NULL; @@ -590,7 +590,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, if (es->buffers) instrument_options |= INSTRUMENT_BUFFERS; - InstrInitOptions(&plan_instr, instrument_options); + plan_instr = InstrQueryAlloc(instrument_options); if (es->memory) { @@ -602,7 +602,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, saved_ctx = MemoryContextSwitchTo(planner_ctx); } - InstrStart(&plan_instr); + InstrQueryStart(plan_instr); /* Look it up in the hash table */ entry = FetchPreparedStatement(execstmt->name, true); @@ -637,13 +637,18 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, cplan = GetCachedPlan(entry->plansource, paramLI, CurrentResourceOwner, pstate->p_queryEnv); - InstrStop(&plan_instr); - if (es->memory) - { MemoryContextSwitchTo(saved_ctx); + + /* + * Finalize only after switching back, so that the instrumentation's + * memory context gets reparented to our context rather than the planner + * one, where it would be counted as planner memory. + */ + InstrQueryStopFinalize(plan_instr); + + if (es->memory) MemoryContextMemConsumed(planner_ctx, &mem_counters); - } plan_list = cplan->stmt_list; @@ -654,7 +659,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, if (pstmt->commandType != CMD_UTILITY) ExplainOnePlan(pstmt, into, es, query_string, paramLI, pstate->p_queryEnv, - &plan_instr.total, (es->buffers ? &plan_instr.bufusage : NULL), + &plan_instr->instr.total, (es->buffers ? &plan_instr->instr.bufusage : NULL), es->memory ? &mem_counters : NULL); else ExplainOneUtility(pstmt->utilityStmt, into, es, pstate, paramLI); diff --git a/src/backend/commands/vacuumparallel.c b/src/backend/commands/vacuumparallel.c index 3f64934db8640..31096808ee551 100644 --- a/src/backend/commands/vacuumparallel.c +++ b/src/backend/commands/vacuumparallel.c @@ -372,8 +372,8 @@ parallel_vacuum_init(Relation rel, Relation *indrels, int nindexes, * PARALLEL_VACUUM_KEY_BUFFER_USAGE and PARALLEL_VACUUM_KEY_WAL_USAGE. * * If there are no extensions loaded that care, we could skip this. We - * have no way of knowing whether anyone's looking at pgBufferUsage or - * pgWalUsage, so do it unconditionally. + * have no way of knowing whether anyone's looking at instrumentation, so + * do it unconditionally. */ shm_toc_estimate_chunk(&pcxt->estimator, mul_size(sizeof(BufferUsage), pcxt->nworkers)); diff --git a/src/backend/executor/execParallel.c b/src/backend/executor/execParallel.c index 1ef88a951d540..b31508037d9e9 100644 --- a/src/backend/executor/execParallel.c +++ b/src/backend/executor/execParallel.c @@ -739,7 +739,7 @@ ExecInitParallelPlan(PlanState *planstate, EState *estate, * * If EXPLAIN is not in use and there are no extensions loaded that care, * we could skip this. But we have no way of knowing whether anyone's - * looking at pgBufferUsage, so do it unconditionally. + * looking at instrumentation, so do it unconditionally. */ shm_toc_estimate_chunk(&pcxt->estimator, mul_size(sizeof(BufferUsage), pcxt->nworkers)); diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index 9b660f6f210af..e5580395e8bdc 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -24,7 +24,6 @@ #include "utils/memutils.h" #include "utils/resowner.h" -BufferUsage pgBufferUsage; WalUsage pgWalUsage; Instrumentation instr_top; InstrStackState instr_stack = { @@ -62,39 +61,21 @@ InstrStackGrow(void) } /* General purpose instrumentation handling */ -Instrumentation * -InstrAlloc(int instrument_options) +static inline bool +InstrNeedStack(int instrument_options) { - Instrumentation *instr = palloc0_object(Instrumentation); - - InstrInitOptions(instr, instrument_options); - return instr; + return (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_WAL)) != 0; } void InstrInitOptions(Instrumentation *instr, int instrument_options) { - instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0; - instr->need_walusage = (instrument_options & INSTRUMENT_WAL) != 0; + instr->need_stack = InstrNeedStack(instrument_options); instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0; } -static inline bool -InstrNeedStack(int instrument_options) -{ - return (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_WAL)) != 0; -} - -/* - * Common part of InstrStart and InstrStartNode: start the timer, and enter - * the entry onto the instrumentation stack. - * - * The diff-mode handling (see struct comment in instrument.h) lives only in - * InstrStart: node instrumentation never measures by diffing, so keeping the - * checks out of here keeps them out of the per-tuple ExecProcNodeInstr path. - */ -static inline void -InstrStartCommon(Instrumentation *instr) +inline void +InstrStart(Instrumentation *instr) { if (instr->need_timer) { @@ -108,26 +89,9 @@ InstrStartCommon(Instrumentation *instr) InstrPushStack(instr); } -inline void -InstrStart(Instrumentation *instr) -{ - InstrStartCommon(instr); - - if (!instr->need_stack) - { - /* save buffer usage totals at start, if needed */ - if (instr->need_bufusage) - instr->bufusage_start = pgBufferUsage; - - if (instr->need_walusage) - instr->walusage_start = pgWalUsage; - } -} - /* * Helper for InstrStop() and InstrStopNode(), to avoid code duplication - * despite slightly different needs about how time is accumulated. Like - * InstrStartCommon, this omits the diff-mode handling. + * despite slightly different needs about how time is accumulated. */ static inline void InstrStopCommon(Instrumentation *instr, instr_time *accum_time) @@ -155,18 +119,6 @@ void InstrStop(Instrumentation *instr) { InstrStopCommon(instr, &instr->total); - - if (!instr->need_stack) - { - /* Add delta of buffer usage since InstrStart to the totals */ - if (instr->need_bufusage) - BufferUsageAccumDiff(&instr->bufusage, - &pgBufferUsage, &instr->bufusage_start); - - if (instr->need_walusage) - WalUsageAccumDiff(&instr->walusage, - &pgWalUsage, &instr->walusage_start); - } } /* @@ -351,7 +303,6 @@ InstrQueryAlloc(int instrument_options) instr->instr_cxt = instr_cxt; InstrInitOptions(&instr->instr, instrument_options); - instr->instr.need_stack = InstrNeedStack(instrument_options); dlist_init(&instr->unfinalized_entries); return instr; @@ -451,12 +402,11 @@ InstrEndParallelQuery(QueryInstrumentation *qinstr, BufferUsage *bufusage, WalUs } /* - * Record WAL/buffer usage imported from a parallel worker. + * Record WAL usage imported from a parallel worker. */ void InstrAccumWorkerUsage(const BufferUsage *bufusage, const WalUsage *walusage) { - BufferUsageAdd(&pgBufferUsage, bufusage); WalUsageAdd(&pgWalUsage, walusage); } @@ -509,7 +459,6 @@ InstrInitNode(NodeInstrumentation *instr, int instrument_options, bool async_mod { memset(instr, 0, sizeof(NodeInstrumentation)); InstrInitOptions(&instr->instr, instrument_options); - instr->instr.need_stack = InstrNeedStack(instrument_options); instr->async_mode = async_mode; } @@ -517,7 +466,7 @@ InstrInitNode(NodeInstrumentation *instr, int instrument_options, bool async_mod inline void InstrStartNode(NodeInstrumentation *instr) { - InstrStartCommon(&instr->instr); + InstrStart(&instr->instr); } @@ -653,7 +602,6 @@ InstrAllocTrigger(QueryInstrumentation *qinstr, int instrument_options, int n) for (i = 0; i < n; i++) { InstrInitOptions(&tginstr[i].instr, instrument_options); - tginstr[i].instr.need_stack = InstrNeedStack(instrument_options); InstrQueryRememberChild(qinstr, &tginstr[i].instr); } @@ -713,36 +661,6 @@ BufferUsageAdd(BufferUsage *dst, const BufferUsage *add) INSTR_TIME_ADD(dst->temp_blk_write_time, add->temp_blk_write_time); } -/* dst += add - sub */ -inline void -BufferUsageAccumDiff(BufferUsage *dst, - const BufferUsage *add, - const BufferUsage *sub) -{ - dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit; - dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read; - dst->shared_blks_dirtied += add->shared_blks_dirtied - sub->shared_blks_dirtied; - dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written; - dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit; - dst->local_blks_read += add->local_blks_read - sub->local_blks_read; - dst->local_blks_dirtied += add->local_blks_dirtied - sub->local_blks_dirtied; - dst->local_blks_written += add->local_blks_written - sub->local_blks_written; - dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read; - dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written; - INSTR_TIME_ACCUM_DIFF(dst->shared_blk_read_time, - add->shared_blk_read_time, sub->shared_blk_read_time); - INSTR_TIME_ACCUM_DIFF(dst->shared_blk_write_time, - add->shared_blk_write_time, sub->shared_blk_write_time); - INSTR_TIME_ACCUM_DIFF(dst->local_blk_read_time, - add->local_blk_read_time, sub->local_blk_read_time); - INSTR_TIME_ACCUM_DIFF(dst->local_blk_write_time, - add->local_blk_write_time, sub->local_blk_write_time); - INSTR_TIME_ACCUM_DIFF(dst->temp_blk_read_time, - add->temp_blk_read_time, sub->temp_blk_read_time); - INSTR_TIME_ACCUM_DIFF(dst->temp_blk_write_time, - add->temp_blk_write_time, sub->temp_blk_write_time); -} - /* helper functions for WAL usage accumulation */ static inline void WalUsageAdd(WalUsage *dst, const WalUsage *add) diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c index 13327f5de8ee4..f9f36e0354b6d 100644 --- a/src/backend/storage/buffer/bufmgr.c +++ b/src/backend/storage/buffer/bufmgr.c @@ -1259,9 +1259,9 @@ PinBufferForBlock(Relation rel, if (rel) { /* - * While pgBufferUsage's "read" counter isn't bumped unless we reach - * WaitReadBuffers() (so, not for hits, and not for buffers that are - * zeroed instead), the per-relation stats always count them. + * While the current buffer usage "read" counter isn't bumped unless + * we reach WaitReadBuffers() (so, not for hits, and not for buffers + * that are zeroed instead), the per-relation stats always count them. */ pgstat_count_buffer_read(rel); } diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c index b6b1e7b0b061c..8c02cd2d40f22 100644 --- a/src/backend/utils/activity/pgstat_io.c +++ b/src/backend/utils/activity/pgstat_io.c @@ -106,9 +106,9 @@ pgstat_prepare_io_time(bool track_io_guc) * pg_stat_database only counts block read and write times, these are done for * IOOP_READ, IOOP_WRITE and IOOP_EXTEND. * - * pgBufferUsage is used for EXPLAIN. pgBufferUsage 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. + * 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. */ void pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, diff --git a/src/include/commands/explain_dr.h b/src/include/commands/explain_dr.h index ab5c53023e1e6..e3ef82c3ea4d1 100644 --- a/src/include/commands/explain_dr.h +++ b/src/include/commands/explain_dr.h @@ -27,6 +27,8 @@ typedef struct SerializeMetrics } SerializeMetrics; extern DestReceiver *CreateExplainSerializeDestReceiver(ExplainState *es); +extern void SetExplainSerializeQueryInstr(DestReceiver *dest, + QueryInstrumentation *qinstr); extern SerializeMetrics *GetSerializationMetrics(DestReceiver *dest); #endif diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index e63af41089f18..17d560fb98222 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -58,7 +58,7 @@ typedef struct WalUsage int64 wal_buffers_full; /* # of times the WAL buffers became full */ } WalUsage; -/* Flag bits included in InstrAlloc's instrument_options bitmask */ +/* Flag bits included in the instrument_options bitmask */ typedef enum InstrumentOption { INSTRUMENT_TIMER = 1 << 0, /* needs timer (and row counts) */ @@ -72,36 +72,31 @@ typedef enum InstrumentOption /* * Instrumentation base class for capturing time and WAL/buffer usage * - * If used directly (InstrAlloc, or a zero initialized struct followed by - * InstrInitOptions), WAL/buffer usage is measured by diffing the global - * pgBufferUsage/pgWalUsage counters between InstrStart and InstrStop. This - * is independent of the instrumentation stack and needs no special handling - * for transaction aborts. + * If used directly: + * - Allocate on the stack and zero initialize the struct + * - Call InstrInitOptions to set instrumentation options + * - Call InstrStart before the activity you want to measure + * - Call InstrStop / InstrStopFinalize after the activity to capture totals * - * Entries with need_stack set, as used by QueryInstrumentation and the node and - * trigger instrumentation, are instead pushed onto the instrumentation stack by - * InstrStart, so that all activity gets recorded directly in them (the diff - * flags are ignored). The last stop call must then be to InstrStopFinalize, to - * ensure parent stack entries get the accumulated totals. If there is risk of - * transaction aborts you must call InstrStopFinalize in a PG_TRY/PG_FINALLY - * block to avoid corrupting the instrumentation stack, or use - * QueryInstrumentation, which handles aborts using the resource owner logic. + * InstrStart/InstrStop may be called multiple times. The last stop call must + * be to InstrStopFinalize to ensure parent stack entries get the accumulated + * totals. If there is risk of transaction aborts you must call + * InstrStopFinalize in a PG_TRY/PG_FINALLY block to avoid corrupting the + * instrumentation stack. + * + * In a query context use QueryInstrumentation instead, which handles aborts + * using the resource owner logic. */ typedef struct Instrumentation { /* Parameters set at creation: */ bool need_timer; /* true if we need timer data */ - bool need_bufusage; /* true if we need buffer usage data */ - bool need_walusage; /* true if we need WAL usage data */ - bool need_stack; /* true if WAL/buffer usage is tracked via - * instr_stack instead */ + bool need_stack; /* true if we need WAL/buffer usage data */ /* Internal state keeping: */ bool on_stack; /* true if currently on instr_stack */ bool finalized; /* true once accumulated to a parent via * InstrFinalizeChild */ instr_time starttime; /* start time of last InstrStart */ - BufferUsage bufusage_start; /* buffer usage at start (diff mode) */ - WalUsage walusage_start; /* WAL usage at start (diff mode) */ /* Accumulated statistics: */ instr_time total; /* total runtime */ BufferUsage bufusage; /* total buffer usage */ @@ -218,11 +213,6 @@ typedef struct InstrStackState Instrumentation *current; /* top of stack, or &instr_top when empty */ } InstrStackState; -/* - * Running totals of the current backend's buffer/WAL usage, kept updated - * alongside the instrumentation stack. - */ -extern PGDLLIMPORT BufferUsage pgBufferUsage; extern PGDLLIMPORT WalUsage pgWalUsage; /* @@ -285,7 +275,6 @@ InstrPopStack(Instrumentation *instr) instr->on_stack = false; } -extern Instrumentation *InstrAlloc(int instrument_options); extern void InstrInitOptions(Instrumentation *instr, int instrument_options); extern void InstrStart(Instrumentation *instr); extern void InstrStop(Instrumentation *instr); @@ -321,25 +310,19 @@ extern TriggerInstrumentation *InstrAllocTrigger(QueryInstrumentation *qinstr, extern void InstrStartTrigger(TriggerInstrumentation *tginstr); extern void InstrStopTrigger(TriggerInstrumentation *tginstr, int64 firings); -extern void BufferUsageAccumDiff(BufferUsage *dst, - const BufferUsage *add, const BufferUsage *sub); extern void WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub); #define INSTR_BUFUSAGE_INCR(fld) do { \ - pgBufferUsage.fld++; \ instr_stack.current->bufusage.fld++; \ } while(0) #define INSTR_BUFUSAGE_ADD(fld,val) do { \ - pgBufferUsage.fld += (val); \ instr_stack.current->bufusage.fld += (val); \ } while(0) #define INSTR_BUFUSAGE_TIME_ADD(fld,val) do { \ - INSTR_TIME_ADD(pgBufferUsage.fld, val); \ INSTR_TIME_ADD(instr_stack.current->bufusage.fld, val); \ } while (0) #define INSTR_BUFUSAGE_TIME_ACCUM_DIFF(fld,endval,startval) do { \ - INSTR_TIME_ACCUM_DIFF(pgBufferUsage.fld, endval, startval); \ INSTR_TIME_ACCUM_DIFF(instr_stack.current->bufusage.fld, endval, startval); \ } while (0) From 886ab44711541812ddf66788a84e924024d7dd5c Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Sun, 5 Apr 2026 19:30:56 -0700 Subject: [PATCH 6/9] instrumentation: Specialize ExecProcNodeInstr for each set of options For most queries, the bulk of the overhead of EXPLAIN ANALYZE happens in ExecProcNodeInstr when starting/stopping instrumentation for that node. Previously each ExecProcNodeInstr would check which instrumentation options are active in the InstrStartNode/InstrStopNode calls, and do the corresponding work (timers, instrumentation stack, etc.). These conditionals being checked for each tuple being emitted add up, and cause a non-optimal set of instructions to be generated by the compiler. Because we already have a mechanism to specify a function pointer when instrumentation is enabled, we can instead create specialized functions that are tailored to the instrumentation options enabled, and avoid conditionals on subsequent ExecProcNodeInstr calls. In a stress test with a large COUNT(*) that does many ExecProcNode calls, this roughly halves the overhead of EXPLAIN (ANALYZE, TIMING OFF, BUFFERS OFF), from ~13% on top of actual runtime to ~6%. When using BUFFERS ON the same query goes from ~20% to ~15% overhead. Author: Lukas Fittl Reviewed-by: Zsolt Parragi Discussion: https://postgr.es/m/CAP53PkzdBK8VJ1fS4AZ481LgMN8f9mJiC39ZRHqkFUSYq6KWmg%40mail.gmail.com --- src/backend/executor/execProcnode.c | 2 +- src/backend/executor/instrument.c | 180 +++++++++++++++++++++------- src/include/executor/executor.h | 5 +- 3 files changed, 141 insertions(+), 46 deletions(-) diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index 5ca8d91344b87..357175ac2cbd7 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -465,7 +465,7 @@ ExecProcNodeFirst(PlanState *node) * have ExecProcNode() directly call the relevant function from now on. */ if (node->instrument) - node->ExecProcNode = ExecProcNodeInstr; + node->ExecProcNode = InstrNodeSetupExecProcNode(node->instrument); else node->ExecProcNode = node->ExecProcNodeReal; diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index e5580395e8bdc..db93562a8fc72 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -74,19 +74,27 @@ InstrInitOptions(Instrumentation *instr, int instrument_options) instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0; } -inline void -InstrStart(Instrumentation *instr) +static inline void +InstrStartTimer(Instrumentation *instr) { - if (instr->need_timer) - { - if (!INSTR_TIME_IS_ZERO(instr->starttime)) - elog(ERROR, "InstrStart called twice in a row"); - else - INSTR_TIME_SET_CURRENT_FAST(instr->starttime); - } + if (!INSTR_TIME_IS_ZERO(instr->starttime)) + elog(ERROR, "InstrStart called twice in a row"); - if (instr->need_stack) - InstrPushStack(instr); + INSTR_TIME_SET_CURRENT_FAST(instr->starttime); +} + +static inline void +InstrStopTimer(Instrumentation *instr, instr_time *accum_time) +{ + instr_time endtime; + + if (INSTR_TIME_IS_ZERO(instr->starttime)) + elog(ERROR, "InstrStop called without start"); + + INSTR_TIME_SET_CURRENT_FAST(endtime); + INSTR_TIME_ACCUM_DIFF(*accum_time, endtime, instr->starttime); + + INSTR_TIME_SET_ZERO(instr->starttime); } /* @@ -96,25 +104,25 @@ InstrStart(Instrumentation *instr) static inline void InstrStopCommon(Instrumentation *instr, instr_time *accum_time) { - instr_time endtime; - /* update the time only if the timer was requested */ if (instr->need_timer) - { - if (INSTR_TIME_IS_ZERO(instr->starttime)) - elog(ERROR, "InstrStop called without start"); - - INSTR_TIME_SET_CURRENT_FAST(endtime); - INSTR_TIME_ACCUM_DIFF(*accum_time, endtime, instr->starttime); - - INSTR_TIME_SET_ZERO(instr->starttime); - } + InstrStopTimer(instr, accum_time); /* pop the stack, unless InstrStopFinalize previously cleaned up */ if (instr->on_stack) InstrPopStack(instr); } +void +InstrStart(Instrumentation *instr) +{ + if (instr->need_timer) + InstrStartTimer(instr); + + if (instr->need_stack) + InstrPushStack(instr); +} + void InstrStop(Instrumentation *instr) { @@ -462,32 +470,30 @@ InstrInitNode(NodeInstrumentation *instr, int instrument_options, bool async_mod instr->async_mode = async_mode; } -/* Entry to a plan node */ -inline void +/* Entry to a plan node. If you modify this, check InstrNodeSetupExecProcNode. */ +void InstrStartNode(NodeInstrumentation *instr) { InstrStart(&instr->instr); } - -/* Exit from a plan node */ -inline void -InstrStopNode(NodeInstrumentation *instr, double nTuples) +/* + * Count the tuples returned by a plan node call, and remember the time it + * took to get to the first tuple of this cycle (which InstrEndLoop turns into + * the node's startup time). Must be called after the node's timer has been + * stopped for this call. + * + * Shared by InstrStopNode and the specialized ExecProcNode wrappers below, + * so that both account in exactly the same way. + */ +static inline void +InstrCountNodeTuples(NodeInstrumentation *instr, double nTuples) { double save_tuplecount = instr->tuplecount; /* count the returned tuples */ instr->tuplecount += nTuples; - /* - * Note that in contrast to InstrStop() the time is accumulated into - * NodeInstrumentation->counter, with total only getting updated in - * InstrEndLoop. We need the separate counter variable because we need to - * calculate start-up time for the first tuple in each cycle, and then - * accumulate it together. - */ - InstrStopCommon(&instr->instr, &instr->counter); - /* Is this the first tuple of this cycle? */ if (!instr->running) { @@ -505,28 +511,116 @@ InstrStopNode(NodeInstrumentation *instr, double nTuples) } } +/* Exit from a plan node */ +void +InstrStopNode(NodeInstrumentation *instr, double nTuples) +{ + /* + * Note that in contrast to InstrStop() the time is accumulated into + * NodeInstrumentation->counter, with total only getting updated in + * InstrEndLoop. We need the separate counter variable because we need to + * calculate start-up time for the first tuple in each cycle, and then + * accumulate it together. + */ + InstrStopCommon(&instr->instr, &instr->counter); + + InstrCountNodeTuples(instr, nTuples); +} + /* - * ExecProcNode wrapper that performs instrumentation calls. By keeping - * this a separate function, we avoid overhead in the normal case where + * ExecProcNode wrappers that perform instrumentation calls. By keeping + * them in separate functions, we avoid overhead in the normal case where * no instrumentation is wanted. * + * These functions are equivalent to running ExecProcNodeReal wrapped in + * InstrStartNode and InstrStopNode, but avoid the conditionals in the hot path + * by checking the instrumentation options when the ExecProcNode pointer gets + * first set, and then using a special-purpose function for each. This results + * in a more optimized set of compiled instructions. + * * This is implemented in instrument.c as all the functions it calls directly * are here, allowing them to be inlined even when not using LTO. */ -TupleTableSlot * -ExecProcNodeInstr(PlanState *node) + +/* Simplified pop: restore saved state instead of re-deriving from array */ +static inline void +InstrPopStackTo(Instrumentation *prev) +{ + Assert(instr_stack.stack_size > 0); + Assert(instr_stack.stack_size > 1 ? instr_stack.entries[instr_stack.stack_size - 2] == prev : &instr_top == prev); + instr_stack.entries[instr_stack.stack_size - 1]->on_stack = false; + instr_stack.stack_size--; + instr_stack.current = prev; +} + +static pg_always_inline TupleTableSlot * +ExecProcNodeInstr(PlanState *node, bool need_timer, bool need_stack) { + NodeInstrumentation *instr = node->instrument; + Instrumentation *prev = instr_stack.current; TupleTableSlot *result; - InstrStartNode(node->instrument); + if (need_stack) + InstrPushStack(&instr->instr); + if (need_timer) + InstrStartTimer(&instr->instr); result = node->ExecProcNodeReal(node); - InstrStopNode(node->instrument, TupIsNull(result) ? 0.0 : 1.0); + if (need_timer) + InstrStopTimer(&instr->instr, &instr->counter); + if (need_stack) + InstrPopStackTo(prev); + + InstrCountNodeTuples(instr, TupIsNull(result) ? 0.0 : 1.0); return result; } +static TupleTableSlot * +ExecProcNodeInstrFull(PlanState *node) +{ + return ExecProcNodeInstr(node, true, true); +} + +static TupleTableSlot * +ExecProcNodeInstrRowsStackOnly(PlanState *node) +{ + return ExecProcNodeInstr(node, false, true); +} + +static TupleTableSlot * +ExecProcNodeInstrRowsTimerOnly(PlanState *node) +{ + return ExecProcNodeInstr(node, true, false); +} + +static TupleTableSlot * +ExecProcNodeInstrRowsOnly(PlanState *node) +{ + return ExecProcNodeInstr(node, false, false); +} + +/* + * Returns an ExecProcNode wrapper that performs instrumentation calls, + * tailored to the instrumentation options enabled for the node. + */ +ExecProcNodeMtd +InstrNodeSetupExecProcNode(NodeInstrumentation *instr) +{ + bool need_timer = instr->instr.need_timer; + bool need_stack = instr->instr.need_stack; + + if (need_timer && need_stack) + return ExecProcNodeInstrFull; + else if (need_stack) + return ExecProcNodeInstrRowsStackOnly; + else if (need_timer) + return ExecProcNodeInstrRowsTimerOnly; + else + return ExecProcNodeInstrRowsOnly; +} + /* Update tuple count */ void InstrUpdateTupleCount(NodeInstrumentation *instr, double nTuples) diff --git a/src/include/executor/executor.h b/src/include/executor/executor.h index e34dd2c805412..f6fad6a6e6851 100644 --- a/src/include/executor/executor.h +++ b/src/include/executor/executor.h @@ -308,11 +308,12 @@ extern void ExecFinalizeWorkerInstrumentation(PlanState *node); extern void ExecSetTupleBound(int64 tuples_needed, PlanState *child_node); /* - * ExecProcNodeInstr() is implemented in instrument.c, as that allows for + * InstrNodeSetupExecProcNode() is implemented in instrument.c, as that allows for * inlining of the instrumentation functions, but thematically it ought to be * in execProcnode.c. */ -extern TupleTableSlot *ExecProcNodeInstr(PlanState *node); + +extern ExecProcNodeMtd InstrNodeSetupExecProcNode(NodeInstrumentation *instr); /* ---------------------------------------------------------------- From 8cb0f58254f789c78ef271a47b4e76322ff49e78 Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Fri, 2 Oct 2026 21:27:08 -0700 Subject: [PATCH 7/9] Index scans: Show table buffer accesses separately in EXPLAIN ANALYZE This sets up a separate instrumentation stack that is used while an Index Scan fetches heap tuples, or an Index Only Scan checks the visibility map and fetches heap tuples for pages that are are not all-visible. EXPLAIN ANALYZE will now show "Table Buffers" that represent such activity. The activity is also included in regular "Buffers" together with index activity and that of any child nodes. Author: Lukas Fittl Suggested-by: Andres Freund (in an earlier version) Reviewed-by: Zsolt Parragi (in an earlier version) Reviewed-by: Tomas Vondra (in an earlier version) Discussion: https://postgr.es/m/CAP53PkzdBK8VJ1fS4AZ481LgMN8f9mJiC39ZRHqkFUSYq6KWmg%40mail.gmail.com --- doc/src/sgml/perform.sgml | 13 +- doc/src/sgml/ref/explain.sgml | 1 + src/backend/access/heap/heapam_indexscan.c | 29 +++++ src/backend/commands/explain.c | 47 ++++++-- src/backend/executor/execProcnode.c | 46 +++++++ src/backend/executor/nodeBitmapIndexscan.c | 2 +- src/backend/executor/nodeIndexonlyscan.c | 55 ++++++++- src/backend/executor/nodeIndexscan.c | 55 ++++++++- src/include/executor/instrument_node.h | 6 + src/test/regress/expected/explain.out | 132 +++++++++++++++++++++ src/test/regress/sql/explain.sql | 75 ++++++++++++ 11 files changed, 441 insertions(+), 20 deletions(-) diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml index ea8da01b7797f..8087dd604036a 100644 --- a/doc/src/sgml/perform.sgml +++ b/doc/src/sgml/perform.sgml @@ -735,6 +735,7 @@ WHERE t1.unique1 < 10 AND t1.unique2 = t2.unique2; -> Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..7.90 rows=1 width=244) (actual time=0.003..0.003 rows=1.00 loops=10) Index Cond: (unique2 = t1.unique2) Index Searches: 10 + Table Buffers: shared hit=10 Buffers: shared hit=24 read=6 Planning: Buffers: shared hit=15 dirtied=9 @@ -1006,7 +1007,8 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @> polygon '(0.5,2.0)'; Index Cond: (f1 @> '((0.5,2))'::polygon) Rows Removed by Index Recheck: 1 Index Searches: 1 - Buffers: shared hit=1 + Table Buffers: shared hit=1 + Buffers: shared hit=2 Planning Time: 0.039 ms Execution Time: 0.098 ms @@ -1015,7 +1017,9 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @> polygon '(0.5,2.0)'; then rejected by a recheck of the index condition. This happens because a GiST index is lossy for polygon containment tests: it actually returns the rows with polygons that overlap the target, and then we have - to do the exact containment test on those rows. + to do the exact containment test on those rows. The Table Buffers + counts indicate how many operations were performed on the table instead of + the index. This number is included in the Buffers counts. @@ -1204,13 +1208,14 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE unique1 < 100 AND unique2 > 9000 QUERY PLAN -------------------------------------------------------------------&zwsp;------------------------------------------------------------ Limit (cost=0.29..14.33 rows=2 width=244) (actual time=0.051..0.071 rows=2.00 loops=1) - Buffers: shared hit=16 + Buffers: shared hit=14 -> Index Scan using tenk1_unique2 on tenk1 (cost=0.29..70.50 rows=10 width=244) (actual time=0.051..0.070 rows=2.00 loops=1) Index Cond: (unique2 > 9000) Filter: (unique1 < 100) Rows Removed by Filter: 287 Index Searches: 1 - Buffers: shared hit=16 + Table Buffers: shared hit=11 + Buffers: shared hit=14 Planning Time: 0.077 ms Execution Time: 0.086 ms diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index f38d31e106a39..2c300792238cd 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -528,6 +528,7 @@ EXPLAIN ANALYZE EXECUTE query(100, 200); -> Index Scan using test_pkey on test (cost=0.29..10.27 rows=99 width=8) (actual time=0.009..0.025 rows=99.00 loops=1) Index Cond: ((id > 100) AND (id < 200)) Index Searches: 1 + Table Buffers: shared hit=1 Buffers: shared hit=4 Planning Time: 0.244 ms Execution Time: 0.073 ms diff --git a/src/backend/access/heap/heapam_indexscan.c b/src/backend/access/heap/heapam_indexscan.c index 49981525c67e0..179e70f8d10c6 100644 --- a/src/backend/access/heap/heapam_indexscan.c +++ b/src/backend/access/heap/heapam_indexscan.c @@ -19,6 +19,7 @@ #include "access/relscan.h" #include "access/tableam_indexscan.h" #include "access/visibilitymap.h" +#include "executor/instrument.h" #include "pgstat.h" #include "storage/predicate.h" @@ -330,6 +331,7 @@ heapam_index_getnext_slot(IndexScanDesc scan, ScanDirection direction, { IndexScanHeapData *hscan; bool all_visible; + Instrumentation *table_instr = NULL; /* * Get the next TID from the index, unless we're still working through @@ -356,6 +358,16 @@ heapam_index_getnext_slot(IndexScanDesc scan, ScanDirection direction, } else { + /* + * If requested, account buffer/WAL activity on the table's + * visility map separately from the index. + */ + if (scan->instrument && scan->instrument->table_instr.need_stack) + { + table_instr = &scan->instrument->table_instr; + InstrPushStack(table_instr); + } + /* * Note: VM_ALL_VISIBLE does not lock the visibility map buffer, * so the result could be slightly stale. See the comments above @@ -365,6 +377,9 @@ heapam_index_getnext_slot(IndexScanDesc scan, ScanDirection direction, ItemPointerGetBlockNumber(&scan->xs_heaptid), &hscan->xs_vmbuffer); + if (table_instr) + InstrPopStack(table_instr); + if (unlikely(!all_visible)) { /* Page isn't all-visible, so need a heap fetch */ @@ -434,6 +449,7 @@ heapam_index_heap_fetch(IndexScanDesc scan, IndexScanHeapData *hscan, HeapTuple heapTuple; bool got_heap_tuple; bool all_dead; + Instrumentation *table_instr = NULL; if (!index_only) { @@ -453,6 +469,16 @@ heapam_index_heap_fetch(IndexScanDesc scan, IndexScanHeapData *hscan, scan->instrument->ntabletuplefetches++; } + /* + * If requested, account buffer/WAL activity on the table separately from + * that on the index, so EXPLAIN (ANALYZE, BUFFERS) can show them apart. + */ + if (scan->instrument && scan->instrument->table_instr.need_stack) + { + table_instr = &scan->instrument->table_instr; + InstrPushStack(table_instr); + } + /* We can skip the buffer-switching logic if we're on the same page. */ if (hscan->xs_blk != ItemPointerGetBlockNumber(tid)) { @@ -528,6 +554,9 @@ heapam_index_heap_fetch(IndexScanDesc scan, IndexScanHeapData *hscan, heapam_index_kill_item(scan); } + if (table_instr) + InstrPopStack(table_instr); + return got_heap_tuple; } diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 97d56f2bd939e..80031a2d4cff0 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -147,7 +147,7 @@ static void show_instrumentation_count(const char *qlabel, int which, static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es); static const char *explain_get_index_name(Oid indexId); static bool peek_buffer_usage(ExplainState *es, const BufferUsage *usage); -static void show_buffer_usage(ExplainState *es, const BufferUsage *usage); +static void show_buffer_usage(ExplainState *es, const BufferUsage *usage, const char *title); static void show_wal_usage(ExplainState *es, const WalUsage *usage); static void show_memory_counters(ExplainState *es, const MemoryContextCounters *mem_counters); @@ -625,7 +625,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, } if (bufusage) - show_buffer_usage(es, bufusage); + show_buffer_usage(es, bufusage, NULL); if (mem_counters) show_memory_counters(es, mem_counters); @@ -1042,7 +1042,7 @@ ExplainPrintSerialize(ExplainState *es, SerializeMetrics *metrics) if (es->buffers && peek_buffer_usage(es, &metrics->instr.bufusage)) { es->indent++; - show_buffer_usage(es, &metrics->instr.bufusage); + show_buffer_usage(es, &metrics->instr.bufusage, NULL); es->indent--; } } @@ -1056,7 +1056,7 @@ ExplainPrintSerialize(ExplainState *es, SerializeMetrics *metrics) BYTES_TO_KILOBYTES(metrics->bytesSent), es); ExplainPropertyText("Format", format, es); if (es->buffers) - show_buffer_usage(es, &metrics->instr.bufusage); + show_buffer_usage(es, &metrics->instr.bufusage, NULL); } ExplainCloseGroup("Serialization", "Serialization", true, es); @@ -1986,6 +1986,9 @@ ExplainNode(PlanState *planstate, List *ancestors, show_instrumentation_count("Rows Removed by Filter", 1, planstate, es); show_indexscan_info(planstate, es); + + if (es->buffers && planstate->instrument) + show_buffer_usage(es, &((IndexScanState *) planstate)->iss_Instrument->table_instr.bufusage, "Table"); break; case T_IndexOnlyScan: show_scan_qual(((IndexOnlyScan *) plan)->indexqual, @@ -2000,6 +2003,9 @@ ExplainNode(PlanState *planstate, List *ancestors, show_instrumentation_count("Rows Removed by Filter", 1, planstate, es); show_indexscan_info(planstate, es); + + if (es->buffers && planstate->instrument) + show_buffer_usage(es, &((IndexOnlyScanState *) planstate)->ioss_Instrument->table_instr.bufusage, "Table"); break; case T_BitmapIndexScan: show_scan_qual(((BitmapIndexScan *) plan)->indexqualorig, @@ -2304,7 +2310,7 @@ ExplainNode(PlanState *planstate, List *ancestors, /* Show buffer/WAL usage */ if (es->buffers && planstate->instrument) - show_buffer_usage(es, &planstate->instrument->instr.bufusage); + show_buffer_usage(es, &planstate->instrument->instr.bufusage, NULL); if (es->wal && planstate->instrument) show_wal_usage(es, &planstate->instrument->instr.walusage); @@ -2323,7 +2329,7 @@ ExplainNode(PlanState *planstate, List *ancestors, ExplainOpenWorker(n, es); if (es->buffers) - show_buffer_usage(es, &instrument->instr.bufusage); + show_buffer_usage(es, &instrument->instr.bufusage, NULL); if (es->wal) show_wal_usage(es, &instrument->instr.walusage); ExplainCloseWorker(n, es); @@ -4331,7 +4337,7 @@ peek_buffer_usage(ExplainState *es, const BufferUsage *usage) * Show buffer usage details. This better be sync with peek_buffer_usage. */ static void -show_buffer_usage(ExplainState *es, const BufferUsage *usage) +show_buffer_usage(ExplainState *es, const BufferUsage *usage, const char *title) { if (es->format == EXPLAIN_FORMAT_TEXT) { @@ -4356,6 +4362,8 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) if (has_shared || has_local || has_temp) { ExplainIndentText(es); + if (title) + appendStringInfo(es->str, "%s ", title); appendStringInfoString(es->str, "Buffers:"); if (has_shared) @@ -4411,6 +4419,8 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) if (has_shared_timing || has_local_timing || has_temp_timing) { ExplainIndentText(es); + if (title) + appendStringInfo(es->str, "%s ", title); appendStringInfoString(es->str, "I/O Timings:"); if (has_shared_timing) @@ -4452,6 +4462,14 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) } else { + char *buffers_title = NULL; + + if (title) + { + buffers_title = psprintf("%s Buffers", title); + ExplainOpenGroup(buffers_title, buffers_title, true, es); + } + ExplainPropertyInteger("Shared Hit Blocks", NULL, usage->shared_blks_hit, es); ExplainPropertyInteger("Shared Read Blocks", NULL, @@ -4472,8 +4490,20 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) usage->temp_blks_read, es); ExplainPropertyInteger("Temp Written Blocks", NULL, usage->temp_blks_written, es); + + if (buffers_title) + ExplainCloseGroup(buffers_title, buffers_title, true, es); + if (track_io_timing) { + char *timings_title = NULL; + + if (title) + { + timings_title = psprintf("%s I/O Timings", title); + ExplainOpenGroup(timings_title, timings_title, true, es); + } + ExplainPropertyFloat("Shared I/O Read Time", "ms", INSTR_TIME_GET_MILLISEC(usage->shared_blk_read_time), 3, es); @@ -4492,6 +4522,9 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) ExplainPropertyFloat("Temp I/O Write Time", "ms", INSTR_TIME_GET_MILLISEC(usage->temp_blk_write_time), 3, es); + + if (timings_title) + ExplainCloseGroup(timings_title, timings_title, true, es); } } } diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index 357175ac2cbd7..57a78325f47d8 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -847,6 +847,20 @@ ExecFinalizeNodeInstrumentation_walker(PlanState *node, void *context) planstate_tree_walker(node, ExecFinalizeNodeInstrumentation_walker, &node->instrument->instr); + /* IndexScan/IndexOnlyScan have a separate entry to track table access */ + if (IsA(node, IndexScanState)) + { + IndexScanState *iss = castNode(IndexScanState, node); + + InstrFinalizeChild(&iss->iss_Instrument->table_instr, &node->instrument->instr); + } + else if (IsA(node, IndexOnlyScanState)) + { + IndexOnlyScanState *ioss = castNode(IndexOnlyScanState, node); + + InstrFinalizeChild(&ioss->ioss_Instrument->table_instr, &node->instrument->instr); + } + InstrFinalizeChild(&node->instrument->instr, parent); return false; @@ -892,6 +906,38 @@ ExecFinalizeWorkerInstrumentation_walker(PlanState *node, void *context) num_workers = node->worker_instrument->num_workers; + /* + * Fold per-worker IndexScan/IndexOnlyScan table buffer stats into the + * per-worker node stats, matching what ExecFinalizeNodeInstrumentation + * does for the leader. + */ + if (IsA(node, IndexScanState)) + { + IndexScanState *iss = castNode(IndexScanState, node); + + if (iss->iss_SharedInfo) + { + int nworkers = Min(num_workers, iss->iss_SharedInfo->num_workers); + + for (int n = 0; n < nworkers; n++) + InstrAccumStack(&node->worker_instrument->instrument[n].instr, + &iss->iss_SharedInfo->winstrument[n].table_instr); + } + } + else if (IsA(node, IndexOnlyScanState)) + { + IndexOnlyScanState *ioss = castNode(IndexOnlyScanState, node); + + if (ioss->ioss_SharedInfo) + { + int nworkers = Min(num_workers, ioss->ioss_SharedInfo->num_workers); + + for (int n = 0; n < nworkers; n++) + InstrAccumStack(&node->worker_instrument->instrument[n].instr, + &ioss->ioss_SharedInfo->winstrument[n].table_instr); + } + } + /* Accumulate this node's per-worker stats to parent's per-worker stats */ if (parent && parent->worker_instrument) { diff --git a/src/backend/executor/nodeBitmapIndexscan.c b/src/backend/executor/nodeBitmapIndexscan.c index 90b010f9b7169..c190a03f47c07 100644 --- a/src/backend/executor/nodeBitmapIndexscan.c +++ b/src/backend/executor/nodeBitmapIndexscan.c @@ -277,7 +277,7 @@ ExecInitBitmapIndexScan(BitmapIndexScan *node, EState *estate, int eflags) /* Set up instrumentation of bitmap index scans if requested */ if (estate->es_instrument) - indexstate->biss_Instrument = palloc0_object(IndexScanInstrumentation); + indexstate->biss_Instrument = MemoryContextAllocZero(estate->es_query_instr->instr_cxt, sizeof(IndexScanInstrumentation)); /* Open the index relation. */ lockmode = exec_rt_fetch(node->scan.scanrelid, estate)->rellockmode; diff --git a/src/backend/executor/nodeIndexonlyscan.c b/src/backend/executor/nodeIndexonlyscan.c index b1009027ac881..b57924be7817c 100644 --- a/src/backend/executor/nodeIndexonlyscan.c +++ b/src/backend/executor/nodeIndexonlyscan.c @@ -262,6 +262,7 @@ ExecEndIndexOnlyScan(IndexOnlyScanState *node) */ winstrument->nsearches += node->ioss_Instrument->nsearches; winstrument->ntabletuplefetches += node->ioss_Instrument->ntabletuplefetches; + InstrAccumStack(&winstrument->table_instr, &node->ioss_Instrument->table_instr); } /* @@ -416,6 +417,29 @@ ExecInitIndexOnlyScan(IndexOnlyScan *node, EState *estate, int eflags) indexstate->recheckqual = ExecInitQual(node->recheckqual, (PlanState *) indexstate); + /* + * Set up instrumentation of index-only scans if requested. Like the + * node's own instrumentation (see ExecInitNode), this must exist even + * when we are only doing EXPLAIN, since EXPLAIN (BUFFERS) reads it + * regardless of whether the plan was run. + */ + if (estate->es_instrument) + { + indexstate->ioss_Instrument = MemoryContextAllocZero(estate->es_query_instr->instr_cxt, sizeof(IndexScanInstrumentation)); + + /* + * Track table and index access separately. We intentionally don't + * collect timing (even if enabled), since we don't need it, and the + * table AM calls InstrPushStack / InstrPopStack around its table + * fetches (instead of the full InstrNode*) to reduce overhead. + */ + if ((estate->es_instrument & INSTRUMENT_BUFFERS) != 0) + { + InstrInitOptions(&indexstate->ioss_Instrument->table_instr, INSTRUMENT_BUFFERS); + InstrQueryRememberChild(estate->es_query_instr, &indexstate->ioss_Instrument->table_instr); + } + } + /* * If we are just doing EXPLAIN (ie, aren't going to run the plan), stop * here. This allows an index-advisor plugin to EXPLAIN a plan containing @@ -424,10 +448,6 @@ ExecInitIndexOnlyScan(IndexOnlyScan *node, EState *estate, int eflags) if (eflags & EXEC_FLAG_EXPLAIN_ONLY) return indexstate; - /* Set up instrumentation of index-only scans if requested */ - if (estate->es_instrument) - indexstate->ioss_Instrument = palloc0_object(IndexScanInstrumentation); - /* Open the index relation. */ lockmode = exec_rt_fetch(node->scan.scanrelid, estate)->rellockmode; indexRelation = index_open(node->indexid, lockmode); @@ -655,6 +675,19 @@ ExecIndexOnlyScanInstrumentInitDSM(IndexOnlyScanState *node, /* Each per-worker area must start out as zeroes */ memset(node->ioss_SharedInfo, 0, size); node->ioss_SharedInfo->num_workers = pcxt->nworkers; + + /* + * Initialize each worker's table_instr with the same options as the + * leader's own entry (see ExecInitIndexOnlyScan), so that accumulating + * from it works once the worker has added its stats. + */ + if ((node->ss.ps.state->es_instrument & INSTRUMENT_BUFFERS) != 0) + { + for (int i = 0; i < pcxt->nworkers; i++) + InstrInitOptions(&node->ioss_SharedInfo->winstrument[i].table_instr, + INSTRUMENT_BUFFERS); + } + shm_toc_insert(pcxt->toc, node->ss.ps.plan->plan_node_id + PARALLEL_KEY_SCAN_INSTRUMENT_OFFSET, @@ -698,4 +731,18 @@ ExecIndexOnlyScanRetrieveInstrumentation(IndexOnlyScanState *node) SharedInfo->num_workers * sizeof(IndexScanInstrumentation); node->ioss_SharedInfo = palloc(size); memcpy(node->ioss_SharedInfo, SharedInfo, size); + + /* + * Aggregate workers' table buffer/WAL usage into leader's entry, which + * ExecFinalizeNodeInstrumentation later rolls up into the node. Record + * the import so that session-level consumers can exclude it (see + * InstrAccumWorkerUsage). + */ + for (int i = 0; i < node->ioss_SharedInfo->num_workers; i++) + { + Instrumentation *winstr = &node->ioss_SharedInfo->winstrument[i].table_instr; + + InstrAccumStack(&node->ioss_Instrument->table_instr, winstr); + InstrAccumWorkerUsage(&winstr->bufusage, &winstr->walusage); + } } diff --git a/src/backend/executor/nodeIndexscan.c b/src/backend/executor/nodeIndexscan.c index 129d005f187dd..2266befe1bc49 100644 --- a/src/backend/executor/nodeIndexscan.c +++ b/src/backend/executor/nodeIndexscan.c @@ -821,6 +821,7 @@ ExecEndIndexScan(IndexScanState *node) */ winstrument->nsearches += node->iss_Instrument->nsearches; Assert(node->iss_Instrument->ntabletuplefetches == 0); + InstrAccumStack(&winstrument->table_instr, &node->iss_Instrument->table_instr); } /* @@ -973,6 +974,29 @@ ExecInitIndexScan(IndexScan *node, EState *estate, int eflags) indexstate->indexorderbyorig = ExecInitExprList(node->indexorderbyorig, (PlanState *) indexstate); + /* + * Set up instrumentation of index scans if requested. Like the node's + * own instrumentation (see ExecInitNode), this must exist even when we + * are only doing EXPLAIN, since EXPLAIN (BUFFERS) reads it regardless of + * whether the plan was run. + */ + if (estate->es_instrument) + { + indexstate->iss_Instrument = MemoryContextAllocZero(estate->es_query_instr->instr_cxt, sizeof(IndexScanInstrumentation)); + + /* + * Track table and index access separately. We intentionally don't + * collect timing (even if enabled), since we don't need it, and the + * table AM calls InstrPushStack / InstrPopStack around its table + * fetches (instead of the full InstrNode*) to reduce overhead. + */ + if ((estate->es_instrument & INSTRUMENT_BUFFERS) != 0) + { + InstrInitOptions(&indexstate->iss_Instrument->table_instr, INSTRUMENT_BUFFERS); + InstrQueryRememberChild(estate->es_query_instr, &indexstate->iss_Instrument->table_instr); + } + } + /* * If we are just doing EXPLAIN (ie, aren't going to run the plan), stop * here. This allows an index-advisor plugin to EXPLAIN a plan containing @@ -981,10 +1005,6 @@ ExecInitIndexScan(IndexScan *node, EState *estate, int eflags) if (eflags & EXEC_FLAG_EXPLAIN_ONLY) return indexstate; - /* Set up instrumentation of index scans if requested */ - if (estate->es_instrument) - indexstate->iss_Instrument = palloc0_object(IndexScanInstrumentation); - /* Open the index relation. */ lockmode = exec_rt_fetch(node->scan.scanrelid, estate)->rellockmode; indexstate->iss_RelationDesc = index_open(node->indexid, lockmode); @@ -1810,6 +1830,19 @@ ExecIndexScanInstrumentInitDSM(IndexScanState *node, /* Each per-worker area must start out as zeroes */ memset(node->iss_SharedInfo, 0, size); node->iss_SharedInfo->num_workers = pcxt->nworkers; + + /* + * Initialize each worker's table_instr with the same options as the + * leader's own entry (see ExecInitIndexScan), so that accumulating from + * it works once the worker has added its stats. + */ + if ((node->ss.ps.state->es_instrument & INSTRUMENT_BUFFERS) != 0) + { + for (int i = 0; i < pcxt->nworkers; i++) + InstrInitOptions(&node->iss_SharedInfo->winstrument[i].table_instr, + INSTRUMENT_BUFFERS); + } + shm_toc_insert(pcxt->toc, node->ss.ps.plan->plan_node_id + PARALLEL_KEY_SCAN_INSTRUMENT_OFFSET, @@ -1853,4 +1886,18 @@ ExecIndexScanRetrieveInstrumentation(IndexScanState *node) SharedInfo->num_workers * sizeof(IndexScanInstrumentation); node->iss_SharedInfo = palloc(size); memcpy(node->iss_SharedInfo, SharedInfo, size); + + /* + * Aggregate workers' table buffer/WAL usage into leader's entry, which + * ExecFinalizeNodeInstrumentation later rolls up into the node. Record + * the import so that session-level consumers can exclude it (see + * InstrAccumWorkerUsage). + */ + for (int i = 0; i < node->iss_SharedInfo->num_workers; i++) + { + Instrumentation *winstr = &node->iss_SharedInfo->winstrument[i].table_instr; + + InstrAccumStack(&node->iss_Instrument->table_instr, winstr); + InstrAccumWorkerUsage(&winstr->bufusage, &winstr->walusage); + } } diff --git a/src/include/executor/instrument_node.h b/src/include/executor/instrument_node.h index 4759a628afea3..b9ddf8966f9c2 100644 --- a/src/include/executor/instrument_node.h +++ b/src/include/executor/instrument_node.h @@ -18,6 +18,8 @@ #ifndef INSTRUMENT_NODE_H #define INSTRUMENT_NODE_H +#include "executor/instrument.h" + /* * Offset added to plan_node_id to create a second TOC key for per-worker scan * instrumentation. Instrumentation and parallel-awareness are independent, so @@ -27,6 +29,7 @@ */ #define PARALLEL_KEY_SCAN_INSTRUMENT_OFFSET UINT64CONST(0xD000000000000000) + /* --------------------- * Instrumentation information for aggregate function execution * --------------------- @@ -108,6 +111,9 @@ typedef struct IndexScanInstrumentation /* Table tuples fetched count (incremented during index-only scans) */ uint64 ntabletuplefetches; + + /* Instrumentation utilized for tracking buffer usage during table access */ + Instrumentation table_instr; } IndexScanInstrumentation; /* diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out index f464baea4c8e5..3bceef6af9050 100644 --- a/src/test/regress/expected/explain.out +++ b/src/test/regress/expected/explain.out @@ -261,6 +261,69 @@ explain_filter ] (1 row) \a +-- Index scans track table buffer accesses separately; make sure EXPLAIN +-- (BUFFERS) copes without ANALYZE, i.e. when the plan was never run +select explain_filter('explain (buffers, costs off) select * from tenk1 where unique1 = 42'); + explain_filter +----------------------------------------- + Index Scan using tenk1_unique1 on tenk1 + Index Cond: (unique1 = N) +(2 rows) + +\a +select explain_filter('explain (buffers, costs off, format json) select * from tenk1 where unique1 = 42'); +explain_filter +[ + { + "Plan": { + "Node Type": "Index Scan", + "Parallel Aware": false, + "Async Capable": false, + "Scan Direction": "Forward", + "Index Name": "tenk1_unique1", + "Relation Name": "tenk1", + "Alias": "tenk1", + "Disabled": false, + "Index Cond": "(unique1 = N)", + "Table Buffers": { + "Shared Hit Blocks": N, + "Shared Read Blocks": N, + "Shared Dirtied Blocks": N, + "Shared Written Blocks": N, + "Local Hit Blocks": N, + "Local Read Blocks": N, + "Local Dirtied Blocks": N, + "Local Written Blocks": N, + "Temp Read Blocks": N, + "Temp Written Blocks": N + }, + "Shared Hit Blocks": N, + "Shared Read Blocks": N, + "Shared Dirtied Blocks": N, + "Shared Written Blocks": N, + "Local Hit Blocks": N, + "Local Read Blocks": N, + "Local Dirtied Blocks": N, + "Local Written Blocks": N, + "Temp Read Blocks": N, + "Temp Written Blocks": N + }, + "Planning": { + "Shared Hit Blocks": N, + "Shared Read Blocks": N, + "Shared Dirtied Blocks": N, + "Shared Written Blocks": N, + "Local Hit Blocks": N, + "Local Read Blocks": N, + "Local Dirtied Blocks": N, + "Local Written Blocks": N, + "Temp Read Blocks": N, + "Temp Written Blocks": N + } + } +] +(1 row) +\a -- Check expansion of window definitions select explain_filter('explain verbose select sum(unique1) over w, sum(unique2) over (w order by hundred), sum(tenthous) over (w order by hundred) from tenk1 window w as (partition by ten)'); explain_filter @@ -1020,3 +1083,72 @@ DROP TRIGGER trig_test_trig ON trig_test_tab; DROP FUNCTION trig_test_func; DROP TABLE trig_test_tab; DROP TABLE trig_work_tab; +-- Parallel index scan buffer usage. +-- Table accesses of an index scan are tracked separately from the index +-- accesses, and parallel workers report them to the leader separately as +-- well. Verify that the total shown for the scan node matches between a +-- serial and a parallel execution where only workers do the scanning. +CREATE TABLE par_idx_buf_test AS SELECT * FROM tenk1; +CREATE INDEX ON par_idx_buf_test (unique1); +VACUUM ANALYZE par_idx_buf_test; +CREATE FUNCTION check_parallel_indexscan_buffers() RETURNS boolean AS $$ +DECLARE + plan_json json; + node json; + serial_buf int; + parallel_buf int; +BEGIN + -- Serial index scan: get the leaf scan node buffers as baseline + SET LOCAL max_parallel_workers_per_gather = 0; + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT count(stringu1) FROM par_idx_buf_test WHERE unique1 >= 0' INTO plan_json; + node := plan_json->0->'Plan'; + WHILE node->'Plans' IS NOT NULL LOOP + node := node->'Plans'->0; + END LOOP; + IF node->>'Node Type' <> 'Index Scan' THEN + RAISE EXCEPTION 'expected Index Scan, got %', node->>'Node Type'; + END IF; + serial_buf := + COALESCE((node->>'Shared Hit Blocks')::int, 0) + + COALESCE((node->>'Shared Read Blocks')::int, 0); + + -- Parallel index scan with only workers scanning + SET LOCAL parallel_setup_cost = 0; + SET LOCAL parallel_tuple_cost = 0; + SET LOCAL min_parallel_index_scan_size = 0; + SET LOCAL min_parallel_table_scan_size = 0; + SET LOCAL max_parallel_workers_per_gather = 2; + SET LOCAL parallel_leader_participation = off; + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT count(stringu1) FROM par_idx_buf_test WHERE unique1 >= 0' INTO plan_json; + node := plan_json->0->'Plan'; + WHILE node->'Plans' IS NOT NULL LOOP + node := node->'Plans'->0; + END LOOP; + IF node->>'Node Type' <> 'Index Scan' OR NOT (node->>'Parallel Aware')::bool THEN + RAISE EXCEPTION 'expected Parallel Index Scan, got %', node->>'Node Type'; + END IF; + parallel_buf := + COALESCE((node->>'Shared Hit Blocks')::int, 0) + + COALESCE((node->>'Shared Read Blocks')::int, 0); + + -- Workers may each fetch some heap pages the other also fetched, so + -- allow for a little slack, but the totals must be in the same ballpark. + RETURN parallel_buf >= serial_buf * 0.9 AND parallel_buf <= serial_buf * 1.5; +END; +$$ LANGUAGE plpgsql; +SET enable_seqscan = off; +SET enable_bitmapscan = off; +SET enable_indexonlyscan = off; +SELECT check_parallel_indexscan_buffers() AS parallel_indexscan_buffers_match; + parallel_indexscan_buffers_match +---------------------------------- + t +(1 row) + +RESET enable_seqscan; +RESET enable_bitmapscan; +RESET enable_indexonlyscan; +DROP FUNCTION check_parallel_indexscan_buffers; +DROP TABLE par_idx_buf_test; diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql index 101914b6d5b47..4a9c8a24d4e3b 100644 --- a/src/test/regress/sql/explain.sql +++ b/src/test/regress/sql/explain.sql @@ -74,6 +74,13 @@ select explain_filter('explain (analyze, serialize, buffers, io, format yaml) se select explain_filter('explain (buffers, format json) select * from int8_tbl i8'); \a +-- Index scans track table buffer accesses separately; make sure EXPLAIN +-- (BUFFERS) copes without ANALYZE, i.e. when the plan was never run +select explain_filter('explain (buffers, costs off) select * from tenk1 where unique1 = 42'); +\a +select explain_filter('explain (buffers, costs off, format json) select * from tenk1 where unique1 = 42'); +\a + -- Check expansion of window definitions select explain_filter('explain verbose select sum(unique1) over w, sum(unique2) over (w order by hundred), sum(tenthous) over (w order by hundred) from tenk1 window w as (partition by ten)'); @@ -379,3 +386,71 @@ DROP TRIGGER trig_test_trig ON trig_test_tab; DROP FUNCTION trig_test_func; DROP TABLE trig_test_tab; DROP TABLE trig_work_tab; + +-- Parallel index scan buffer usage. +-- Table accesses of an index scan are tracked separately from the index +-- accesses, and parallel workers report them to the leader separately as +-- well. Verify that the total shown for the scan node matches between a +-- serial and a parallel execution where only workers do the scanning. +CREATE TABLE par_idx_buf_test AS SELECT * FROM tenk1; +CREATE INDEX ON par_idx_buf_test (unique1); +VACUUM ANALYZE par_idx_buf_test; + +CREATE FUNCTION check_parallel_indexscan_buffers() RETURNS boolean AS $$ +DECLARE + plan_json json; + node json; + serial_buf int; + parallel_buf int; +BEGIN + -- Serial index scan: get the leaf scan node buffers as baseline + SET LOCAL max_parallel_workers_per_gather = 0; + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT count(stringu1) FROM par_idx_buf_test WHERE unique1 >= 0' INTO plan_json; + node := plan_json->0->'Plan'; + WHILE node->'Plans' IS NOT NULL LOOP + node := node->'Plans'->0; + END LOOP; + IF node->>'Node Type' <> 'Index Scan' THEN + RAISE EXCEPTION 'expected Index Scan, got %', node->>'Node Type'; + END IF; + serial_buf := + COALESCE((node->>'Shared Hit Blocks')::int, 0) + + COALESCE((node->>'Shared Read Blocks')::int, 0); + + -- Parallel index scan with only workers scanning + SET LOCAL parallel_setup_cost = 0; + SET LOCAL parallel_tuple_cost = 0; + SET LOCAL min_parallel_index_scan_size = 0; + SET LOCAL min_parallel_table_scan_size = 0; + SET LOCAL max_parallel_workers_per_gather = 2; + SET LOCAL parallel_leader_participation = off; + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT count(stringu1) FROM par_idx_buf_test WHERE unique1 >= 0' INTO plan_json; + node := plan_json->0->'Plan'; + WHILE node->'Plans' IS NOT NULL LOOP + node := node->'Plans'->0; + END LOOP; + IF node->>'Node Type' <> 'Index Scan' OR NOT (node->>'Parallel Aware')::bool THEN + RAISE EXCEPTION 'expected Parallel Index Scan, got %', node->>'Node Type'; + END IF; + parallel_buf := + COALESCE((node->>'Shared Hit Blocks')::int, 0) + + COALESCE((node->>'Shared Read Blocks')::int, 0); + + -- Workers may each fetch some heap pages the other also fetched, so + -- allow for a little slack, but the totals must be in the same ballpark. + RETURN parallel_buf >= serial_buf * 0.9 AND parallel_buf <= serial_buf * 1.5; +END; +$$ LANGUAGE plpgsql; + +SET enable_seqscan = off; +SET enable_bitmapscan = off; +SET enable_indexonlyscan = off; +SELECT check_parallel_indexscan_buffers() AS parallel_indexscan_buffers_match; +RESET enable_seqscan; +RESET enable_bitmapscan; +RESET enable_indexonlyscan; + +DROP FUNCTION check_parallel_indexscan_buffers; +DROP TABLE par_idx_buf_test; From 916016996e9292c9726ef9d2afce044faab6e906 Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Sat, 7 Mar 2026 11:46:41 -0800 Subject: [PATCH 8/9] Add test_session_buffer_usage test module This is intended for testing instrumentation related logic as it pertains to the top level stack that is maintained as a running total. There is currently no in-core user that utilizes the top-level values in this manner, and especially during abort situations this helps ensure we don't lose activity due to incorrect handling of unfinalized node stacks. --- src/test/modules/Makefile | 1 + src/test/modules/meson.build | 1 + .../test_session_buffer_usage/Makefile | 23 + .../expected/test_session_buffer_usage.out | 401 ++++++++++++++++++ .../test_session_buffer_usage/meson.build | 33 ++ .../sql/test_session_buffer_usage.sql | 286 +++++++++++++ .../test_session_buffer_usage--1.0.sql | 31 ++ .../test_session_buffer_usage.c | 154 +++++++ .../test_session_buffer_usage.control | 5 + 9 files changed, 935 insertions(+) create mode 100644 src/test/modules/test_session_buffer_usage/Makefile create mode 100644 src/test/modules/test_session_buffer_usage/expected/test_session_buffer_usage.out create mode 100644 src/test/modules/test_session_buffer_usage/meson.build create mode 100644 src/test/modules/test_session_buffer_usage/sql/test_session_buffer_usage.sql create mode 100644 src/test/modules/test_session_buffer_usage/test_session_buffer_usage--1.0.sql create mode 100644 src/test/modules/test_session_buffer_usage/test_session_buffer_usage.c create mode 100644 src/test/modules/test_session_buffer_usage/test_session_buffer_usage.control diff --git a/src/test/modules/Makefile b/src/test/modules/Makefile index 6c1504ac9323a..e4b6b02023f42 100644 --- a/src/test/modules/Makefile +++ b/src/test/modules/Makefile @@ -50,6 +50,7 @@ SUBDIRS = \ test_resowner \ test_rls_hooks \ test_saslprep \ + test_session_buffer_usage \ test_shmem \ test_shm_mq \ test_slru \ diff --git a/src/test/modules/meson.build b/src/test/modules/meson.build index ef3cdb8faf9c9..49a47c678ab53 100644 --- a/src/test/modules/meson.build +++ b/src/test/modules/meson.build @@ -52,6 +52,7 @@ subdir('test_regex') subdir('test_resowner') subdir('test_rls_hooks') subdir('test_saslprep') +subdir('test_session_buffer_usage') subdir('test_shmem') subdir('test_shm_mq') subdir('test_slru') diff --git a/src/test/modules/test_session_buffer_usage/Makefile b/src/test/modules/test_session_buffer_usage/Makefile new file mode 100644 index 0000000000000..1252b222cb9f8 --- /dev/null +++ b/src/test/modules/test_session_buffer_usage/Makefile @@ -0,0 +1,23 @@ +# src/test/modules/test_session_buffer_usage/Makefile + +MODULE_big = test_session_buffer_usage +OBJS = \ + $(WIN32RES) \ + test_session_buffer_usage.o + +EXTENSION = test_session_buffer_usage +DATA = test_session_buffer_usage--1.0.sql +PGFILEDESC = "test_session_buffer_usage - show buffer usage statistics for the current session" + +REGRESS = test_session_buffer_usage + +ifdef USE_PGXS +PG_CONFIG = pg_config +PGXS := $(shell $(PG_CONFIG) --pgxs) +include $(PGXS) +else +subdir = src/test/modules/test_session_buffer_usage +top_builddir = ../../../.. +include $(top_builddir)/src/Makefile.global +include $(top_srcdir)/contrib/contrib-global.mk +endif diff --git a/src/test/modules/test_session_buffer_usage/expected/test_session_buffer_usage.out b/src/test/modules/test_session_buffer_usage/expected/test_session_buffer_usage.out new file mode 100644 index 0000000000000..b3ee0a49dc27a --- /dev/null +++ b/src/test/modules/test_session_buffer_usage/expected/test_session_buffer_usage.out @@ -0,0 +1,401 @@ +LOAD 'test_session_buffer_usage'; +CREATE EXTENSION test_session_buffer_usage; +-- Verify all columns are non-negative +SELECT count(*) = 1 AS ok FROM test_session_buffer_usage() +WHERE shared_blks_hit >= 0 AND shared_blks_read >= 0 + AND shared_blks_dirtied >= 0 AND shared_blks_written >= 0 + AND local_blks_hit >= 0 AND local_blks_read >= 0 + AND local_blks_dirtied >= 0 AND local_blks_written >= 0 + AND temp_blks_read >= 0 AND temp_blks_written >= 0 + AND shared_blk_read_time >= 0 AND shared_blk_write_time >= 0 + AND local_blk_read_time >= 0 AND local_blk_write_time >= 0 + AND temp_blk_read_time >= 0 AND temp_blk_write_time >= 0; + ok +---- + t +(1 row) + +-- Verify counters increase after buffer activity +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +CREATE TEMP TABLE test_buf_activity (id int, data text); +INSERT INTO test_buf_activity SELECT i, repeat('x', 100) FROM generate_series(1, 1000) AS i; +SELECT count(*) FROM test_buf_activity; + count +------- + 1000 +(1 row) + +SELECT local_blks_hit + local_blks_read > 0 AS blocks_increased +FROM test_session_buffer_usage(); + blocks_increased +------------------ + t +(1 row) + +DROP TABLE test_buf_activity; +-- Parallel query test +CREATE TABLE par_dc_tab (a int, b char(200)); +INSERT INTO par_dc_tab SELECT i, repeat('x', 200) FROM generate_series(1, 5000) AS i; +SELECT count(*) FROM par_dc_tab; + count +------- + 5000 +(1 row) + +-- Measure serial scan delta (leader does all the work) +SET max_parallel_workers_per_gather = 0; +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +SELECT count(*) FROM par_dc_tab; + count +------- + 5000 +(1 row) + +CREATE TEMP TABLE dc_serial_result AS +SELECT shared_blks_hit AS serial_delta FROM test_session_buffer_usage(); +-- Measure parallel scan delta with leader NOT participating in scanning. +-- Workers do all table scanning; leader only runs the Gather node. +SET parallel_setup_cost = 0; +SET parallel_tuple_cost = 0; +SET min_parallel_table_scan_size = 0; +SET max_parallel_workers_per_gather = 2; +SET parallel_leader_participation = off; +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +SELECT count(*) FROM par_dc_tab; + count +------- + 5000 +(1 row) + +-- Confirm we got a similar hit counter through parallel worker accumulation +SELECT shared_blks_hit > s.serial_delta / 2 AND shared_blks_hit < s.serial_delta * 2 + AS leader_buffers_match +FROM test_session_buffer_usage(), dc_serial_result s; + leader_buffers_match +---------------------- + t +(1 row) + +RESET parallel_setup_cost; +RESET parallel_tuple_cost; +RESET min_parallel_table_scan_size; +RESET max_parallel_workers_per_gather; +RESET parallel_leader_participation; +DROP TABLE par_dc_tab, dc_serial_result; +-- +-- Abort/exception tests: verify buffer usage survives various error paths. +-- +-- Rolled-back divide-by-zero under EXPLAIN ANALYZE +CREATE TEMP TABLE exc_tab (a int, b char(20)); +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +EXPLAIN (ANALYZE, BUFFERS, COSTS OFF) + WITH ins AS (INSERT INTO exc_tab VALUES (1, 'aaa') RETURNING a) + SELECT a / 0 FROM ins; +ERROR: division by zero +SELECT local_blks_dirtied > 0 AS exception_buffers_visible +FROM test_session_buffer_usage(); + exception_buffers_visible +--------------------------- + t +(1 row) + +DROP TABLE exc_tab; +-- Unique constraint violation in regular query +CREATE TEMP TABLE unique_tab (a int UNIQUE, b char(20)); +INSERT INTO unique_tab VALUES (1, 'first'); +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +INSERT INTO unique_tab VALUES (1, 'duplicate'); +ERROR: duplicate key value violates unique constraint "unique_tab_a_key" +DETAIL: Key (a)=(1) already exists. +SELECT local_blks_hit > 0 AS unique_violation_buffers_visible +FROM test_session_buffer_usage(); + unique_violation_buffers_visible +---------------------------------- + t +(1 row) + +DROP TABLE unique_tab; +-- Caught exception in PL/pgSQL subtransaction (BEGIN...EXCEPTION) +CREATE TEMP TABLE subxact_tab (a int, b char(20)); +CREATE FUNCTION subxact_exc_func() RETURNS text AS $$ +BEGIN + BEGIN + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF) + WITH ins AS (INSERT INTO subxact_tab VALUES (1, ''aaa'') RETURNING a) + SELECT a / 0 FROM ins'; + EXCEPTION WHEN division_by_zero THEN + RETURN 'caught'; + END; + RETURN 'not reached'; +END; +$$ LANGUAGE plpgsql; +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +SELECT subxact_exc_func(); + subxact_exc_func +------------------ + caught +(1 row) + +SELECT local_blks_dirtied > 0 AS subxact_buffers_visible +FROM test_session_buffer_usage(); + subxact_buffers_visible +------------------------- + t +(1 row) + +DROP FUNCTION subxact_exc_func; +DROP TABLE subxact_tab; +-- Cursor (FOR loop) in aborted subtransaction; verify post-exception tracking +CREATE TEMP TABLE cursor_tab (a int, b char(200)); +INSERT INTO cursor_tab SELECT i, repeat('x', 200) FROM generate_series(1, 500) AS i; +CREATE FUNCTION cursor_exc_func() RETURNS text AS $$ +DECLARE + rec record; + cnt int := 0; +BEGIN + BEGIN + FOR rec IN SELECT * FROM cursor_tab LOOP + cnt := cnt + 1; + IF cnt = 250 THEN + PERFORM 1 / 0; + END IF; + END LOOP; + EXCEPTION WHEN division_by_zero THEN + RETURN 'caught after ' || cnt || ' rows'; + END; + RETURN 'not reached'; +END; +$$ LANGUAGE plpgsql; +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +SELECT cursor_exc_func(); + cursor_exc_func +----------------------- + caught after 250 rows +(1 row) + +SELECT local_blks_hit + local_blks_read > 0 + AS cursor_subxact_buffers_visible +FROM test_session_buffer_usage(); + cursor_subxact_buffers_visible +-------------------------------- + t +(1 row) + +DROP FUNCTION cursor_exc_func; +DROP TABLE cursor_tab; +-- Trigger abort under EXPLAIN ANALYZE: verify that buffer activity from a +-- trigger that throws an error is still properly propagated. +CREATE TEMP TABLE trig_err_tab (a int); +CREATE TEMP TABLE trig_work_tab (a int, b char(200)); +INSERT INTO trig_work_tab SELECT i, repeat('x', 200) FROM generate_series(1, 500) AS i; +-- Warm local buffers so trig_work_tab reads become hits +SELECT count(*) FROM trig_work_tab; + count +------- + 500 +(1 row) + +CREATE FUNCTION trig_err_func() RETURNS trigger AS $$ +BEGIN + PERFORM count(*) FROM trig_work_tab; + RAISE EXCEPTION 'trigger error'; + RETURN NEW; +END; +$$ LANGUAGE plpgsql; +CREATE TRIGGER trig_err BEFORE INSERT ON trig_err_tab + FOR EACH ROW EXECUTE FUNCTION trig_err_func(); +-- Measure how many local buffer hits a scan of trig_work_tab produces +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +SELECT count(*) FROM trig_work_tab; + count +------- + 500 +(1 row) + +CREATE TEMP TABLE trig_serial_result AS +SELECT local_blks_hit AS serial_hits FROM test_session_buffer_usage(); +-- Now trigger the same scan via a trigger that errors +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +EXPLAIN (ANALYZE, BUFFERS, COSTS OFF) + INSERT INTO trig_err_tab VALUES (1); +ERROR: trigger error +CONTEXT: PL/pgSQL function trig_err_func() line 4 at RAISE +-- The trigger scanned trig_work_tab but errored before InstrStopTrigger ran, +-- so its entry was never finalized. The query's QueryInstrumentation keeps +-- such entries in its unfinalized list, and the resource owner cleanup on +-- abort accumulates them, so the buffer data is still propagated. +SELECT local_blks_hit >= s.serial_hits / 2 + AS trigger_abort_buffers_propagated +FROM test_session_buffer_usage(), trig_serial_result s; + trigger_abort_buffers_propagated +---------------------------------- + t +(1 row) + +DROP TABLE trig_err_tab, trig_work_tab, trig_serial_result; +DROP FUNCTION trig_err_func; +-- Parallel worker abort: worker buffer activity is currently NOT propagated on abort. +-- +-- When a parallel worker aborts, InstrEndParallelQuery and +-- ExecParallelReportInstrumentation never run, so the worker's buffer +-- activity is never written to shared memory, despite the information having been +-- captured by the res owner release instrumentation handling. +CREATE TABLE par_abort_tab (a int, b char(200)); +INSERT INTO par_abort_tab SELECT i, repeat('x', 200) FROM generate_series(1, 5000) AS i; +-- Warm shared buffers so all reads become hits +SELECT count(*) FROM par_abort_tab; + count +------- + 5000 +(1 row) + +-- Measure serial scan delta as a reference (leader reads all blocks) +SET max_parallel_workers_per_gather = 0; +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +SELECT b::int2 FROM par_abort_tab WHERE a > 1000; +ERROR: invalid input syntax for type smallint: "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx" +CREATE TABLE par_abort_serial_result AS +SELECT shared_blks_hit AS serial_delta FROM test_session_buffer_usage(); +-- Now force parallel with leader NOT participating in scanning +SET parallel_setup_cost = 0; +SET parallel_tuple_cost = 0; +SET min_parallel_table_scan_size = 0; +SET max_parallel_workers_per_gather = 2; +SET parallel_leader_participation = off; +SET debug_parallel_query = on; -- Ensure we get CONTEXT line consistently +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +SELECT b::int2 FROM par_abort_tab WHERE a > 1000; +ERROR: invalid input syntax for type smallint: "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx" +CONTEXT: parallel worker +RESET debug_parallel_query; +-- Workers scanned the table but aborted before reporting stats back. +-- The leader's delta should be much less than a serial scan, documenting +-- that worker buffer activity is lost on abort. +SELECT shared_blks_hit < s.serial_delta / 2 + AS worker_abort_buffers_not_propagated +FROM test_session_buffer_usage(), par_abort_serial_result s; + worker_abort_buffers_not_propagated +------------------------------------- + t +(1 row) + +RESET parallel_setup_cost; +RESET parallel_tuple_cost; +RESET min_parallel_table_scan_size; +RESET max_parallel_workers_per_gather; +RESET parallel_leader_participation; +DROP TABLE par_abort_tab, par_abort_serial_result; +-- Cursor fetched inside a transaction that then aborts, with query-level +-- instrumentation on the cursor's own query (as it would be with +-- pg_stat_statements loaded). +-- +-- The fetches accumulate into the cursor query's QueryInstrumentation, which +-- only reaches the session totals when it is finalized: at ExecutorFinish in +-- the normal case, or through the resource owner cleanup on abort. Here the +-- portal is dropped as failed without ExecutorFinish ever running, so the +-- buffer activity of the fetches must be recovered by the abort cleanup. +SET test_session_buffer_usage.track_queries = on; +CREATE TABLE cursor_abort_tab (a int, b char(200)); +INSERT INTO cursor_abort_tab SELECT i, repeat('x', 200) FROM generate_series(1, 5000) AS i; +-- Warm shared buffers so all reads become hits +SELECT count(*) FROM cursor_abort_tab; + count +------- + 5000 +(1 row) + +-- Reference: a complete scan outside of a cursor +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +SELECT count(*) FROM cursor_abort_tab; + count +------- + 5000 +(1 row) + +CREATE TABLE cursor_abort_serial_result AS +SELECT shared_blks_hit AS serial_delta FROM test_session_buffer_usage(); +-- Same scan through a cursor, in a transaction that aborts after the fetch +SELECT test_session_buffer_usage_reset(); + test_session_buffer_usage_reset +--------------------------------- + +(1 row) + +BEGIN; +DECLARE cursor_abort_cur CURSOR FOR SELECT * FROM cursor_abort_tab; +MOVE ALL IN cursor_abort_cur; +SELECT 1 / 0; +ERROR: division by zero +ROLLBACK; +SELECT shared_blks_hit >= s.serial_delta / 2 + AS cursor_abort_buffers_visible +FROM test_session_buffer_usage(), cursor_abort_serial_result s; + cursor_abort_buffers_visible +------------------------------ + t +(1 row) + +RESET test_session_buffer_usage.track_queries; +DROP TABLE cursor_abort_tab, cursor_abort_serial_result; +-- Cleanup +DROP EXTENSION test_session_buffer_usage; diff --git a/src/test/modules/test_session_buffer_usage/meson.build b/src/test/modules/test_session_buffer_usage/meson.build new file mode 100644 index 0000000000000..b96f67dc7fe37 --- /dev/null +++ b/src/test/modules/test_session_buffer_usage/meson.build @@ -0,0 +1,33 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +test_session_buffer_usage_sources = files( + 'test_session_buffer_usage.c', +) + +if host_system == 'windows' + test_session_buffer_usage_sources += rc_lib_gen.process(win32ver_rc, extra_args: [ + '--NAME', 'test_session_buffer_usage', + '--FILEDESC', 'test_session_buffer_usage - show buffer usage statistics for the current session',]) +endif + +test_session_buffer_usage = shared_module('test_session_buffer_usage', + test_session_buffer_usage_sources, + kwargs: pg_test_mod_args, +) +test_install_libs += test_session_buffer_usage + +test_install_data += files( + 'test_session_buffer_usage.control', + 'test_session_buffer_usage--1.0.sql', +) + +tests += { + 'name': 'test_session_buffer_usage', + 'sd': meson.current_source_dir(), + 'bd': meson.current_build_dir(), + 'regress': { + 'sql': [ + 'test_session_buffer_usage', + ], + }, +} diff --git a/src/test/modules/test_session_buffer_usage/sql/test_session_buffer_usage.sql b/src/test/modules/test_session_buffer_usage/sql/test_session_buffer_usage.sql new file mode 100644 index 0000000000000..0a3c3aff45e65 --- /dev/null +++ b/src/test/modules/test_session_buffer_usage/sql/test_session_buffer_usage.sql @@ -0,0 +1,286 @@ +LOAD 'test_session_buffer_usage'; +CREATE EXTENSION test_session_buffer_usage; + +-- Verify all columns are non-negative +SELECT count(*) = 1 AS ok FROM test_session_buffer_usage() +WHERE shared_blks_hit >= 0 AND shared_blks_read >= 0 + AND shared_blks_dirtied >= 0 AND shared_blks_written >= 0 + AND local_blks_hit >= 0 AND local_blks_read >= 0 + AND local_blks_dirtied >= 0 AND local_blks_written >= 0 + AND temp_blks_read >= 0 AND temp_blks_written >= 0 + AND shared_blk_read_time >= 0 AND shared_blk_write_time >= 0 + AND local_blk_read_time >= 0 AND local_blk_write_time >= 0 + AND temp_blk_read_time >= 0 AND temp_blk_write_time >= 0; + +-- Verify counters increase after buffer activity +SELECT test_session_buffer_usage_reset(); + +CREATE TEMP TABLE test_buf_activity (id int, data text); +INSERT INTO test_buf_activity SELECT i, repeat('x', 100) FROM generate_series(1, 1000) AS i; +SELECT count(*) FROM test_buf_activity; + +SELECT local_blks_hit + local_blks_read > 0 AS blocks_increased +FROM test_session_buffer_usage(); + +DROP TABLE test_buf_activity; + +-- Parallel query test +CREATE TABLE par_dc_tab (a int, b char(200)); +INSERT INTO par_dc_tab SELECT i, repeat('x', 200) FROM generate_series(1, 5000) AS i; + +SELECT count(*) FROM par_dc_tab; + +-- Measure serial scan delta (leader does all the work) +SET max_parallel_workers_per_gather = 0; + +SELECT test_session_buffer_usage_reset(); +SELECT count(*) FROM par_dc_tab; + +CREATE TEMP TABLE dc_serial_result AS +SELECT shared_blks_hit AS serial_delta FROM test_session_buffer_usage(); + +-- Measure parallel scan delta with leader NOT participating in scanning. +-- Workers do all table scanning; leader only runs the Gather node. +SET parallel_setup_cost = 0; +SET parallel_tuple_cost = 0; +SET min_parallel_table_scan_size = 0; +SET max_parallel_workers_per_gather = 2; +SET parallel_leader_participation = off; + +SELECT test_session_buffer_usage_reset(); +SELECT count(*) FROM par_dc_tab; + +-- Confirm we got a similar hit counter through parallel worker accumulation +SELECT shared_blks_hit > s.serial_delta / 2 AND shared_blks_hit < s.serial_delta * 2 + AS leader_buffers_match +FROM test_session_buffer_usage(), dc_serial_result s; + +RESET parallel_setup_cost; +RESET parallel_tuple_cost; +RESET min_parallel_table_scan_size; +RESET max_parallel_workers_per_gather; +RESET parallel_leader_participation; + +DROP TABLE par_dc_tab, dc_serial_result; + +-- +-- Abort/exception tests: verify buffer usage survives various error paths. +-- + +-- Rolled-back divide-by-zero under EXPLAIN ANALYZE +CREATE TEMP TABLE exc_tab (a int, b char(20)); + +SELECT test_session_buffer_usage_reset(); + +EXPLAIN (ANALYZE, BUFFERS, COSTS OFF) + WITH ins AS (INSERT INTO exc_tab VALUES (1, 'aaa') RETURNING a) + SELECT a / 0 FROM ins; + +SELECT local_blks_dirtied > 0 AS exception_buffers_visible +FROM test_session_buffer_usage(); + +DROP TABLE exc_tab; + +-- Unique constraint violation in regular query +CREATE TEMP TABLE unique_tab (a int UNIQUE, b char(20)); +INSERT INTO unique_tab VALUES (1, 'first'); + +SELECT test_session_buffer_usage_reset(); +INSERT INTO unique_tab VALUES (1, 'duplicate'); + +SELECT local_blks_hit > 0 AS unique_violation_buffers_visible +FROM test_session_buffer_usage(); + +DROP TABLE unique_tab; + +-- Caught exception in PL/pgSQL subtransaction (BEGIN...EXCEPTION) +CREATE TEMP TABLE subxact_tab (a int, b char(20)); + +CREATE FUNCTION subxact_exc_func() RETURNS text AS $$ +BEGIN + BEGIN + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF) + WITH ins AS (INSERT INTO subxact_tab VALUES (1, ''aaa'') RETURNING a) + SELECT a / 0 FROM ins'; + EXCEPTION WHEN division_by_zero THEN + RETURN 'caught'; + END; + RETURN 'not reached'; +END; +$$ LANGUAGE plpgsql; + +SELECT test_session_buffer_usage_reset(); +SELECT subxact_exc_func(); + +SELECT local_blks_dirtied > 0 AS subxact_buffers_visible +FROM test_session_buffer_usage(); + +DROP FUNCTION subxact_exc_func; +DROP TABLE subxact_tab; + +-- Cursor (FOR loop) in aborted subtransaction; verify post-exception tracking +CREATE TEMP TABLE cursor_tab (a int, b char(200)); +INSERT INTO cursor_tab SELECT i, repeat('x', 200) FROM generate_series(1, 500) AS i; + +CREATE FUNCTION cursor_exc_func() RETURNS text AS $$ +DECLARE + rec record; + cnt int := 0; +BEGIN + BEGIN + FOR rec IN SELECT * FROM cursor_tab LOOP + cnt := cnt + 1; + IF cnt = 250 THEN + PERFORM 1 / 0; + END IF; + END LOOP; + EXCEPTION WHEN division_by_zero THEN + RETURN 'caught after ' || cnt || ' rows'; + END; + RETURN 'not reached'; +END; +$$ LANGUAGE plpgsql; + +SELECT test_session_buffer_usage_reset(); +SELECT cursor_exc_func(); + +SELECT local_blks_hit + local_blks_read > 0 + AS cursor_subxact_buffers_visible +FROM test_session_buffer_usage(); + +DROP FUNCTION cursor_exc_func; +DROP TABLE cursor_tab; + +-- Trigger abort under EXPLAIN ANALYZE: verify that buffer activity from a +-- trigger that throws an error is still properly propagated. +CREATE TEMP TABLE trig_err_tab (a int); +CREATE TEMP TABLE trig_work_tab (a int, b char(200)); +INSERT INTO trig_work_tab SELECT i, repeat('x', 200) FROM generate_series(1, 500) AS i; + +-- Warm local buffers so trig_work_tab reads become hits +SELECT count(*) FROM trig_work_tab; + +CREATE FUNCTION trig_err_func() RETURNS trigger AS $$ +BEGIN + PERFORM count(*) FROM trig_work_tab; + RAISE EXCEPTION 'trigger error'; + RETURN NEW; +END; +$$ LANGUAGE plpgsql; + +CREATE TRIGGER trig_err BEFORE INSERT ON trig_err_tab + FOR EACH ROW EXECUTE FUNCTION trig_err_func(); + +-- Measure how many local buffer hits a scan of trig_work_tab produces +SELECT test_session_buffer_usage_reset(); +SELECT count(*) FROM trig_work_tab; + +CREATE TEMP TABLE trig_serial_result AS +SELECT local_blks_hit AS serial_hits FROM test_session_buffer_usage(); + +-- Now trigger the same scan via a trigger that errors +SELECT test_session_buffer_usage_reset(); +EXPLAIN (ANALYZE, BUFFERS, COSTS OFF) + INSERT INTO trig_err_tab VALUES (1); + +-- The trigger scanned trig_work_tab but errored before InstrStopTrigger ran, +-- so its entry was never finalized. The query's QueryInstrumentation keeps +-- such entries in its unfinalized list, and the resource owner cleanup on +-- abort accumulates them, so the buffer data is still propagated. +SELECT local_blks_hit >= s.serial_hits / 2 + AS trigger_abort_buffers_propagated +FROM test_session_buffer_usage(), trig_serial_result s; + +DROP TABLE trig_err_tab, trig_work_tab, trig_serial_result; +DROP FUNCTION trig_err_func; + +-- Parallel worker abort: worker buffer activity is currently NOT propagated on abort. +-- +-- When a parallel worker aborts, InstrEndParallelQuery and +-- ExecParallelReportInstrumentation never run, so the worker's buffer +-- activity is never written to shared memory, despite the information having been +-- captured by the res owner release instrumentation handling. +CREATE TABLE par_abort_tab (a int, b char(200)); +INSERT INTO par_abort_tab SELECT i, repeat('x', 200) FROM generate_series(1, 5000) AS i; + +-- Warm shared buffers so all reads become hits +SELECT count(*) FROM par_abort_tab; + +-- Measure serial scan delta as a reference (leader reads all blocks) +SET max_parallel_workers_per_gather = 0; + +SELECT test_session_buffer_usage_reset(); +SELECT b::int2 FROM par_abort_tab WHERE a > 1000; + +CREATE TABLE par_abort_serial_result AS +SELECT shared_blks_hit AS serial_delta FROM test_session_buffer_usage(); + +-- Now force parallel with leader NOT participating in scanning +SET parallel_setup_cost = 0; +SET parallel_tuple_cost = 0; +SET min_parallel_table_scan_size = 0; +SET max_parallel_workers_per_gather = 2; +SET parallel_leader_participation = off; +SET debug_parallel_query = on; -- Ensure we get CONTEXT line consistently + +SELECT test_session_buffer_usage_reset(); +SELECT b::int2 FROM par_abort_tab WHERE a > 1000; + +RESET debug_parallel_query; + +-- Workers scanned the table but aborted before reporting stats back. +-- The leader's delta should be much less than a serial scan, documenting +-- that worker buffer activity is lost on abort. +SELECT shared_blks_hit < s.serial_delta / 2 + AS worker_abort_buffers_not_propagated +FROM test_session_buffer_usage(), par_abort_serial_result s; + +RESET parallel_setup_cost; +RESET parallel_tuple_cost; +RESET min_parallel_table_scan_size; +RESET max_parallel_workers_per_gather; +RESET parallel_leader_participation; + +DROP TABLE par_abort_tab, par_abort_serial_result; + +-- Cursor fetched inside a transaction that then aborts, with query-level +-- instrumentation on the cursor's own query (as it would be with +-- pg_stat_statements loaded). +-- +-- The fetches accumulate into the cursor query's QueryInstrumentation, which +-- only reaches the session totals when it is finalized: at ExecutorFinish in +-- the normal case, or through the resource owner cleanup on abort. Here the +-- portal is dropped as failed without ExecutorFinish ever running, so the +-- buffer activity of the fetches must be recovered by the abort cleanup. +SET test_session_buffer_usage.track_queries = on; + +CREATE TABLE cursor_abort_tab (a int, b char(200)); +INSERT INTO cursor_abort_tab SELECT i, repeat('x', 200) FROM generate_series(1, 5000) AS i; + +-- Warm shared buffers so all reads become hits +SELECT count(*) FROM cursor_abort_tab; + +-- Reference: a complete scan outside of a cursor +SELECT test_session_buffer_usage_reset(); +SELECT count(*) FROM cursor_abort_tab; + +CREATE TABLE cursor_abort_serial_result AS +SELECT shared_blks_hit AS serial_delta FROM test_session_buffer_usage(); + +-- Same scan through a cursor, in a transaction that aborts after the fetch +SELECT test_session_buffer_usage_reset(); +BEGIN; +DECLARE cursor_abort_cur CURSOR FOR SELECT * FROM cursor_abort_tab; +MOVE ALL IN cursor_abort_cur; +SELECT 1 / 0; +ROLLBACK; + +SELECT shared_blks_hit >= s.serial_delta / 2 + AS cursor_abort_buffers_visible +FROM test_session_buffer_usage(), cursor_abort_serial_result s; + +RESET test_session_buffer_usage.track_queries; +DROP TABLE cursor_abort_tab, cursor_abort_serial_result; + +-- Cleanup +DROP EXTENSION test_session_buffer_usage; diff --git a/src/test/modules/test_session_buffer_usage/test_session_buffer_usage--1.0.sql b/src/test/modules/test_session_buffer_usage/test_session_buffer_usage--1.0.sql new file mode 100644 index 0000000000000..e9833be470ae5 --- /dev/null +++ b/src/test/modules/test_session_buffer_usage/test_session_buffer_usage--1.0.sql @@ -0,0 +1,31 @@ +/* src/test/modules/test_session_buffer_usage/test_session_buffer_usage--1.0.sql */ + +-- complain if script is sourced in psql, rather than via CREATE EXTENSION +\echo Use "CREATE EXTENSION test_session_buffer_usage" to load this file. \quit + +CREATE FUNCTION test_session_buffer_usage( + OUT shared_blks_hit bigint, + OUT shared_blks_read bigint, + OUT shared_blks_dirtied bigint, + OUT shared_blks_written bigint, + OUT local_blks_hit bigint, + OUT local_blks_read bigint, + OUT local_blks_dirtied bigint, + OUT local_blks_written bigint, + OUT temp_blks_read bigint, + OUT temp_blks_written bigint, + OUT shared_blk_read_time double precision, + OUT shared_blk_write_time double precision, + OUT local_blk_read_time double precision, + OUT local_blk_write_time double precision, + OUT temp_blk_read_time double precision, + OUT temp_blk_write_time double precision +) +RETURNS record +AS 'MODULE_PATHNAME', 'test_session_buffer_usage' +LANGUAGE C PARALLEL RESTRICTED; + +CREATE FUNCTION test_session_buffer_usage_reset() +RETURNS void +AS 'MODULE_PATHNAME', 'test_session_buffer_usage_reset' +LANGUAGE C PARALLEL RESTRICTED; diff --git a/src/test/modules/test_session_buffer_usage/test_session_buffer_usage.c b/src/test/modules/test_session_buffer_usage/test_session_buffer_usage.c new file mode 100644 index 0000000000000..b8ff46aabf21e --- /dev/null +++ b/src/test/modules/test_session_buffer_usage/test_session_buffer_usage.c @@ -0,0 +1,154 @@ +/*------------------------------------------------------------------------- + * + * test_session_buffer_usage.c + * show buffer usage statistics for the current session + * + * Copyright (c) 2026, PostgreSQL Global Development Group + * + * src/test/modules/test_session_buffer_usage/test_session_buffer_usage.c + *------------------------------------------------------------------------- + */ +#include "postgres.h" + +#include "access/htup_details.h" +#include "executor/executor.h" +#include "executor/instrument.h" +#include "funcapi.h" +#include "miscadmin.h" +#include "utils/guc.h" +#include "utils/memutils.h" + +PG_MODULE_MAGIC_EXT( + .name = "test_session_buffer_usage", + .version = PG_VERSION +); + +#define NUM_BUFFER_USAGE_COLUMNS 16 + +PG_FUNCTION_INFO_V1(test_session_buffer_usage); +PG_FUNCTION_INFO_V1(test_session_buffer_usage_reset); + +/* + * test_session_buffer_usage.track_queries + * + * When on, request query-level buffer/WAL instrumentation for every query + * executed in this session, the same way pg_stat_statements does. This lets + * the tests exercise the QueryInstrumentation code paths (resource owner + * registration, abort handling, accumulation into the session totals) + * without depending on a contrib module. + */ +static bool track_queries = false; + +static ExecutorStart_hook_type prev_ExecutorStart = NULL; + +static void +tsbu_ExecutorStart(QueryDesc *queryDesc, int eflags) +{ + if (track_queries) + queryDesc->query_instr_options |= INSTRUMENT_BUFFERS | INSTRUMENT_WAL; + + if (prev_ExecutorStart) + prev_ExecutorStart(queryDesc, eflags); + else + standard_ExecutorStart(queryDesc, eflags); +} + +void +_PG_init(void) +{ + DefineCustomBoolVariable("test_session_buffer_usage.track_queries", + "Request query-level buffer/WAL instrumentation for all queries.", + NULL, + &track_queries, + false, + PGC_USERSET, + 0, + NULL, NULL, NULL); + + MarkGUCPrefixReserved("test_session_buffer_usage"); + + prev_ExecutorStart = ExecutorStart_hook; + ExecutorStart_hook = tsbu_ExecutorStart; +} + +#define HAVE_INSTR_STACK 1 /* Change to 0 when testing before stack + * change */ + +/* + * Snapshot of the session counters taken by test_session_buffer_usage_reset(). + * + * The session-level totals must never be reset, since the cumulative stats + * system (pg_stat_database I/O timings) relies on them only ever increasing, + * so report everything relative to this baseline instead. + */ +static BufferUsage baseline; + +#define DIFF_COUNTER(fld) ((int64) (usage->fld - baseline.fld)) +#define DIFF_TIME_MS(fld) \ + (INSTR_TIME_GET_MILLISEC(usage->fld) - INSTR_TIME_GET_MILLISEC(baseline.fld)) + +/* + * SQL function: test_session_buffer_usage() + * + * Returns a single row with all BufferUsage counters accumulated since the + * start of the session, or since the last call to + * test_session_buffer_usage_reset(). Excludes any usage not yet added to the + * top of the stack (e.g. if this gets called inside a statement that also had + * buffer activity). + */ +Datum +test_session_buffer_usage(PG_FUNCTION_ARGS) +{ + TupleDesc tupdesc; + Datum values[NUM_BUFFER_USAGE_COLUMNS]; + bool nulls[NUM_BUFFER_USAGE_COLUMNS]; + BufferUsage *usage; + + if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE) + elog(ERROR, "return type must be a row type"); + + memset(nulls, 0, sizeof(nulls)); + +#if HAVE_INSTR_STACK + usage = &instr_top.bufusage; +#else + usage = &pgBufferUsage; +#endif + + values[0] = Int64GetDatum(DIFF_COUNTER(shared_blks_hit)); + values[1] = Int64GetDatum(DIFF_COUNTER(shared_blks_read)); + values[2] = Int64GetDatum(DIFF_COUNTER(shared_blks_dirtied)); + values[3] = Int64GetDatum(DIFF_COUNTER(shared_blks_written)); + values[4] = Int64GetDatum(DIFF_COUNTER(local_blks_hit)); + values[5] = Int64GetDatum(DIFF_COUNTER(local_blks_read)); + values[6] = Int64GetDatum(DIFF_COUNTER(local_blks_dirtied)); + values[7] = Int64GetDatum(DIFF_COUNTER(local_blks_written)); + values[8] = Int64GetDatum(DIFF_COUNTER(temp_blks_read)); + values[9] = Int64GetDatum(DIFF_COUNTER(temp_blks_written)); + values[10] = Float8GetDatum(DIFF_TIME_MS(shared_blk_read_time)); + values[11] = Float8GetDatum(DIFF_TIME_MS(shared_blk_write_time)); + values[12] = Float8GetDatum(DIFF_TIME_MS(local_blk_read_time)); + values[13] = Float8GetDatum(DIFF_TIME_MS(local_blk_write_time)); + values[14] = Float8GetDatum(DIFF_TIME_MS(temp_blk_read_time)); + values[15] = Float8GetDatum(DIFF_TIME_MS(temp_blk_write_time)); + + PG_RETURN_DATUM(HeapTupleGetDatum(heap_form_tuple(tupdesc, values, nulls))); +} + +/* + * SQL function: test_session_buffer_usage_reset() + * + * Makes test_session_buffer_usage() report counters relative to the current + * session totals. Useful in tests to avoid the baseline/delta pattern. + */ +Datum +test_session_buffer_usage_reset(PG_FUNCTION_ARGS) +{ +#if HAVE_INSTR_STACK + baseline = instr_top.bufusage; +#else + baseline = pgBufferUsage; +#endif + + PG_RETURN_VOID(); +} diff --git a/src/test/modules/test_session_buffer_usage/test_session_buffer_usage.control b/src/test/modules/test_session_buffer_usage/test_session_buffer_usage.control new file mode 100644 index 0000000000000..41cfb15a7650a --- /dev/null +++ b/src/test/modules/test_session_buffer_usage/test_session_buffer_usage.control @@ -0,0 +1,5 @@ +# test_session_buffer_usage extension +comment = 'show buffer usage statistics for the current session' +default_version = '1.0' +module_pathname = '$libdir/test_session_buffer_usage' +relocatable = true From a5cc07e1b9972f5480ce5c465678fcdaddc1b7eb Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Fri, 2 Oct 2026 21:52:08 -0700 Subject: [PATCH 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 371b56b339ded..af3b67a385242 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 51b0f72c29cd3..288131c0b5fb4 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 dd71e8028e5a3..232247df4c6ec 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 57a78325f47d8..311df12647863 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 db93562a8fc72..d2484e03f1858 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 d31c0b48a1db5..f7d83eeef4f03 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 7f3bc0165931c..a006c889169c2 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 8c02cd2d40f22..d37cebc52a790 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 f6fad6a6e6851..16e4cb4663d94 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 17d560fb98222..df76271d09bae 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 9b99062f8534d..4d01a8702edce 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().