Thread
Commits
Same data as JSON:
GET /api/v1/messages/:b64id/commits
the thread's linked commits as JSON, with link sources.
API reference →
-
instrumentation: Allocate query level instrumentation in ExecutorStart
- 2c16deee2f7d 19 (unreleased) landed
-
instrumentation: Move ExecProcNodeInstr to allow inlining
- 544000288ec8 19 (unreleased) landed
-
instrumentation: Separate per-node logic from other uses
- 5a79e78501f4 19 (unreleased) landed
-
instrumentation: Separate trigger logic from other uses
- 7d9b74df53e9 19 (unreleased) landed
-
instrumentation: Rename INSTR_TIME_LT macro to INSTR_TIME_GT
- 3218825271bd 19 (unreleased) landed
-
instrumentation: Keep time fields as instrtime, convert in callers
- e5a5e0a90750 19 (unreleased) landed
-
Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2025-08-31T23:57:01Z
Hi, Please find attached a patch series that introduces a new paradigm for how per-node WAL/buffer usage is tracked, with two primary goals: (1) reduce overhead of EXPLAIN ANALYZE, (2) enable future work like tracking estimated distinct buffer hits [0]. Currently we utilize pgWalUsage/pgBufferUsage as global counters, and in InstrStopNode we call the rather expensive BufferUsageAccumDiff/WalUsageAccumDiff to know how much activity happened within a given node cycle. This proposal instead uses a stack, where each time we enter a node (InstrStartNode) we point a new global (pgInstrStack) to the current stack entry. Whilst we're in that node we increment buffer/WAL usage statistics to the stack entry. On exit (InstrStopNode) we restore the previous entry. This change provides about a 10% performance benefit for EXPLAIN ANALYZE on paths that repeatedly enter InstrStopNode, e.g. SELECT COUNT(*): CREATE TABLE test(id int); INSERT INTO test SELECT * FROM generate_series(0, 1000000); master (124ms, best out of 3): postgres=# EXPLAIN (ANALYZE) SELECT COUNT(*) FROM test; QUERY PLAN ------------------------------------------------------------------------------------------------------------------------ Aggregate (cost=16925.01..16925.02 rows=1 width=8) (actual time=124.910..124.910 rows=1.00 loops=1) Buffers: shared hit=752 read=3673 -> Seq Scan on test (cost=0.00..14425.01 rows=1000001 width=0) (actual time=0.201..62.228 rows=1000001.00 loops=1) Buffers: shared hit=752 read=3673 Planning Time: 0.116 ms Execution Time: 124.961 ms patched (109ms, best out of 3): postgres=# EXPLAIN (ANALYZE) SELECT COUNT(*) FROM test; QUERY PLAN ------------------------------------------------------------------------------------------------------------------------ Aggregate (cost=16925.01..16925.02 rows=1 width=8) (actual time=109.788..109.788 rows=1.00 loops=1) Buffers: shared hit=940 read=3485 -> Seq Scan on test (cost=0.00..14425.01 rows=1000001 width=0) (actual time=0.153..69.368 rows=1000001.00 loops=1) Buffers: shared hit=940 read=3485 Planning Time: 0.134 ms Execution Time: 109.837 ms (6 rows) I have also prototyped a more ambitious approach that completely removes pgWalUsage/pgBufferUsage (utilizing the stack-collected data for e.g. pg_stat_statements), but for now this patch set does not include that change, but instead keeps adding to these legacy globals as well. Patches attached: 0001: Separate node instrumentation from other use of Instrumentation struct Previously different places (e.g. query "total time") were repurposing the per-node Instrumentation struct. Instead, simplify the Instrumentation struct to only track time, WAL/buffer usage, and tuple counts. Similarly, drop the use of InstrEndLoop outside of per-node instrumentation. Introduce the NodeInstrumentation struct to carry forward the per-node instrumentation information. 0002: Replace direct changes of pgBufferUsage/pgWalUsage with INSTR_* macros 0003: Introduce stack for tracking per-node WAL/buffer usage Feedback/thoughts welcome! CCing Andres since he had expressed interest in this off-list. [0]: See lightning talk slides from PGConf.Dev discussing an HLL-based EXPLAIN (BUFFERS DISTINCT): https://resources.pganalyze.com/pganalyze_PGConf.dev_2025_shared_blks_hit_distinct.pdf Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Andres Freund <andres@anarazel.de> — 2025-09-04T20:23:06Z
Hi, On 2025-08-31 16:57:01 -0700, Lukas Fittl wrote: > Please find attached a patch series that introduces a new paradigm for how > per-node WAL/buffer usage is tracked, with two primary goals: (1) reduce > overhead of EXPLAIN ANALYZE, (2) enable future work like tracking estimated > distinct buffer hits [0]. I like this for a third reason: To separate out buffer access statistics for the index and the table in index scans. Right now it's very hard to figure out if a query is slow because of the index lookups or finding the tuples in the table. > 0001: Separate node instrumentation from other use of Instrumentation struct > > Previously different places (e.g. query "total time") were repurposing > the per-node Instrumentation struct. Instead, simplify the Instrumentation > struct to only track time, WAL/buffer usage, and tuple counts. Similarly, > drop the use of InstrEndLoop outside of per-node instrumentation. Introduce > the NodeInstrumentation struct to carry forward the per-node > instrumentation information. It's mildly odd that the two types of instrumentation have a different definition of 'total' (one double, one instr_time). > 0003: Introduce stack for tracking per-node WAL/buffer usage > From 4375fcb4141f18d6cd927659970518553aa3fe94 Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Sun, 31 Aug 2025 16:37:05 -0700 > Subject: [PATCH v1 3/3] Introduce stack for tracking per-node WAL/buffer usage > diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c > index b83ced9a57a..1c2268bc608 100644 > --- a/src/backend/executor/execMain.c > +++ b/src/backend/executor/execMain.c > @@ -312,6 +312,7 @@ standard_ExecutorRun(QueryDesc *queryDesc, > DestReceiver *dest; > bool sendTuples; > MemoryContext oldcontext; > + InstrStackResource *res; > > /* sanity checks */ > Assert(queryDesc != NULL); > @@ -333,6 +334,9 @@ standard_ExecutorRun(QueryDesc *queryDesc, > if (queryDesc->totaltime) > InstrStart(queryDesc->totaltime); > > + /* Start up per-query node level instrumentation */ > + res = InstrStartQuery(); > + > /* > * extract information from the query descriptor and the query feature. > */ > @@ -382,6 +386,9 @@ standard_ExecutorRun(QueryDesc *queryDesc, > if (sendTuples) > dest->rShutdown(dest); > > + /* Shut down per-query node level instrumentation */ > + InstrShutdownQuery(res); > + > if (queryDesc->totaltime) > InstrStop(queryDesc->totaltime, estate->es_processed); Why are we doing Instr{Start,Stop}Query when not using instrumentation? Resowner stuff ain't free, so I'd skip them when not necessary. > diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c > index d286471254b..7436f307994 100644 > --- a/src/backend/executor/execProcnode.c > +++ b/src/backend/executor/execProcnode.c > @@ -823,8 +823,17 @@ ExecShutdownNode_walker(PlanState *node, void *context) > > /* Stop the node if we started it above, reporting 0 tuples. */ > if (node->instrument && node->instrument->running) > + { > InstrStopNode(node->instrument, 0); > > + /* > + * Propagate WAL/buffer stats to the parent node on the > + * instrumentation stack (which is where InstrStopNode returned us > + * to). > + */ > + InstrNodeAddToCurrent(&node->instrument->stack); > + } > + > return false; > } Can we rely on this being reached? Note that ExecutePlan() calls ExecShutdownNode() conditionally: /* * If we know we won't need to back up, we can release resources at this * point. */ if (!(estate->es_top_eflags & EXEC_FLAG_BACKWARD)) ExecShutdownNode(planstate); > +static void > +ResOwnerReleaseInstrStack(Datum res) > +{ > + /* > + * XXX: Registered resources are *not* called in reverse order, i.e. we'll > + * get what was first registered first at shutdown. To avoid handling > + * that, we are resetting the stack here on abort (instead of recovering > + * to previous). > + */ > + pgInstrStack = NULL; > +} Hm, doesn't that mean we loose track of instrumentation if you e.g. do an EXPLAIN ANALYZE of a query that executes a function, which internally triggers an error and catches it? I wonder if the solution could be to walk the stack and search for the to-be-released element. Greetings, Andres Freund -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2025-09-09T19:35:43Z
Hi Andres, Thanks for the review! Attached an updated patch set that addresses the feedback, and also adds the complete removal of the global pgBufferUsage variable in later patches (0005-0007), to avoid counting both the stack and the variable. FWIW, pgWalUsage would also be nice to remove, but it has some interesting interactions with the cumulative statistics system and heap_page_prune_and_freeze, and seems less performance critical. On Thu, Sep 4, 2025 at 1:23 PM Andres Freund <andres@anarazel.de> wrote: > > 0001: Separate node instrumentation from other use of Instrumentation > struct > ... > It's mildly odd that the two types of instrumentation have a different > definition of 'total' (one double, one instr_time). > Yeah, agreed. I added in a new 0001 patch that changes this to instr_time consistently. I don't see a good reason to keep the transformation to seconds in the Instrumentation logic, since all in-tree callers convert it to milliseconds anyway. > > 0003: Introduce stack for tracking per-node WAL/buffer usage > > Why are we doing Instr{Start,Stop}Query when not using instrumentation? > Resowner stuff ain't free, so I'd skip them when not necessary. > Makes sense, I've adjusted that to be conditional (in the now renamed 0004 patch). In the updated patch I've also decided to piggyback on QueryDesc totaltime as the "owning" Instrumentation here for the query's lifetime. It seems simpler that way and avoids having special purpose methods. To go along with that I've changed the general purpose Instrumentation struct to use stack-based instrumentation at the same time. > diff --git a/src/backend/executor/execProcnode.c > b/src/backend/executor/execProcnode.c > > index d286471254b..7436f307994 100644 > > --- a/src/backend/executor/execProcnode.c > > +++ b/src/backend/executor/execProcnode.c > > @@ -823,8 +823,17 @@ ExecShutdownNode_walker(PlanState *node, void > *context) > ... > > + InstrNodeAddToCurrent(&node->instrument->stack); > ... > > Can we rely on this being reached? Note that ExecutePlan() calls > ExecShutdownNode() conditionally: You are of course correct, I didn't consider cursors correctly here. It seems there isn't an existing executor node walk that could be repurposed, so I added a new one in ExecutorFinish ("ExecAccumNodeInstrumentation"). From my read of the code there are no use cases where we need aggregated instrumentation data before ExecutorFinish. > +static void > > +ResOwnerReleaseInstrStack(Datum res) > > +{ > > + /* > > + * XXX: Registered resources are *not* called in reverse order, > i.e. we'll > > + * get what was first registered first at shutdown. To avoid > handling > > + * that, we are resetting the stack here on abort (instead of > recovering > > + * to previous). > > + */ > > + pgInstrStack = NULL; > > +} > > Hm, doesn't that mean we loose track of instrumentation if you e.g. do an > EXPLAIN ANALYZE of a query that executes a function, which internally > triggers > an error and catches it? > > I wonder if the solution could be to walk the stack and search for the > to-be-released element. > Yes, good point, I did not consider that case. I've addressed this by only updating the current stack if its not already a parent of the element being released. We are also always adding the element's statistics to the (updated) active stack element at abort. Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2025-10-22T11:28:24Z
On Tue, Sep 9, 2025 at 10:35 PM Lukas Fittl <lukas@fittl.com> wrote: > Attached an updated patch set that addresses the feedback, and also adds > the complete removal of the global pgBufferUsage variable in later patches > (0005-0007), to avoid counting both the stack and the variable. > See attached the same patch set rebased on latest master. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Andres Freund <andres@anarazel.de> — 2025-10-22T12:59:02Z
On 2025-10-22 14:28:24 +0300, Lukas Fittl wrote: > On Tue, Sep 9, 2025 at 10:35 PM Lukas Fittl <lukas@fittl.com> wrote: > > > Attached an updated patch set that addresses the feedback, and also adds > > the complete removal of the global pgBufferUsage variable in later patches > > (0005-0007), to avoid counting both the stack and the variable. > > > > See attached the same patch set rebased on latest master. > From d40f69cce15dfa10479c8be31917b33a49d01477 Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Sun, 31 Aug 2025 16:37:05 -0700 > Subject: [PATCH v3 1/7] Instrumentation: Keep time fields as instrtime, > require caller to convert > > Previously the Instrumentation logic always converted to seconds, only for many > of the callers to do unnecessary division to get to milliseconds. Since an upcoming > refactoring will split the Instrumentation struct, utilize instrtime always to > keep things simpler. LGTM, think we should apply this regardless of the rest of the patches. > @@ -173,14 +169,14 @@ InstrAggNode(Instrumentation *dst, Instrumentation *add) > dst->running = true; > dst->firsttuple = add->firsttuple; > } > - else if (dst->running && add->running && dst->firsttuple > add->firsttuple) > + else if (dst->running && add->running && INSTR_TIME_CMP_LT(dst->firsttuple, add->firsttuple)) > dst->firsttuple = add->firsttuple; This isn't due to this patch, but it seems a bit odd that we use the minimum time for the first tuple, but the average time for the node's completion... > diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h > index f71a851b18d..646934020d1 100644 > --- a/src/include/portability/instr_time.h > +++ b/src/include/portability/instr_time.h > @@ -184,6 +184,8 @@ GetTimerFrequency(void) > #define INSTR_TIME_ACCUM_DIFF(x,y,z) \ > ((x).ticks += (y).ticks - (z).ticks) > > +#define INSTR_TIME_CMP_LT(x,y) \ > + ((x).ticks > (y).ticks) > > #define INSTR_TIME_GET_DOUBLE(t) \ > ((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S) > -- > 2.47.1 Any reason to actually have _CMP_ in the name? Other operations like _ADD don't have such an additional verb in the name. > From 7546f855d138d0dac0d8c22ea5915314810f13e5 Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Sat, 1 Mar 2025 19:31:30 -0800 > Subject: [PATCH v3 2/7] Separate node instrumentation from other use of > Instrumentation struct > > Previously different places (e.g. query "total time") were repurposing > the Instrumentation struct initially introduced for capturing per-node > statistics during execution. This dual use of the struct is confusing, > e.g. by cluttering calls of InstrStartNode/InstrStopNode in unrelated > code paths, and prevents future refactorings. > > Instead, simplify the Instrumentation struct to only track time, > WAL/buffer usage, and tuple counts. Similarly, drop the use of InstrEndLoop > outside of per-node instrumentation. Introduce the NodeInstrumentation > struct to carry forward the per-node instrumentation information. > @@ -381,12 +381,6 @@ explain_ExecutorEnd(QueryDesc *queryDesc) > */ > oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt); > > - /* > - * Make sure stats accumulation is done. (Note: it's okay if several > - * levels of hook all do this.) > - */ > - InstrEndLoop(queryDesc->totaltime); > - > /* Log plan if duration is exceeded. */ > msec = INSTR_TIME_GET_MILLISEC(queryDesc->totaltime->total); > if (msec >= auto_explain_log_min_duration) Maybe add a comment about the removal of these InstrEndLoop() calls to the commit message? If I understand correctly they were superfluous before, but that's not entirely obvious when just looking at the patch. > +/* > + * General purpose instrumentation that can capture time, WAL/buffer usage and tuples > + * > + * Initialized through InstrAlloc, followed by one or more calls to a pair of > + * InstrStart/InstrStop (activity is measured inbetween). > + */ > 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 */ > + /* Internal state keeping: */ > + instr_time starttime; /* start time of last InstrStart */ > + BufferUsage bufusage_start; /* buffer usage at start */ > + WalUsage walusage_start; /* WAL usage at start */ > + /* Accumulated statistics: */ > + instr_time total; /* total runtime */ > + double ntuples; /* total tuples counted in InstrStop */ > + BufferUsage bufusage; /* total buffer usage */ > + WalUsage walusage; /* total WAL usage */ > +} Instrumentation; Maybe add a comment explaining why ntuples is in here? > From aa1acccb3dfa6a5d81a9a049d8cb63762a3d7cf7 Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Tue, 9 Sep 2025 02:16:59 -0700 > Subject: [PATCH v3 4/7] Introduce stack for tracking per-node WAL/buffer usage Could use a commit message :) > --- > .../pg_stat_statements/pg_stat_statements.c | 4 +- > src/backend/commands/explain.c | 8 +- > src/backend/commands/trigger.c | 4 +- > src/backend/executor/execMain.c | 25 ++- > src/backend/executor/execProcnode.c | 29 +++ > src/backend/executor/instrument.c | 199 ++++++++++++++---- > src/include/executor/executor.h | 1 + > src/include/executor/instrument.h | 53 ++++- > 8 files changed, 260 insertions(+), 63 deletions(-) > > diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c > index f43a33b3787..eeabd820d8e 100644 > --- a/contrib/pg_stat_statements/pg_stat_statements.c > +++ b/contrib/pg_stat_statements/pg_stat_statements.c > @@ -1089,8 +1089,8 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) > PGSS_EXEC, > INSTR_TIME_GET_MILLISEC(queryDesc->totaltime->total), > queryDesc->estate->es_total_processed, > - &queryDesc->totaltime->bufusage, > - &queryDesc->totaltime->walusage, > + &INSTR_GET_BUFUSAGE(queryDesc->totaltime), > + &INSTR_GET_WALUSAGE(queryDesc->totaltime), Getting a pointer to something returned by a macro is a bit ugly... Perhaps it'd be better to just pass the &queryDesc->totaltime? But ugh, that's not easily possible given how pgss_planner() currently tracks things :( Maybe it's worth refactoring this a bit in a precursor patch? > @@ -1266,7 +1280,12 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, > resultRelInfo->ri_TrigWhenExprs = (ExprState **) > palloc0(n * sizeof(ExprState *)); > if (instrument_options) > - resultRelInfo->ri_TrigInstrument = InstrAlloc(n, instrument_options); > + { > + if ((instrument_options & INSTRUMENT_TIMER) != 0) > + resultRelInfo->ri_TrigInstrument = InstrAlloc(n, INSTRUMENT_TIMER); > + else > + resultRelInfo->ri_TrigInstrument = InstrAlloc(n, INSTRUMENT_ROWS); > + } > } > else > { I'd not duplicate the InstrAlloc(), but compute the flags separately. > /* ------------------------------------------------------------------------ > @@ -828,6 +829,34 @@ ExecShutdownNode_walker(PlanState *node, void *context) > return false; > } > > +/* > + * ExecAccumNodeInstrumentation > + * > + * Accumulate instrumentation stats from all execution nodes to their respective > + * parents (or the original parent instrumentation stack). > + */ > +void > +ExecAccumNodeInstrumentation(PlanState *node) > +{ > + (void) ExecAccumNodeInstrumentation_walker(node, NULL); > +} I wonder if this is too narrow a name. There might be other uses of a pass across the node tree at that point. OTOH, it's probably better to just rename it at that later point. > +static bool > +ExecAccumNodeInstrumentation_walker(PlanState *node, void *context) > +{ > + if (node == NULL) > + return false; > + > + check_stack_depth(); > + > + planstate_tree_walker(node, ExecAccumNodeInstrumentation_walker, context); There already is a check_stack_depth() in planstate_tree_walker(). > + if (node->instrument && node->instrument->stack.previous) > + InstrStackAdd(node->instrument->stack.previous, &node->instrument->stack); > + > + return false; > +} E.g. in ExecShutdownNode_walker we use planstate_tree_walker(), but then also have special handling for a few node types. Do we need something like that here too? It probably is ok, but it's worth explicitly checking and adding a comment. > +/* > + * Use ResourceOwner mechanism to correctly reset pgInstrStack on abort. > + */ > +static void ResOwnerReleaseInstrumentation(Datum res); > +static const ResourceOwnerDesc instrumentation_resowner_desc = > +{ > + .name = "instrumentation", > + .release_phase = RESOURCE_RELEASE_BEFORE_LOCKS, > + .release_priority = RELEASE_PRIO_FIRST, > + .ReleaseResource = ResOwnerReleaseInstrumentation, > + .DebugPrint = NULL, /* default message is fine */ > +}; Is there a reason to do the release here before the lock release? And why _FIRST? > +static void > +ResOwnerReleaseInstrumentation(Datum res) > +{ > + Instrumentation *instr = (Instrumentation *) DatumGetPointer(res); > + > + /* > + * Because registered resources are *not* called in reverse order, we'll > + * get what was first registered first at shutdown. Thus, on any later > + * resources we need to not change the stack, which was already set to the > + * correct previous entry. > + */ FWIW, the release order is not guaranteed to be in that order either, e.g. once resowner switches to hashing, it'll essentially be random. > + if (pgInstrStack && !StackIsParent(pgInstrStack, &instr->stack)) > + pgInstrStack = instr->stack.previous; Hm - this is effectively O(stack-depth^2), right? It's probably fine, given that we have fairly limited nesting (explain + pg_stat_statements + auto_explain is probably the current max), but seems worth noting in a comment? > + /* > + * Always accumulate all collected stats before the abort, even if we > + * already walked up the stack with an earlier resource. > + */ > + if (pgInstrStack) > + InstrStackAdd(pgInstrStack, &instr->stack); Why are we accumulating stats in case of errors? It's probably fine, but doing less as part of cleanup is pre ferrable... > /* General purpose instrumentation handling */ > Instrumentation * > InstrAlloc(int n, int instrument_options) > { > - Instrumentation *instr; > + Instrumentation *instr = NULL; > + bool need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0; > + bool need_wal = (instrument_options & INSTRUMENT_WAL) != 0; > + bool need_timer = (instrument_options & INSTRUMENT_TIMER) != 0; > + int i; > + > + /* > + * If resource owner will be used, we must allocate in the transaction > + * context (not the calling context, usually a lower context), because the > + * memory might otherwise be freed too early in an abort situation. > + */ > + if (need_buffers || need_wal) > + instr = MemoryContextAllocZero(CurTransactionContext, n * sizeof(Instrumentation)); > + else > + instr = palloc0(n * sizeof(Instrumentation)); Is this long-lived enough? I'm e.g. wondering about utility statements that internally starting transactions, wouldn't that cause problems with a user like pgss tracking something like CIC? > - /* initialize all fields to zeroes, then modify as needed */ > - instr = palloc0(n * sizeof(Instrumentation)); > - if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER | INSTRUMENT_WAL)) > + for (i = 0; i < n; i++) > { > - bool need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0; > - bool need_wal = (instrument_options & INSTRUMENT_WAL) != 0; > - bool need_timer = (instrument_options & INSTRUMENT_TIMER) != 0; > - int i; > - > - for (i = 0; i < n; i++) > - { > - instr[i].need_bufusage = need_buffers; > - instr[i].need_walusage = need_wal; > - instr[i].need_timer = need_timer; > - } > + instr[i].need_bufusage = need_buffers; > + instr[i].need_walusage = need_wal; > + instr[i].need_timer = need_timer; > } > > return instr; > } > + > void > InstrStart(Instrumentation *instr) > { > + Assert(!instr->finalized); > + > if (instr->need_timer && > !INSTR_TIME_SET_CURRENT_LAZY(instr->starttime)) > elog(ERROR, "InstrStart called twice in a row"); > > - if (instr->need_bufusage) > - instr->bufusage_start = pgBufferUsage; > - > - if (instr->need_walusage) > - instr->walusage_start = pgWalUsage; > + if (instr->need_bufusage || instr->need_walusage) > + InstrPushStackResource(instr); > } > + > void > -InstrStop(Instrumentation *instr, double nTuples) > +InstrStop(Instrumentation *instr, double nTuples, bool finalize) > { > instr_time endtime; > > @@ -84,14 +178,15 @@ InstrStop(Instrumentation *instr, double nTuples) > INSTR_TIME_SET_ZERO(instr->starttime); > } > > - /* Add delta of buffer usage since entry to node's totals */ > - if (instr->need_bufusage) > - BufferUsageAccumDiff(&instr->bufusage, > - &pgBufferUsage, &instr->bufusage_start); > + if (instr->need_bufusage || instr->need_walusage) > + InstrPopStackResource(instr); > > - if (instr->need_walusage) > - WalUsageAccumDiff(&instr->walusage, > - &pgWalUsage, &instr->walusage_start); > + if (finalize) > + { > + instr->finalized = true; > + if (pgInstrStack) > + InstrStackAdd(pgInstrStack, &instr->stack); > + } > } > > /* Allocate new node instrumentation structure(s) */ > @@ -139,12 +234,14 @@ InstrStartNode(NodeInstrumentation * instr) > !INSTR_TIME_SET_CURRENT_LAZY(instr->starttime)) > elog(ERROR, "InstrStartNode called twice in a row"); > > - /* save buffer usage totals at node entry, if needed */ > - if (instr->need_bufusage) > - instr->bufusage_start = pgBufferUsage; > + if (instr->need_bufusage || instr->need_walusage) > + { > + /* Ensure that we always have a parent, even at the top most node */ > + Assert(pgInstrStack != NULL); > > - if (instr->need_walusage) > - instr->walusage_start = pgWalUsage; > + instr->stack.previous = pgInstrStack; > + pgInstrStack = &instr->stack; > + } > } > > /* Exit from a plan node */ > @@ -169,14 +266,12 @@ InstrStopNode(NodeInstrumentation * instr, double nTuples) > INSTR_TIME_SET_ZERO(instr->starttime); > } > > - /* Add delta of buffer usage since entry to node's totals */ > - if (instr->need_bufusage) > - BufferUsageAccumDiff(&instr->bufusage, > - &pgBufferUsage, &instr->bufusage_start); > - > - if (instr->need_walusage) > - WalUsageAccumDiff(&instr->walusage, > - &pgWalUsage, &instr->walusage_start); > + if (instr->need_bufusage || instr->need_walusage) > + { > + /* Ensure that we always have a parent, even at the top most node */ > + Assert(instr->stack.previous != NULL); > + pgInstrStack = instr->stack.previous; > + } > > /* Is this the first tuple of this cycle? */ > if (!instr->running) > @@ -253,10 +348,20 @@ InstrAggNode(NodeInstrumentation * dst, NodeInstrumentation * add) > > /* Add delta of buffer usage since entry to node's totals */ > if (dst->need_bufusage) > - BufferUsageAdd(&dst->bufusage, &add->bufusage); > + BufferUsageAdd(&dst->stack.bufusage, &add->stack.bufusage); > > if (dst->need_walusage) > - WalUsageAdd(&dst->walusage, &add->walusage); > + WalUsageAdd(&dst->stack.walusage, &add->stack.walusage); > +} > + > +void > +InstrStackAdd(InstrStack * dst, InstrStack * add) > +{ > + Assert(dst != NULL); > + Assert(add != NULL); > + > + BufferUsageAdd(&dst->bufusage, &add->bufusage); > + WalUsageAdd(&dst->walusage, &add->walusage); > } > Do we want to do BufferUsageAdd() etc even if we are not tracking buffer usage? Those operations aren't cheap... > /* note current values during parallel executor startup */ > @@ -281,6 +386,14 @@ InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage) > void > InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage) > { > + if (pgInstrStack != NULL) > + { > + InstrStack *dst = pgInstrStack; > + > + BufferUsageAdd(&dst->bufusage, bufusage); > + WalUsageAdd(&dst->walusage, walusage); > + } > + > BufferUsageAdd(&pgBufferUsage, bufusage); > WalUsageAdd(&pgWalUsage, walusage); > } Is the pgInstrStack == NULL case actually reachable? > diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h > index 78d3653997b..d04607ce40c 100644 > --- a/src/include/executor/instrument.h > +++ b/src/include/executor/instrument.h > @@ -14,6 +14,7 @@ > #define INSTRUMENT_H > > #include "portability/instr_time.h" > +#include "utils/resowner.h" I'd probably not include resowner here but just forward declare the typedef. > @@ -146,26 +161,46 @@ 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 InstrStackAdd(InstrStack * dst, InstrStack * add); > extern void WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, > const WalUsage *sub); > > +#define INSTR_GET_BUFUSAGE(instr) \ > + instr->stack.bufusage > + > +#define INSTR_GET_WALUSAGE(instr) \ > + instr->stack.walusage Not convinced that having these macros is worthwhile. At this point I reached return -ENEEDCOFFEE :) Greetings, Andres Freund -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2025-10-31T07:18:04Z
Hi Andres, Thanks for the detailed review! Attached v4 patchset that addresses feedback (unless otherwise noted below) and is rebased on master. Other changes: - Ensured each patch is individually pgindent clean (and compiles) - Refactored 0003 a bit to consistently use InstrPushStack/InstrPopStack helpers for modifying the active stack entry - Building on that refactoring, merged v3/0006 "Introduce alternate Instrumentation stack mechanism relying on PG_FINALLY" into the main commit introducing the stack mechanism (the "alternate" mechanism is just using these helpers directly and making sure InstrPopStack is called via PG_FINALLY, instead of using resource owners) - Per our off-list conversation at PGConf.EU, added a patch (v4/0007) that illustrates how the stack mechanism can be used to separate index and table buffer accesses in the EXPLAIN for Index Scans On Wed, Oct 22, 2025 at 5:59 AM Andres Freund <andres@anarazel.de> wrote: > > +/* > > + * General purpose instrumentation that can capture time, WAL/buffer > usage and tuples > > + * > > + * Initialized through InstrAlloc, followed by one or more calls to a > pair of > > + * InstrStart/InstrStop (activity is measured inbetween). > > + */ > > 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 > */ > > + /* Internal state keeping: */ > > + instr_time starttime; /* start time of last > InstrStart */ > > + BufferUsage bufusage_start; /* buffer usage at start */ > > + WalUsage walusage_start; /* WAL usage at start */ > > + /* Accumulated statistics: */ > > + instr_time total; /* total runtime */ > > + double ntuples; /* total tuples counted in > InstrStop */ > > + BufferUsage bufusage; /* total buffer usage */ > > + WalUsage walusage; /* total WAL usage */ > > +} Instrumentation; > > Maybe add a comment explaining why ntuples is in here? > After thinking about this some more, I'd think we should just go ahead and special case trigger instrumentation, and specifically count firings of the trigger (which was counted in "ntuples" before). I've adjusted the 0002 patch accordingly to split out both node and trigger instrumentation. > > > > > --- > > .../pg_stat_statements/pg_stat_statements.c | 4 +- > > src/backend/commands/explain.c | 8 +- > > src/backend/commands/trigger.c | 4 +- > > src/backend/executor/execMain.c | 25 ++- > > src/backend/executor/execProcnode.c | 29 +++ > > src/backend/executor/instrument.c | 199 ++++++++++++++---- > > src/include/executor/executor.h | 1 + > > src/include/executor/instrument.h | 53 ++++- > > 8 files changed, 260 insertions(+), 63 deletions(-) > > > > diff --git a/contrib/pg_stat_statements/pg_stat_statements.c > b/contrib/pg_stat_statements/pg_stat_statements.c > > index f43a33b3787..eeabd820d8e 100644 > > --- a/contrib/pg_stat_statements/pg_stat_statements.c > > +++ b/contrib/pg_stat_statements/pg_stat_statements.c > > @@ -1089,8 +1089,8 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) > > PGSS_EXEC, > > > INSTR_TIME_GET_MILLISEC(queryDesc->totaltime->total), > > queryDesc->estate->es_total_processed, > > - &queryDesc->totaltime->bufusage, > > - &queryDesc->totaltime->walusage, > > + > &INSTR_GET_BUFUSAGE(queryDesc->totaltime), > > + > &INSTR_GET_WALUSAGE(queryDesc->totaltime), > > Getting a pointer to something returned by a macro is a bit ugly... Perhaps > it'd be better to just pass the &queryDesc->totaltime? But ugh, that's not > easily possible given how pgss_planner() currently tracks things :( > > Maybe it's worth refactoring this a bit in a precursor patch? > I've dropped the macro (its just one additional indirection after all) - I think we could refactor this further (i.e. pass the stack), but that doesn't seem strictly necessary. > /* > ------------------------------------------------------------------------ > > @@ -828,6 +829,34 @@ ExecShutdownNode_walker(PlanState *node, void > *context) > > return false; > > } > > > > +/* > > + * ExecAccumNodeInstrumentation > > + * > > + * Accumulate instrumentation stats from all execution nodes to their > respective > > + * parents (or the original parent instrumentation stack). > > + */ > > +void > > +ExecAccumNodeInstrumentation(PlanState *node) > > +{ > > + (void) ExecAccumNodeInstrumentation_walker(node, NULL); > > +} > > I wonder if this is too narrow a name. There might be other uses of a pass > across the node tree at that point. OTOH, it's probably better to just > rename > it at that later point. > Yeah, I can't think of a better name, so I've left this the same for now. > > > + if (node->instrument && node->instrument->stack.previous) > > + InstrStackAdd(node->instrument->stack.previous, > &node->instrument->stack); > > + > > + return false; > > +} > > E.g. in ExecShutdownNode_walker we use planstate_tree_walker(), but then > also > have special handling for a few node types. Do we need something like that > here too? It probably is ok, but it's worth explicitly checking and > adding a > comment. > I went through and double checked - we don't need to special case these node types in my understanding, and I couldn't see any specific cases where intermediary nodes would be removed in shutdown either (o.e. causing dropped stats since a node was removed with its associated stats not being added to the parent yet). I added a comment to make it clear this must run after ExecShutdownNode. > > +/* > > + * Use ResourceOwner mechanism to correctly reset pgInstrStack on abort. > > + */ > > +static void ResOwnerReleaseInstrumentation(Datum res); > > +static const ResourceOwnerDesc instrumentation_resowner_desc = > > +{ > > + .name = "instrumentation", > > + .release_phase = RESOURCE_RELEASE_BEFORE_LOCKS, > > + .release_priority = RELEASE_PRIO_FIRST, > > + .ReleaseResource = ResOwnerReleaseInstrumentation, > > + .DebugPrint = NULL, /* default message is fine > */ > > +}; > > Is there a reason to do the release here before the lock release? And why > _FIRST? > Adjusted to have its own phase, and after lock release. > > + if (pgInstrStack && !StackIsParent(pgInstrStack, &instr->stack)) > > + pgInstrStack = instr->stack.previous; > > Hm - this is effectively O(stack-depth^2), right? It's probably fine, > given > that we have fairly limited nesting (explain + pg_stat_statements + > auto_explain is probably the current max), but seems worth noting in a > comment? > Yeah, I added a comment - I don't see a case where this is a bottleneck today given the limited nesting of resource owner using stacks. > > + /* > > + * Always accumulate all collected stats before the abort, even if > we > > + * already walked up the stack with an earlier resource. > > + */ > > + if (pgInstrStack) > > + InstrStackAdd(pgInstrStack, &instr->stack); > > Why are we accumulating stats in case of errors? It's probably fine, but > doing > less as part of cleanup is pre ferrable... > In my understanding, we need to do this in case of functions called in a query that catch a rollback/error, since we'd otherwise not account for that function's activity as part of the top-level query. > /* General purpose instrumentation handling */ > > Instrumentation * > > InstrAlloc(int n, int instrument_options) > > { > ... > > + if (need_buffers || need_wal) > > + instr = MemoryContextAllocZero(CurTransactionContext, n * > sizeof(Instrumentation)); > > + else > > + instr = palloc0(n * sizeof(Instrumentation)); > > Is this long-lived enough? I'm e.g. wondering about utility statements that > internally starting transactions, wouldn't that cause problems with a user > like pgss tracking something like CIC? > I ended up refactoring this a bit, since it seemed useful to do an explicit pfree at InstrStop or when aborting, both to avoid leaks, and to theoretically support using TopMemoryContext here. That said, from my testing I think CurTransactionContext is sufficient, because we just need something that lives long enough during resource owner abort situations (e.g. per-query context doesn't work, since the abort frees it before we do our resource owner handling). The pgss+CIC case isn't relevant here (I think), because utility statements don't use the resource owner mechanism at all (with the exception of EXPLAIN which calls into ExecutorStart), instead we use a PG_TRY/PG_FINALLY in pg_stat_statements to pop the stack. > > +void > > +InstrStackAdd(InstrStack * dst, InstrStack * add) > > +{ > > + Assert(dst != NULL); > > + Assert(add != NULL); > > + > > + BufferUsageAdd(&dst->bufusage, &add->bufusage); > > + WalUsageAdd(&dst->walusage, &add->walusage); > > } > > > > Do we want to do BufferUsageAdd() etc even if we are not tracking buffer > usage? Those operations aren't cheap... > I briefly considered whether we could add this to the InstrStack itself (i.e. whether we actually care about buffer, WAL usage or both), but I think where it gets messy is that we can have indirect requirements to track this - you might have pg_stat_statements capturing both, but e.g. the utility statement being executed only caring about emitting WAL usage in the log. I'm also not familiar with an in-core use case today where only WAL (but not buffers) is needed, short of doing something like "EXPLAIN (ANALYZE, BUFFERS OFF, WAL ON)" without having pg_stat_statements or similar enabled. Do you have a specific example where this could help? > /* note current values during parallel executor startup */ > > @@ -281,6 +386,14 @@ InstrEndParallelQuery(BufferUsage *bufusage, > WalUsage *walusage) > > void > > InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage) > > { > > + if (pgInstrStack != NULL) > > + { > > + InstrStack *dst = pgInstrStack; > > + > > + BufferUsageAdd(&dst->bufusage, bufusage); > > + WalUsageAdd(&dst->walusage, walusage); > > + } > > + > > BufferUsageAdd(&pgBufferUsage, bufusage); > > WalUsageAdd(&pgWalUsage, walusage); > > } > > Is the pgInstrStack == NULL case actually reachable? > In my reading of the code, its necessary because we unconditionally track WAL/buffer usage in parallel workers, even if the leader doesn't actually need it. We could be smarter about this (i.e. tell the workers not to collect the information in the first place), but for now it seemed easiest to just discard it. Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Andres Freund <andres@anarazel.de> — 2026-01-09T19:38:30Z
Hi, On 2025-10-31 00:18:04 -0700, Lukas Fittl wrote: > Attached v4 patchset that addresses feedback (unless otherwise noted below) > and is rebased on master. Other changes: > > [...] > - Per our off-list conversation at PGConf.EU, added a patch (v4/0007) that > illustrates how the stack mechanism can be used to separate index and table > buffer accesses in the EXPLAIN for Index Scans Nice! I pushed 0001. The only changes I made were to break a few long lines. > From 324666b35d4513676783f0c352ad3a27371c08d8 Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Sat, 1 Mar 2025 19:31:30 -0800 > Subject: [PATCH v4 2/7] Separate node and trigger instrumentation from other > use of Instrumentation struct > > Previously different places (e.g. query "total time") were repurposing > the Instrumentation struct initially introduced for capturing per-node > statistics during execution. This overuse of the same struct is confusing, > e.g. by cluttering calls of InstrStartNode/InstrStopNode in unrelated > code paths, and prevents future refactorings. > > Instead, simplify the Instrumentation struct to only track time and > WAL/buffer usage. Similarly, drop the use of InstrEndLoop outside of > per-node instrumentation - these calls were added without any apparent > benefit since the relevant fields were never read. > > Introduce the NodeInstrumentation struct to carry forward the per-node > instrumentation information, and introduce TriggerInstrumentation to > capture trigger timing and firings (previously counted in "ntuples"). Hm. It looks to me that after moving trigger instrumentation to its own thing, there are no users of InstrAlloc() with n > 1. I think it may make sense to drop that? > diff --git a/src/backend/executor/execParallel.c b/src/backend/executor/execParallel.c > index f098a5557cf..e87810d292e 100644 > --- a/src/backend/executor/execParallel.c > +++ b/src/backend/executor/execParallel.c > @@ -85,7 +85,7 @@ typedef struct FixedParallelExecutorState > * instrument_options: Same meaning here as in instrument.c. > * > * instrument_offset: Offset, relative to the start of this structure, > - * of the first Instrumentation object. This will depend on the length of > + * of the first NodeInstrumentation object. This will depend on the length of > * the plan_node_id array. > * > * num_workers: Number of workers. > @@ -102,11 +102,15 @@ struct SharedExecutorInstrumentation > int num_workers; > int num_plan_nodes; > int plan_node_id[FLEXIBLE_ARRAY_MEMBER]; > - /* array of num_plan_nodes * num_workers Instrumentation objects follows */ > + > + /* > + * array of num_plan_nodes * num_workers NodeInstrumentation objects > + * follows > + */ > }; Spurious change, I think? > + > +/* Trigger instrumentation handling */ > +TriggerInstrumentation * > +InstrAllocTrigger(int n, int instrument_options) > +{ > + TriggerInstrumentation *tginstr = palloc0(n * sizeof(TriggerInstrumentation)); > + bool need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0; > + bool need_wal = (instrument_options & INSTRUMENT_WAL) != 0; > + bool need_timer = (instrument_options & INSTRUMENT_TIMER) != 0; > + int i; > + > + for (i = 0; i < n; i++) > + { > + tginstr[i].instr.need_bufusage = need_buffers; > + tginstr[i].instr.need_walusage = need_wal; > + tginstr[i].instr.need_timer = need_timer; > + } > + > + return tginstr; Hm. Not that it's a huge difference, but I wonder if we ought to use InstrInit() here and in InstrAlloc(), InstrAllocNode(), to avoid repetition? > +/* Trigger instrumentation */ > +typedef struct TriggerInstrumentation > +{ > + Instrumentation instr; > + int firings; /* number of times the instrumented trigger > + * was fired */ > +} TriggerInstrumentation; > + > +/* > + * Specialized instrumentation for per-node execution statistics > + */ > +typedef struct NodeInstrumentation > { > /* Parameters set at node creation: */ > bool need_timer; /* true if we need timer data */ > @@ -92,25 +125,34 @@ typedef struct Instrumentation > double nfiltered2; /* # of tuples removed by "other" quals */ > BufferUsage bufusage; /* total buffer usage */ > WalUsage walusage; /* total WAL usage */ > -} Instrumentation; > +} NodeInstrumentation; The indentation here will look better if you add TriggerInstrumentation, NodeInstrumentation to typedefs.list > typedef struct WorkerInstrumentation > { > int num_workers; /* # of structures that follow */ > - Instrumentation instrument[FLEXIBLE_ARRAY_MEMBER]; > + NodeInstrumentation instrument[FLEXIBLE_ARRAY_MEMBER]; > } WorkerInstrumentation; Hm. Shouldn't this be WorkerNodeInstrumentation now? > From 74f44adc505a436a65d6069b286c8a878d4fe4af Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Sun, 31 Aug 2025 16:34:42 -0700 > Subject: [PATCH v4 3/7] Replace direct changes of pgBufferUsage/pgWalUsage > with INSTR_* macros Looks sane to me. I'd move that to the head of the queue in the next revision. > From e03c96cbd3079c03ae63b6427937b79edaa9562b Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Tue, 9 Sep 2025 02:16:59 -0700 > Subject: [PATCH v4 4/7] Optimize measuring WAL/buffer usage through > stack-based instrumentation > > 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 the function BufferUsageAccumDiff showing up in profiles and > in some cases adding up to 10% overhead to an EXPLAIN (ANALYZE, BUFFERS) run. > > 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 InstrEndNode. 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 Instrumentation struct, and its associated InstrStart/ > InstrStop helpers (which use resource owners to handle aborts), or dedicated > PG_TRY/PG_FINALLY calls that ensure the stack is in a consistent state after > an abort. I think it may be good to have some tests for edge cases. E.g. testing that a query that an explain analyze of a query that executes a plpgsql function which in turn does another explain analyze or just another query without explain analyze, does something reasonable. > @@ -1089,8 +1074,13 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) > PGSS_EXEC, > INSTR_TIME_GET_MILLISEC(queryDesc->totaltime->total), > queryDesc->estate->es_total_processed, > - &queryDesc->totaltime->bufusage, > - &queryDesc->totaltime->walusage, > + > + /* > + * Check if stack is initialized - it is not when ExecutorRun wasn't > + * called > + */ > + queryDesc->totaltime->stack ? &queryDesc->totaltime->stack->bufusage : NULL, > + queryDesc->totaltime->stack ? &queryDesc->totaltime->stack->walusage : NULL, > queryDesc->estate->es_jit ? &queryDesc->estate->es_jit->instr : NULL, > NULL, > queryDesc->estate->es_parallel_workers_to_launch, Maybe it's just the diff, but this looks a bit odd, indentation wise. > @@ -1266,7 +1280,15 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, > resultRelInfo->ri_TrigWhenExprs = (ExprState **) > palloc0(n * sizeof(ExprState *)); > if (instrument_options) > - resultRelInfo->ri_TrigInstrument = InstrAllocTrigger(n, instrument_options); > + { > + /* > + * Triggers do not individually track buffer/WAL usage, even if > + * otherwise tracked > + */ Why is that? > @@ -59,15 +125,31 @@ InstrStart(Instrumentation *instr) > !INSTR_TIME_SET_CURRENT_LAZY(instr->starttime)) > elog(ERROR, "InstrStart called twice in a row"); > > - if (instr->need_bufusage) > - instr->bufusage_start = pgBufferUsage; > + if (instr->need_bufusage || instr->need_walusage) > + { > + Assert(CurrentResourceOwner != NULL); > + instr->owner = CurrentResourceOwner; > + > + /* > + * Allocate the stack resource in a memory context that survives > + * during an abort. This will be freed by InstrStop (regular > + * execution) or ResOwnerReleaseInstrumentation (abort). > + * > + * We don't do this in InstrAlloc to avoid leaking when InstrStart + > + * InstrStop isn't called. > + */ > + if (instr->stack == NULL) > + instr->stack = MemoryContextAllocZero(CurTransactionContext, sizeof(InstrStack)); > > - if (instr->need_walusage) > - instr->walusage_start = pgWalUsage; > + ResourceOwnerEnlarge(instr->owner); > + ResourceOwnerRememberInstrStack(instr->owner, instr->stack); > + > + InstrPushStack(instr->stack); > + } > } I'm still worried that allocating something in CurTransactionContext will bite us eventually. It seems like it'd be pretty sane to want to have instrumentation around procedure execution, for example. > void > -InstrStop(Instrumentation *instr) > +InstrStop(Instrumentation *instr, bool finalize) > { > instr_time endtime; > > @@ -83,14 +165,28 @@ InstrStop(Instrumentation *instr) > INSTR_TIME_SET_ZERO(instr->starttime); > } > > - /* Add delta of buffer usage since entry to node's totals */ > - if (instr->need_bufusage) > - BufferUsageAccumDiff(&instr->bufusage, > - &pgBufferUsage, &instr->bufusage_start); > + if (instr->need_bufusage || instr->need_walusage) > + { > + InstrPopStack(instr->stack, finalize); > > - if (instr->need_walusage) > - WalUsageAccumDiff(&instr->walusage, > - &pgWalUsage, &instr->walusage_start); > + Assert(instr->owner != NULL); > + ResourceOwnerForgetInstrStack(instr->owner, instr->stack); > + instr->owner = NULL; > + > + if (finalize) > + { > + /* > + * To avoid keeping memory allocated beyond when its needed, copy > + * the result to the current memory context, and free it in the > + * transaction context. > + */ > + InstrStack *stack = palloc(sizeof(InstrStack)); > + > + memcpy(stack, instr->stack, sizeof(InstrStack)); > + pfree(instr->stack); > + instr->stack = stack; > + } > + } > } Hm. I'm not entirely sure I understand the gain due to the palloc & copy & pfree. Won't that typically increase memory usage due to temporarily having two versions of the InstrStack? > /* Trigger instrumentation handling */ > @@ -98,15 +194,20 @@ TriggerInstrumentation * > InstrAllocTrigger(int n, int instrument_options) > { > TriggerInstrumentation *tginstr = palloc0(n * sizeof(TriggerInstrumentation)); > - bool need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0; > - bool need_wal = (instrument_options & INSTRUMENT_WAL) != 0; > bool need_timer = (instrument_options & INSTRUMENT_TIMER) != 0; > int i; > > + /* > + * To avoid having to determine when the last trigger fired, we never > + * track WAL/buffer usage for now > + */ > + Assert((instrument_options & INSTRUMENT_BUFFERS) == 0); > + Assert((instrument_options & INSTRUMENT_WAL) == 0); > + > for (i = 0; i < n; i++) > { > - tginstr[i].instr.need_bufusage = need_buffers; > - tginstr[i].instr.need_walusage = need_wal; > + tginstr[i].instr.need_bufusage = false; > + tginstr[i].instr.need_walusage = false; > tginstr[i].instr.need_timer = need_timer; > } > That does seem problematic to me. > @@ -400,21 +398,22 @@ InstrAggNode(NodeInstrumentation * dst, NodeInstrumentation * add) > } > > /* start instrumentation during parallel executor startup */ > -void > +Instrumentation * > InstrStartParallelQuery(void) > { > - save_pgBufferUsage = pgBufferUsage; > - save_pgWalUsage = pgWalUsage; > + Instrumentation *instr = InstrAlloc(1, INSTRUMENT_BUFFERS | INSTRUMENT_WAL); > + > + InstrStart(instr); > + return instr; > } > /* report usage after parallel executor shutdown */ > void > -InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage) > +InstrEndParallelQuery(Instrumentation *instr, BufferUsage *bufusage, WalUsage *walusage) > { > - memset(bufusage, 0, sizeof(BufferUsage)); > - BufferUsageAccumDiff(bufusage, &pgBufferUsage, &save_pgBufferUsage); > - memset(walusage, 0, sizeof(WalUsage)); > - WalUsageAccumDiff(walusage, &pgWalUsage, &save_pgWalUsage); > + InstrStop(instr, true); > + memcpy(bufusage, &instr->stack->bufusage, sizeof(BufferUsage)); > + memcpy(walusage, &instr->stack->walusage, sizeof(WalUsage)); > } Wonder if we should slap a pg_nodiscard on InstrStartParallelQuery() to make it easier for extensions to notice this? OTOH, InstrEndParallelQuery() will make that pretty clear... > 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; > @@ -975,19 +976,17 @@ heap_vacuum_rel(Relation rel, const VacuumParams params, > int64 total_blks_hit; > int64 total_blks_read; > int64 total_blks_dirtied; > + BufferUsage bufusage = instr->stack->bufusage; > + WalUsage walusage = instr->stack->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; > - total_blks_read = bufferusage.shared_blks_read + > - bufferusage.local_blks_read; > - total_blks_dirtied = bufferusage.shared_blks_dirtied + > - bufferusage.local_blks_dirtied; > + > + 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; Why rename and move the declaration of bufferusage here? That seems to make the diff unnecessarily noisy? Kinda going the other way: Why copy this on the stack, rather than use a pointer? > diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c > index 34b6410d6a2..77b4c59e71c 100644 > --- a/src/backend/commands/prepare.c > +++ b/src/backend/commands/prepare.c > @@ -578,14 +578,16 @@ 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 *instr = NULL; > MemoryContextCounters mem_counters; > MemoryContext planner_ctx = NULL; > MemoryContext saved_ctx = NULL; > > + if (es->buffers) > + instr = InstrAlloc(1, INSTRUMENT_TIMER | INSTRUMENT_BUFFERS); > + else > + instr = InstrAlloc(1, INSTRUMENT_TIMER); I'd not duplicate the call to InstrAlloc(). > From ccea6e453872a0ae63351b3ba4360845035ec621 Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Thu, 30 Oct 2025 22:27:30 -0700 > Subject: [PATCH v4 7/7] Index scans: Split heap and index buffer access > reporting in EXPLAIN > > This makes it clear whether activity was on the index directly, or > on the table based on heap fetches. Yay^2. > --- > src/backend/commands/explain.c | 56 ++++++++++++++++------------ > src/backend/executor/execProcnode.c | 13 +++++++ > src/backend/executor/instrument.c | 25 +++++++++++++ > src/backend/executor/nodeIndexscan.c | 15 +++++++- > src/include/access/genam.h | 3 ++ > src/include/executor/instrument.h | 3 ++ > 6 files changed, 91 insertions(+), 24 deletions(-) > > diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c > index dd3bf615581..fb96dd5248c 100644 > diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c > index d00cf820a27..f19af428d97 100644 > --- a/src/backend/executor/execProcnode.c > +++ b/src/backend/executor/execProcnode.c > @@ -854,7 +854,20 @@ ExecAccumNodeInstrumentation_walker(PlanState *node, void *context) > planstate_tree_walker(node, ExecAccumNodeInstrumentation_walker, context); > > if (node->instrument && node->instrument->stack.previous) > + { Perhaps we should instead (probably in the earlier patch) just make the function return early if we don't have instrumentation / a previous node? We might gain a few more special cases, and it's nice if they're less indented. > + /* > + * Index Scan nodes account for heap buffer usage separately, so we > + * need to explitly add here > + */ s/heap/table/ Greetings, Andres Freund -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-01-13T08:01:53Z
On Fri, Jan 9, 2026 at 11:38 AM Andres Freund <andres@anarazel.de> wrote: > I pushed 0001. The only changes I made were to break a few long lines. Thanks! Attached v5, feedback addressed unless otherwise noted, with the patch adding macros to access pgBufferUsage/pgWalUsage (was v4/0003) to the front per your request. Its also worth noting that 2defd0006255 just added a new "instrument_node.h". We could consider moving the per-node instrumentation structs and associated functions there (but probably keep a single "instrument.c" unit file?). Thoughts? > Hm. It looks to me that after moving trigger instrumentation to its own thing, > there are no users of InstrAlloc() with n > 1. I think it may make sense to > drop that? Yep, makes sense, done like that. I also did a code search for any extension use cases and couldn't find anything that'd need multiples of the Instrumentation struct (either the new general purpose one, or the per-node one). > > +++ b/src/backend/executor/execParallel.c > > ... > > - /* array of num_plan_nodes * num_workers Instrumentation objects follows */ > > + > > + /* > > + * array of num_plan_nodes * num_workers NodeInstrumentation objects > > + * follows > > + */ > > }; > > Spurious change, I think? pgindent forces the line break here, because of the Instrumentation => NodeInstrumentation change. Are you saying we shouldn't make that wording change? then I'd suggest we lower case the "i" of "instrumentation", so it doesn't get confused with the struct of that name. > > typedef struct WorkerInstrumentation > > { > > int num_workers; /* # of structures that follow */ > > - Instrumentation instrument[FLEXIBLE_ARRAY_MEMBER]; > > + NodeInstrumentation instrument[FLEXIBLE_ARRAY_MEMBER]; > > } WorkerInstrumentation; > > Hm. Shouldn't this be WorkerNodeInstrumentation now? Yeah, the name feels a bit lengthy, but given that I found some of the parallel query instrumentation logic confusing, erring on the side of being more explicit is probably good here. Done that way. > > Subject: [PATCH v4 4/7] Optimize measuring WAL/buffer usage through > > stack-based instrumentation > > I think it may be good to have some tests for edge cases. E.g. testing that a > query that an explain analyze of a query that executes a plpgsql function > which in turn does another explain analyze or just another query without > explain analyze, does something reasonable. > Yeah, that makes sense - I ran out of time to add this now (and I feel there are other things worth discussing in the meantime), but will work on this. > > @@ -1266,7 +1280,15 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, > > resultRelInfo->ri_TrigWhenExprs = (ExprState **) > > palloc0(n * sizeof(ExprState *)); > > if (instrument_options) > > - resultRelInfo->ri_TrigInstrument = InstrAllocTrigger(n, instrument_options); > > + { > > + /* > > + * Triggers do not individually track buffer/WAL usage, even if > > + * otherwise tracked > > + */ > > Why is that? I originally special cased triggers (i.e. didn't permit trigger instrumentation to track WAL/buffer usage) because the current code does not need it, and it simplified the logic, because we always need to add child stack information to the parent so that totals are correct, e.g. for pg_stat_statements. But, I see your point that this isn't great, and we may want to emit WAL/buffer usage for triggers in EXPLAIN in the future. To handle this I adjusted this so we now also finalize the per-trigger instrumentation in ExecutorFinish, like we do it for per-node instrumentation. > > > > @@ -59,15 +125,31 @@ InstrStart(Instrumentation *instr) > > !INSTR_TIME_SET_CURRENT_LAZY(instr->starttime)) > > elog(ERROR, "InstrStart called twice in a row"); > > > > - if (instr->need_bufusage) > > - instr->bufusage_start = pgBufferUsage; > > + if (instr->need_bufusage || instr->need_walusage) > > + { > > + Assert(CurrentResourceOwner != NULL); > > + instr->owner = CurrentResourceOwner; > > + > > + /* > > + * Allocate the stack resource in a memory context that survives > > + * during an abort. This will be freed by InstrStop (regular > > + * execution) or ResOwnerReleaseInstrumentation (abort). > > + * > > + * We don't do this in InstrAlloc to avoid leaking when InstrStart + > > + * InstrStop isn't called. > > + */ > > + if (instr->stack == NULL) > > + instr->stack = MemoryContextAllocZero(CurTransactionContext, sizeof(InstrStack)); > > > > - if (instr->need_walusage) > > - instr->walusage_start = pgWalUsage; > > + ResourceOwnerEnlarge(instr->owner); > > + ResourceOwnerRememberInstrStack(instr->owner, instr->stack); > > + > > + InstrPushStack(instr->stack); > > + } > > } > > I'm still worried that allocating something in CurTransactionContext will bite > us eventually. It seems like it'd be pretty sane to want to have > instrumentation around procedure execution, for example. Hmm, I'll have to spend more time thinking through that future procedure instrumentation case and how it interacts with resource owners. Just to state it, the main point of using CurTransactionContext (instead of CurrentMemoryContext) here is that we handle an abort situation that may propagate above the function that called InstrStart. We need to make sure memory survives until the resource owner gets cleaned up (either by aborting, or by InstrStop being called with finalize = true), so we can add the stack to its parent. I'm happy to adjust this to TopTransactionContext if that's what you had in mind? Or maybe I'm missing some other way to get a memory context that relates to the current resource owner? (i.e. survives at least until the resource owner gets released) > > void > > -InstrStop(Instrumentation *instr) > > +InstrStop(Instrumentation *instr, bool finalize) > > { > > instr_time endtime; > > > > @@ -83,14 +165,28 @@ InstrStop(Instrumentation *instr) > > INSTR_TIME_SET_ZERO(instr->starttime); > > } > > > > - /* Add delta of buffer usage since entry to node's totals */ > > - if (instr->need_bufusage) > > - BufferUsageAccumDiff(&instr->bufusage, > > - &pgBufferUsage, &instr->bufusage_start); > > + if (instr->need_bufusage || instr->need_walusage) > > + { > > + InstrPopStack(instr->stack, finalize); > > > > - if (instr->need_walusage) > > - WalUsageAccumDiff(&instr->walusage, > > - &pgWalUsage, &instr->walusage_start); > > + Assert(instr->owner != NULL); > > + ResourceOwnerForgetInstrStack(instr->owner, instr->stack); > > + instr->owner = NULL; > > + > > + if (finalize) > > + { > > + /* > > + * To avoid keeping memory allocated beyond when its needed, copy > > + * the result to the current memory context, and free it in the > > + * transaction context. > > + */ > > + InstrStack *stack = palloc(sizeof(InstrStack)); > > + > > + memcpy(stack, instr->stack, sizeof(InstrStack)); > > + pfree(instr->stack); > > + instr->stack = stack; > > + } > > + } > > } > > Hm. I'm not entirely sure I understand the gain due to the palloc & copy & > pfree. Won't that typically increase memory usage due to temporarily having > two versions of the InstrStack? This is mainly about making the caller to InstrStop take responsibility for freeing the memory allocation when its current context gets freed, which will potentially be before CurTransactionContext (or whichever context we chose) gets freed. If we kept it around and e.g. this was a long transaction with many queries executed, we'd keep consuming more and more memory otherwise. Or looking at it differently, the principle here is, if you've reached InstrStop (with finalize=true), no aborts involving this stack can occur anymore, and so all that's left is for the caller to utilize the instrumentation data as it sees fit, e.g. emitting it to the logs, etc. > > /* report usage after parallel executor shutdown */ > > void > > -InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage) > > +InstrEndParallelQuery(Instrumentation *instr, BufferUsage *bufusage, WalUsage *walusage) > > Wonder if we should slap a pg_nodiscard on InstrStartParallelQuery() to make > it easier for extensions to notice this? OTOH, InstrEndParallelQuery() will > make that pretty clear... Good point, why not, added pg_nodiscard - seems like cheap insurance to help notice someone they're calling it incorrectly. > > @@ -975,19 +976,17 @@ heap_vacuum_rel(Relation rel, const VacuumParams params, > > int64 total_blks_hit; > > int64 total_blks_read; > > int64 total_blks_dirtied; > > + BufferUsage bufusage = instr->stack->bufusage; > > + WalUsage walusage = instr->stack->walusage; > > ... > > - total_blks_dirtied = bufferusage.shared_blks_dirtied + > > - bufferusage.local_blks_dirtied; > > + > > + total_blks_hit = bufusage.shared_blks_hit + > ... > > Why rename and move the declaration of bufferusage here? That seems to make > the diff unnecessarily noisy? > > Kinda going the other way: Why copy this on the stack, rather than use a > pointer? For now to keep the diff smaller, I went the way of not renaming the variable. I don't think efficiency matters much in that code path (i.e. the copy of ~150 bytes seems fine to me), but happy to adjust if you think a pointer is better. Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Peter Smith <smithpb2250@gmail.com> — 2026-01-15T22:05:44Z
On Sat, Jan 10, 2026 at 6:38 AM Andres Freund <andres@anarazel.de> wrote: > > Hi, > > > On 2025-10-31 00:18:04 -0700, Lukas Fittl wrote: > > Attached v4 patchset that addresses feedback (unless otherwise noted below) > > and is rebased on master. Other changes: > > > > [...] > > - Per our off-list conversation at PGConf.EU, added a patch (v4/0007) that > > illustrates how the stack mechanism can be used to separate index and table > > buffer accesses in the EXPLAIN for Index Scans > > Nice! > > > I pushed 0001. The only changes I made were to break a few long lines. > > I happened to be reading the code in this recent push [1] and saw this new macro: +#define INSTR_TIME_LT(x,y) \ + ((x).ticks > (y).ticks) Is that macro name OK? It seemed backwards to me. Shouldn't it be called INSTR_TIME_GT because it is checking that x is "Greater Than" y? ====== [1] https://github.com/postgres/postgres/commit/e5a5e0a90750d665cab417322b9f85c806430d85#diff-d927962e2574e803c27ea9a429eeecf7bc29c7a38c830ccb3a10e9e3da5ba357R187 Kind Regards. Peter Smith. Fujitsu Australia
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-01-15T22:34:04Z
On Thu, Jan 15, 2026 at 2:06 PM Peter Smith <smithpb2250@gmail.com> wrote: > I happened to be reading the code in this recent push [1] and saw this > new macro: > > +#define INSTR_TIME_LT(x,y) \ > + ((x).ticks > (y).ticks) > > Is that macro name OK? It seemed backwards to me. Shouldn't it be > called INSTR_TIME_GT because it is checking that x is "Greater Than" > y? Oh yeah, good catch. I think I must have thought of "larger than" instead of "less than". I think adjusting that to INSTR_TIME_GT makes sense, and is consistent with how "lt" and "gt" is used elsewhere in the source. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-02-24T04:18:34Z
Hi, Attached v6: 0001 addresses the issue that Peter raised and corrects the macro name + adds a missing comment. 0002/0003 are the same as in v5 and are preparatory commits that should be in good shape to go. 0004 adds new regression tests that pass on both master and the patched version, and stress test some of the nested instrumentation handling. 0005 is what was previously 0003, and introduces the stack-based instrumentation mechanism. I've made several changes here: - Rename pgInstrStack => CurrentInstrStack - Always initialize a top-level stack (TopInstrStack) to avoid condition when writing to stack - Rename ExecAccumNodeInstrumentation to ExecFinalizeNodeInstrumentation, and skip it for parallel workers to avoid double counting (covered by new test cases). The new InstrFinalizeNode method that accompanies this now also copies the per-node instrumentation into the per-query context when in the regular non-abort case. I think this is necessary when we have a long-running transaction with auto_explain enabled and many fast statements, so we don't want to keep NodeInstrumentation until transaction end (since each NodeInstrumentation is ~288 bytes). - Accumulate unfinalized per-node stacks on abort (so we can rely on accumulated totals to be correct) - note that this requires an additional tree walk in the first ExecutorRun because we lazily initialize the query->totaltime stack - Moved the non-node instr stack allocations to TopMemoryContext - after further testing and review I agree that's necessary because of utility statements. The specific test case that showed that was pgss_ProcessUtility and how it behaves with the new utility.sql test case, as well as VACUUM commands in stream regress. - Combined parallel worker changes into this commit (it didn't really make sense to keep these separate based on some of the edge cases) - Explicit handling of orphaned stack entries when we experience out-of-order cleanup during abort - Added a lot more comments (too many?) to explain different edge cases. 0006 could probably be merged into 0005, and is the existing mechanical change to drop the pgBufferUsage global, but kept separate for easier review for now. 0007 is the stack-mechanism for splitting out "Table Buffers" for Index Scans. This has been changed to: - Report combined index/table buffers as "Buffers" and only show "Table Buffers" broken out. This was suggested off-list by Andres, and I've realized this is also otherwise confusing when there are child nodes below that accumulate up. - Fix a bug relating to parallel query reporting where previously the table stack contents would not be copied from parallel workers to the leader. - Add documentation and update EXPLAIN ANALYZE examples that reference Index Scan nodes. 0008 adds a pg_session_buffer_usage() module for testing the global counters. This helps to verify the handling of aborts behave sanely (and can run on both master and patched), but I don't think we should commit this. --- Two questions on my mind: 1) Should we call this "instrumentation context" (InstrContext?) instead of "instrumentation stack" (InstrStack)? When writing comments I found the difference between "stack entry" and "stack" confusing at times, and "context" feels a bit more clear as a term (e.g. as in "CurrentInstrContext" or "CurrentInstrumentationContext"). 2) For 0007, "Table Buffers" feels a bit inconsistent with "Heap Fetches" and "Heap Blocks" used elsewhere, should we potentially use "Heap Buffers", or change the existing names to "Table ..." instead? And one follow-up on a prior note: On Tue, Jan 13, 2026 at 12:01 AM Lukas Fittl <lukas@fittl.com> wrote: > Its also worth noting that 2defd0006255 just added a new > "instrument_node.h". We could consider moving the per-node > instrumentation structs and associated functions there (but probably > keep a single "instrument.c" unit file?). Thoughts? I've consider this again and think that's not a good idea, because instrument_node.h seems specifically focused on parallel query - so I've left all new methods/structs in instrument.h for now. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-08T04:27:38Z
On Mon, Feb 23, 2026 at 8:18 PM Lukas Fittl <lukas@fittl.com> wrote: > 0001 addresses the issue that Peter raised and corrects the macro name > + adds a missing comment. This has been pushed by Andres, thanks again Peter for noting this! See attached v7, with the changes as noted later. But first, some fresh performance numbers that take into account extra inlining added in a new v7/0006: Example (default shared_buffers, runtimes are best out of 3-ish): CREATE TABLE lotsarows(key int not null); INSERT INTO lotsarows SELECT generate_series(1, 50000000); VACUUM FREEZE lotsarows; 250ms actual runtime (no instrumentation) BUFFERS OFF, TIMING OFF: 295ms master 295ms with stack-based instrumentation only (v7/0005) -- no change because BUFFERS OFF 260ms with ExecProcNodeInstr inlining work (v7/0006) BUFFERS ON, TIMING OFF: 380ms master 305ms with stack-based instrumentation only (v7/0005) 280ms with ExecProcNodeInstr inlining work (v7/0006) In summary: For BUFFERS ON, we're going from 52% overhead in this stress test, to 12% overhead (22% without the ExecProcNodeInstr change). With rows instrumentation only, we go from 18% to 3% overhead. > 0002/0003 are the same as in v5 and are preparatory commits that > should be in good shape to go. I split out the trigger instrumentation refactoring into its own commit (0001) per Andres' request off-list. 0002 is the node instrumentation refactoring, which changed slightly, because Instrumentation is now treated as a base struct and NodeInstrumentation now contains an Instrumentation "instr" field to reduce duplication. 0003 replaces pgBufferUsage/pgWalUsage with INSTR_* macros, pretty much unchanged from v6/0002. > 0004 adds new regression tests that pass on both master and the > patched version, and stress test some of the nested instrumentation > handling. This patch is the same in v7 as in v6. > 0005 is what was previously 0003, and introduces the stack-based > instrumentation mechanism. 0005 is still the stack-based instrumentation commit, but has several improvements over v6: - Andres suggested a different stack structure in a conversation off-list, where we track the stack entries in a separately kept array instead of with inline pointers on the Instrumentation structure - that ends up making the whole change a lot easier to reason about, and clarifies the abort handling as well - I've separated out the ResOwner handling into a new "QueryInstrumentation" struct - this makes it clearer that one can use Instrumentation directly with certain caveats (i.e. one must deal with aborts directly), and feels better now that we're including Instrumentation in NodeInstrumentation as well > 0006 could probably be merged into 0005, and is the existing > mechanical change to drop the pgBufferUsage global, but kept separate > for easier review for now. I've merged that together now into 0005 because it feels better to reason about this as a whole and drop pgBufferUsage within the same commit where we're adding the stack-based instrumentation. There is now a new 0006 patch that further optimizes ExecProcNodeInstr (with performance numbers as noted in the beginning of this mail). During my testing I realized that the conditional checks in InstrStartNode/InstrStopNode are quite unnecessary - we never change what gets instrumented during execution, and so we can create specialized functions for the different instrumentation combinations, giving the compiler a much better chance at generating optimal instructions. The assembly here looks a lot better now. > 0007 is the stack-mechanism for splitting out "Table Buffers" for > Index Scans. This stayed pretty much the same from the earlier version, but I reworked this a bit to avoid special Instr functions for dealing with this case, instead it re-uses NodeInstrumentation and InstrStartNode/InstrStopNode. > 0008 adds a pg_session_buffer_usage() module for testing the global > counters. This helps to verify the handling of aborts behave sanely > (and can run on both master and patched), but I don't think we should > commit this. This is identical with v6/0008, but continues to prove very useful in testing the refactorings. > Two questions on my mind: > > 1) Should we call this "instrumentation context" (InstrContext?) > instead of "instrumentation stack" (InstrStack)? When writing comments > I found the difference between "stack entry" and "stack" confusing at > times, and "context" feels a bit more clear as a term (e.g. as in > "CurrentInstrContext" or "CurrentInstrumentationContext"). With the refactoring of the stack-mechanism done now, I think we don't need to change the naming here, since "InstrStack" as a commonly used struct is gone now (its just Instrumentation now), so I'd suggest keeping the "stack" terminology to describe the approach itself. > 2) For 0007, "Table Buffers" feels a bit inconsistent with "Heap > Fetches" and "Heap Blocks" used elsewhere, should we potentially use > "Heap Buffers", or change the existing names to "Table ..." instead? That is still an open question. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-08T04:31:07Z
On Sat, Mar 7, 2026 at 8:27 PM Lukas Fittl <lukas@fittl.com> wrote: > Example (default shared_buffers, runtimes are best out of 3-ish): > > CREATE TABLE lotsarows(key int not null); > INSERT INTO lotsarows SELECT generate_series(1, 50000000); > VACUUM FREEZE lotsarows; > > 250ms actual runtime (no instrumentation) > > BUFFERS OFF, TIMING OFF: > 295ms master > 295ms with stack-based instrumentation only (v7/0005) -- no change > because BUFFERS OFF > 260ms with ExecProcNodeInstr inlining work (v7/0006) > > BUFFERS ON, TIMING OFF: > 380ms master > 305ms with stack-based instrumentation only (v7/0005) > 280ms with ExecProcNodeInstr inlining work (v7/0006) > > In summary: For BUFFERS ON, we're going from 52% overhead in this > stress test, to 12% overhead (22% without the ExecProcNodeInstr > change). With rows instrumentation only, we go from 18% to 3% > overhead. Erm, and I forgot the query here, this is testing "SELECT count(*) FROM lotsarows;", just like over in [0]. Thanks, Lukas [0]: https://www.postgresql.org/message-id/flat/20200612232810.f46nbqkdhbutzqdg@alap3.anarazel.de -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Zsolt Parragi <zsolt.parragi@percona.com> — 2026-03-09T21:55:22Z
Hello + if (queryDesc->totaltime && estate->es_instrument && !IsParallelWorker()) + { + ExecFinalizeNodeInstrumentation(queryDesc->planstate); + + ExecFinalizeTriggerInstrumentation(estate); + } + if (queryDesc->totaltime) - InstrStop(queryDesc->totaltime); + queryDesc->totaltime = InstrQueryStopFinalize(queryDesc->totaltime); In ExecFinalizeNodeInstrumentation InstrFinalizeNode pfrees the original instrumentation, but doesn't remove it from the unfinalized_children list. In normal execution in InstrQueryStopFinalize ResourceOwnerForgetInstrumentation handles this, but what about the error path, if something happens between the two? Won't we end up in ResOwnerReleaseInstrumentation and do use after free reads and then a double free on the now invalid pointer? + if (myState->es->timing || myState->es->buffers) + instr = InstrQueryStopFinalize(instr); + Is it okay to leak 1 instrumentation copy per tuple in the query context? This freshly palloced object will be out of scope a few lines after this. @@ -128,8 +130,22 @@ IndexNext(IndexScanState *node) IndexNextWithReorder doesn't need the same handling? + if (scandesc->xs_heap_continue) + elog(ERROR, "non-MVCC snapshots are not supported in index-only scans"); Shouldn't this say index scans? (there's another preexisting indexonylscan mention in this file, but that also seems wrong) +#if HAVE_INSTR_STACK + usage = &instr_top.bufusage; +#else + usage = &pgBufferUsage; +#endif I don't see pgBufferUsage anywhere else in the current code, it was probably removed between rebases? + char *prefix = title ? psprintf("%s ", title) : pstrdup(""); + + ExplainPropertyInteger(psprintf("%sShared Hit Blocks", prefix), NULL, usage->shared_blks_hit, es); (And many similar ExplainPropery after this) title is NULL most of the time, and this results in 16 allocations for that common case - isn't there a better solution like using ExplainOpenGroup or something? + * 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, instead call InstrPopAndFinalizeStack which can skip intermediate + * stack entries, or instead use InstrStart/InstrStop. InstrPopAndFinalizeStack doesn't exists in the latest patch version -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-09T23:45:55Z
Hi Zsolt, Thanks for reviewing! On Mon, Mar 9, 2026 at 2:55 PM Zsolt Parragi <zsolt.parragi@percona.com> wrote: > + if (queryDesc->totaltime && estate->es_instrument && !IsParallelWorker()) > + { > + ExecFinalizeNodeInstrumentation(queryDesc->planstate); > + > + ExecFinalizeTriggerInstrumentation(estate); > + } > + > if (queryDesc->totaltime) > - InstrStop(queryDesc->totaltime); > + queryDesc->totaltime = InstrQueryStopFinalize(queryDesc->totaltime); > > In ExecFinalizeNodeInstrumentation InstrFinalizeNode pfrees the > original instrumentation, but doesn't remove it from the > unfinalized_children list. In normal execution in > InstrQueryStopFinalize ResourceOwnerForgetInstrumentation handles > this, but what about the error path, if something happens between the > two? > Won't we end up in ResOwnerReleaseInstrumentation and do use after > free reads and then a double free on the now invalid pointer? ResourceOwnerForgetInstrumentation directly follows the call to ExecFinalizeNodeInstrumentation in standard_ExecutorFinish, so I'm not sure which error case you're thinking of? We could explicitly zap the unfinalized_children list at the end of ExecFinalizeNodeInstrumentation (and have it take a QueryInstrumentation argument) to protect against this, but I don't think that makes much of a difference with the code as currently written. Maybe I'm misunderstanding which situation you're thinking of? > + if (myState->es->timing || myState->es->buffers) > + instr = InstrQueryStopFinalize(instr); > + > > Is it okay to leak 1 instrumentation copy per tuple in the query > context? This freshly palloced object will be out of scope a few lines > after this. I don't think that's a permanent leak, since it would be in the memory context of the caller, i.e. the per-query memory context, but yeah, this doesn't seem ideal, since we're keeping this memory around for each tuple processed. First of all, we could just do a pfree in serializeAnalyzeReceive after we added the stats, but that said, this extra instrumentation for EXPLAIN (SERIALIZE) is a bit of a curious edge case I suppose, since serializeAnalyzeReceive gets called once per tuple - and so doing the ResOwner dance for each tuple is probably not ideal. I wonder if maybe we shouldn't treat this as a case of NodeInstrumentation instead, and attach to the query's totaltime instrumentation for abort safety. The only thing that's a bit inconvenient about that is that calling InstrQueryRememberNode/InstrFinalizeNode requires passing in that parent QueryInstrumentation, and the SerializeDestReceiver doesn't currently have easy access to that. If we brute-force solve that we could just add an extra method to set it after CreateQueryDesc is called, but: Stepping back, from an overall API design perspective, we could also track the current QueryInstrumentation in a global variable - that'd make it easier to attach/finalize extra instrumentation on it even if we don't have direct access to querydesc->totaltime, or we're in a non-executor context that uses QueryInstrumentation (like some utility commands) for future use cases of extra sub-query-level instrumentation. For example, that could also come in handy if we wanted VACUUM VERBOSE break out the buffer access it does on indexes vs tables. > @@ -128,8 +130,22 @@ IndexNext(IndexScanState *node) > > IndexNextWithReorder doesn't need the same handling? Yes - good point, that's an unintentional omission. For context, I hadn't spent substantial amounts of time on this part of the series (rather on getting the design of the stack mechanism right), but will fix this in the next revision to also handle IndexNextWithReorder. I've also been thinking whether we should teach Index-only Scans to break out the per-table buffer stats for the (rare) heap fetches. I guess we should? (it'd be fairly easy to instrument that index_fetch_heap there now) > + if (scandesc->xs_heap_continue) > + elog(ERROR, "non-MVCC snapshots are not supported in index-only scans"); > > Shouldn't this say index scans? (there's another preexisting > indexonylscan mention in this file, but that also seems wrong) Hmm. Looking at this again, I think the handling of xs_heap_continue isn't right altogether. Basically it should be this instead, I think, so we correctly call the table AM's table_index_fetch_tuple again if call_again gets set: while ((tid = index_getnext_tid(scandesc, direction)) != NULL) { if (node->iss_InstrumentTable) InstrPushStack(&node->iss_InstrumentTable->instr); for (;;) { found = index_fetch_heap(scandesc, slot); if (found || !scandesc->xs_heap_continue) break; } if (node->iss_InstrumentTable) InstrPopStack(&node->iss_InstrumentTable->instr); if (unlikely(!found)) continue; Which matches the loop in index_getnext_slot (i.e keep calling index_fetch_heap if xs_heap_continue=true). Based on that, we wouldn't need the elog at all. > +#if HAVE_INSTR_STACK > + usage = &instr_top.bufusage; > +#else > + usage = &pgBufferUsage; > +#endif > > I don't see pgBufferUsage anywhere else in the current code, it was > probably removed between rebases? That's intentional to allow testing pg_session_buffer_usage both on master (HAVE_INSTR_STACK=0) and with the patched version (HAVE_INSTR_STACK=1) - mainly to ensure we're matching behavior for anyone interested in the top-line buffer or WAL numbers. I don't think we should commit pg_session_buffer_usage (at least not as-is), its just there for testing the earlier changes. > + char *prefix = title ? psprintf("%s ", title) : pstrdup(""); > + > + ExplainPropertyInteger(psprintf("%sShared Hit Blocks", prefix), NULL, > usage->shared_blks_hit, es); > > (And many similar ExplainPropery after this) > > title is NULL most of the time, and this results in 16 allocations for > that common case - isn't there a better solution like using > ExplainOpenGroup or something? Yeah, I guess that's fair - I don't know if the extra allocations really matter, but I can see your point. If we used ExplainOpenGroup that would make it a nested structure in the JSON/etc representation, so it'd look like this: "Shared Read Blocks:" 123.0, ... "Temp I/O Write Time:" 42.0, "Table": { "Shared Read Blocks:" 123.0, ... "Temp I/O Write Time:" 42.0, } compared to text representation (simplified): Buffers: shared read=123.0 I/O Timings: temp write=42.0 Table Buffers: shared read=123.0 Table I/O Timings: temp write=42.0 I think that can work, and we have precedence for using groups in a node like this, e.g. with "Workers". If we go with this, I do wonder if we should clarify the JSON/etc group key as "Table Access" (one group) or "Table Buffers" / "Table I/O" (two groups), instead of just "Table"? > + * 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, instead call InstrPopAndFinalizeStack which can skip intermediate > + * stack entries, or instead use InstrStart/InstrStop. > > InstrPopAndFinalizeStack doesn't exists in the latest patch version Ah, yeah, that should say InstrStopFinalize (basically direct use of InstrPushStack/InstrPopStack is discouraged over use of the Instrumentation functions), I'll fix it in the next revision. Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Zsolt Parragi <zsolt.parragi@percona.com> — 2026-03-10T08:12:56Z
> ResourceOwnerForgetInstrumentation directly follows the call to > ExecFinalizeNodeInstrumentation in standard_ExecutorFinish, so I'm not > sure which error case you're thinking of? There are a few pallocs between them, so OOM is possible, even if unlikely. I mainly mentioned this because even if unlikely it can happen in theory, and the fix seems simple to me. > I don't think that's a permanent leak, since it would be in the memory > context of the caller, i.e. the per-query memory context Yes, it's definitely not permanent, but could be bad with many tuples. > and so > doing the ResOwner dance for each tuple is probably not ideal. These approaches are interesting, but also add complexity, so I'm unsure which is better for this, the pfree calls add one line and solve the main issue with the current code. > Basically it should be this instead, I think, > so we correctly call the table AM's table_index_fetch_tuple again if > call_again gets set: Right, this code will be better. > I don't know if the extra allocations > really matter, but I can see your point. Yeah, probably doesn't matter that much, but the code also wasn't that nice in that form. I didn't try to actually modify it, but by just looking at it the grouped option seemed cleaner to me, and the output should also be self-explanatory and logical to users.
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-14T20:49:23Z
On Tue, Mar 10, 2026 at 1:13 AM Zsolt Parragi <zsolt.parragi@percona.com> wrote: > > ResourceOwnerForgetInstrumentation directly follows the call to > > ExecFinalizeNodeInstrumentation in standard_ExecutorFinish, so I'm not > > sure which error case you're thinking of? > > There are a few pallocs between them, so OOM is possible, even if > unlikely. I mainly mentioned this because even if unlikely it can > happen in theory, and the fix seems simple to me. Ah, yeah, I didn't consider the pallocs in InstrFinalizeNode causing an OOM that would cause an abort - good thinking! I've adjusted this to use a dlist instead of an slist and InstrFinalizeNode now deletes the node from the list. > > I don't think that's a permanent leak, since it would be in the memory > > context of the caller, i.e. the per-query memory context > > Yes, it's definitely not permanent, but could be bad with many tuples. > > > and so > > doing the ResOwner dance for each tuple is probably not ideal. > > These approaches are interesting, but also add complexity, so I'm > unsure which is better for this, the pfree calls add one line and > solve the main issue with the current code. Yeah, fair point on complexity - I've just added the pfree for now. > > Basically it should be this instead, I think, > > so we correctly call the table AM's table_index_fetch_tuple again if > > call_again gets set: > > Right, this code will be better. Implemented this fix in IndexNext, and also expanded the tracking of table access to IndexNextWithReorder. Regarding Index-Only Scans, I did not add instrumentation for table access yet - I might add that in a follow-up revision or we could also do it in a follow-on patch. > > I don't know if the extra allocations > > really matter, but I can see your point. > > Yeah, probably doesn't matter that much, but the code also wasn't that > nice in that form. I didn't try to actually modify it, but by just > looking at it the grouped option seemed cleaner to me, and the output > should also be self-explanatory and logical to users. Yep, fair point - I've now added two groups "Table Buffers" and "Table I/O Timings" that get used in structured output. --- See attached v8 rebased on latest master, that also fixes the issues Zsolt pointed out in 0005 and 0007. Additionally, two other minor changes in 0005 (the commit that adds stack-based instrumentation): 1) Change the allocation for query/node instrumentation so that we only use top-level memory context when WAL/buffer usage is requested (i.e. instrumentation stack is needed) - easy enough to do, and makes the timing/rows only case a bit cheaper. 2) Fix a missing addition to the remaining pgWalUsage global in the parallel query case, when instrumentation is used. For context, to avoid double counting we don't have the parallel workers call ExecFinalizeNodeInstrumentation (instead the per-node numbers get reported back to the leader, and that one bubbles them up), but that also means that InstrAccumParallelQuery doesn't see the per-node activity. This now gets added in ExecParallelRetrieveInstrumentation. All other patches as before. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Tomas Vondra <tomas@vondra.me> — 2026-03-16T23:50:40Z
On 3/14/26 21:49, Lukas Fittl wrote: > ... > > Implemented this fix in IndexNext, and also expanded the tracking of > table access to IndexNextWithReorder. > > Regarding Index-Only Scans, I did not add instrumentation for table > access yet - I might add that in a follow-up revision or we could also > do it in a follow-on patch. > I think we should, and it probably should be done in the same commit as for plain index scans. Mostly for consistency / less confusion. Every now and then there's an index-only scan that has to do a lot of heap fetches, possibly just as many as the plain index scan. But the IOS version would not say how many buffer accesses are for table, and users might assume an index-only scan does not access table. Confusing. I only started to look at the patch today, so I don't have any real review comments. But I noticed the pg_session_buffer_usage is added only to the contrib/meson.build and not to the Makefile. I assume that's not intentional. regards -- Tomas Vondra
-
Re: Stack-based tracking of per-node WAL/buffer usage
Zsolt Parragi <zsolt.parragi@percona.com> — 2026-03-17T06:21:18Z
+ TriggerInstrumentation *ti = rInfo->ri_TrigInstrument; + + if (ti && (ti->instr.need_bufusage || ti->instr.need_walusage)) + InstrAccum(instr_stack.current, &ti->instr); I think there's one more bug here, isn't ti an array? This seems to only process the first entry, not all of them. +InstrPopStackTo(Instrumentation *prev) +{ + Assert(instr_stack.stack_size > 0); + instr_stack.stack_size--; + instr_stack.current = prev; +} + Shouldn't this have the same additional assertion as InstrPopStack? -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-17T08:18:38Z
Hi Tomas and Zsolt, On Mon, Mar 16, 2026 at 4:50 PM Tomas Vondra <tomas@vondra.me> wrote: > On 3/14/26 21:49, Lukas Fittl wrote: > > Regarding Index-Only Scans, I did not add instrumentation for table > > access yet - I might add that in a follow-up revision or we could also > > do it in a follow-on patch. > > > > I think we should, and it probably should be done in the same commit as > for plain index scans. Mostly for consistency / less confusion. > > Every now and then there's an index-only scan that has to do a lot of > heap fetches, possibly just as many as the plain index scan. But the IOS > version would not say how many buffer accesses are for table, and users > might assume an index-only scan does not access table. Confusing. Makes sense - added support for index-only scans in the same commit now. > I only started to look at the patch today, so I don't have any real > review comments. But I noticed the pg_session_buffer_usage is added only > to the contrib/meson.build and not to the Makefile. I assume that's not > intentional. Yeah, that was missed, thanks! For context, pg_session_buffer_usage is not necessarily meant to be committed, its just testing a few edge cases around aborts that can't be easily tested otherwise. On Mon, Mar 16, 2026 at 11:21 PM Zsolt Parragi <zsolt.parragi@percona.com> wrote: > > + TriggerInstrumentation *ti = rInfo->ri_TrigInstrument; > + > + if (ti && (ti->instr.need_bufusage || ti->instr.need_walusage)) > + InstrAccum(instr_stack.current, &ti->instr); > > I think there's one more bug here, isn't ti an array? This seems to > only process the first entry, not all of them. Good catch, fixed! > +InstrPopStackTo(Instrumentation *prev) > +{ > + Assert(instr_stack.stack_size > 0); > + instr_stack.stack_size--; > + instr_stack.current = prev; > +} > + > > Shouldn't this have the same additional assertion as InstrPopStack? Yep, added. It has to be slightly different because we're passing the previous stack entry (hence the "To" in the function name), vs the current one (to save instructions), but probably helpful to have that assurance. --- See attached v9, with 0001 to 0004 the same as before. 0005 has the following additional changes beyond what's mentioned above: - Replaced individual need_bufusage/need_walusage flags on Instrumentation with a single "need_stack" (to fix duplication of checks noted by Tomas over in [0]) - Renamed InstrAccum to InstrAccumStack to clarify it only accumulates stack entries, not total time (which is also part of Instrumentation, but doesn't use the stack mechanism) - Fixed a stale comment on InstrPushStack regarding resource owner / PG_FINALLY use 0006 is the patch moved here now that I shared over in [0] to help with the IOUsage case. I think up to 0006 would be the required patches to allow the work in that thread to use the stack-based instrumentation. 0007 (ExecProcNodeInstr optimization) has minor change to adjust ExecProcNodeInstr function naming to be less specific to WAL/buffer usage, in anticipation of potentially adding IOUsage. 0008 (Index scans: Show table buffer accesses) added Index Only Scan support, and switched IndexScanInstrumentation to use Instrumentation struct instead of individual Buffer/WALUsage for passing back parallel worker info - that avoids accidentally missing new types of stack-based instrumentation being passed back, which would then be missing from query totals. Thanks, Lukas [0]: https://www.postgresql.org/message-id/41d87d75-d126-438b-a02e-6671142d39b7@vondra.me -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Zsolt Parragi <zsolt.parragi@percona.com> — 2026-03-18T20:49:37Z
+ instr_stack.stack_space *= 2; + instr_stack.entries = repalloc_array(instr_stack.entries, Instrumentation *, instr_stack.stack_space); Can't this also cause issues with OOM? repalloc_array failing, but we already doubled stack_space. The initialization above uses the same order, but that should be safe as entries is initially NULL. + * 2) Accumulate all instrumentation to the currently active instrumentation, + * so that callers get a complete picture of activity, even after an abort ... + if (idx >= 0) + { + while (instr_stack.stack_size > idx + 1) + instr_stack.stack_size--; + + InstrPopStack(instr); + } There seems to be one more bug in this: 1. EXPLAIN ANALYZE fires a trigger 2. The trigger function throws ERROR, InstrStopTrigger never runs 3. ResOwnerReleaseInstrumentation runs but only checks unfinalized_children, not triggers 4. InstrStopFinalize discards the trigger entry 5. Trigger instrumentation information shows 0 -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-18T23:36:03Z
On Wed, Mar 18, 2026 at 1:49 PM Zsolt Parragi <zsolt.parragi@percona.com> wrote: > > + instr_stack.stack_space *= 2; > + instr_stack.entries = repalloc_array(instr_stack.entries, > Instrumentation *, instr_stack.stack_space); > > Can't this also cause issues with OOM? repalloc_array failing, but we > already doubled stack_space. > The initialization above uses the same order, but that should be safe > as entries is initially NULL. Yeah, that's fair, I think its reasonable to do the update of instr_stack.stack_space after the allocation succeeded. I also think its good to do that even for the initialization case - it seems extremely unlikely, but the fact that entries is NULL doesn't protect us against a subsequent InstrPushStack running after an OOM and the check whether InstrStackGrow should be called runs based on the stack space, not the entries array. I have a fix for that staged for the next iteration. > + * 2) Accumulate all instrumentation to the currently active instrumentation, > + * so that callers get a complete picture of activity, even after an abort > ... > + if (idx >= 0) > + { > + while (instr_stack.stack_size > idx + 1) > + instr_stack.stack_size--; > + > + InstrPopStack(instr); > + } > > There seems to be one more bug in this: > > 1. EXPLAIN ANALYZE fires a trigger > 2. The trigger function throws ERROR, InstrStopTrigger never runs > 3. ResOwnerReleaseInstrumentation runs but only checks > unfinalized_children, not triggers > 4. InstrStopFinalize discards the trigger entry > 5. Trigger instrumentation information shows 0 Hmm, so I think you're correct that a trigger function error would cause any stack-based instrumentation from the trigger to get lost. In practice that doesn't matter today, since triggers never capture WAL/buffer usage data (only timing), but its maybe a design flaw because trigger instrumentation is its own thing without a defined relationship with the stack, unlike NodeInstrumentation which is registered to the query that handles the aborts. In a sense this is a similar situation to the EXPLAIN (SERIALIZE) per-tuple handling we talked about previously - we have instrumentation that's related to a query, but its not per-node, so using NodeInstrumentation doesn't really make sense. I could imagine three ways forward, if we want to address that now (vs documenting that this isn't handled but effectively not a problem): 1) We add a second list for unfinalized trigger instrumentations on QueryInstrumentation, and accumulate that too in ResOwnerReleaseInstrumentation 2) We call InstrStopFinalize in ExecCallTriggerFunc if an error was thrown from the trigger function (i.e. turn the existing PG_FINALLY block into a PG_CATCH) 3) We generalize the QueryInstrumentation children handling to allow other types of Instrumentation (i.e. not just NodeInstrumentation) I think (3) would be ideal and would let us deal with EXPLAIN (SERIALIZE) too, but is complicated by the fact that ResOwnerReleaseInstrumentation needs to have reference to the full allocated struct (not just the Instrumentation contained within) so it can call pfree to avoid leaking memory until top transaction end. In a prior iteration we had the Instrumentation allocated separately inside NodeInstrumentation (so its a pointer and can thus be freed independently / replaced with a copy on clean exit), which allows ResOwnerReleaseInstrumentation to just deal with Instrumentation, but that becomes inconvenient when dealing with parallel workers. There is an alternate design I had considered, which is to basically keep two copies of Instrumentation in NodeInstrumentation: One is a pointer to the running instrumentation (allocated in a memory context that survives long enough in an abort, and which will be freed upon abort or clean exit), and one is a direct member of the containing struct (like we have it today), and gets updated via a memcpy() upon a clean exit. I think that'd make the API easier to use and the same concept could then be applied to TriggerInstrumentation, but the big downside is that we'd be doubling memory usage because whilst we're running we'd both have the allocation in the higher memory context, and the direct member of the containing struct (to return the result to the caller). Because of that, I feel like we should do (1) or (2) for now - but I'll also wait if Andres or others have additional feedback on 0005 before proceeding with further changes. I also do think that the 0001-0004 patches are good to be committed unless anyone had additional feedback there. Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-19T00:45:49Z
On Wed, Mar 18, 2026 at 4:36 PM Lukas Fittl <lukas@fittl.com> wrote: > On Wed, Mar 18, 2026 at 1:49 PM Zsolt Parragi <zsolt.parragi@percona.com> wrote: > > There seems to be one more bug in this: > > > > 1. EXPLAIN ANALYZE fires a trigger > > 2. The trigger function throws ERROR, InstrStopTrigger never runs > > 3. ResOwnerReleaseInstrumentation runs but only checks > > unfinalized_children, not triggers > > 4. InstrStopFinalize discards the trigger entry > > 5. Trigger instrumentation information shows 0 > > Hmm, so I think you're correct that a trigger function error would > cause any stack-based instrumentation from the trigger to get lost. > > In practice that doesn't matter today, since triggers never capture > WAL/buffer usage data (only timing), After twisting and turning this in my head more, I realize that's actually not correct - as it stands, trigger instrumentation is inheriting the instrumentation options from the overall query, and so that will cause a typical EXPLAIN (ANALYZE) to also capture Buffer/WAL usage for triggers - it just won't be shown in EXPLAIN. Since its not used in practice, we could fix that by explicitly setting INSTRUMENT_TIMER for triggers, but AFAIR Andres had noted on a prior iteration that special casing this doesn't seem right, since we should probably output buffer/WAL usage for triggers anyway. So I guess that brings us back to, we should fix it with one of the ways I mentioned. FWIW, I was able to create a test case in the pg_session_buffer_usage module to that effect, so there is indeed a current issue where activity during triggers gets lost and won't be added to the overall totals on abort. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Heikki Linnakangas <hlinnaka@iki.fi> — 2026-03-23T14:41:18Z
On 19/03/2026 02:45, Lukas Fittl wrote: > On Wed, Mar 18, 2026 at 4:36 PM Lukas Fittl <lukas@fittl.com> wrote: >> On Wed, Mar 18, 2026 at 1:49 PM Zsolt Parragi <zsolt.parragi@percona.com> wrote: >>> There seems to be one more bug in this: >>> >>> 1. EXPLAIN ANALYZE fires a trigger >>> 2. The trigger function throws ERROR, InstrStopTrigger never runs >>> 3. ResOwnerReleaseInstrumentation runs but only checks >>> unfinalized_children, not triggers >>> 4. InstrStopFinalize discards the trigger entry >>> 5. Trigger instrumentation information shows 0 >> >> Hmm, so I think you're correct that a trigger function error would >> cause any stack-based instrumentation from the trigger to get lost. >> >> In practice that doesn't matter today, since triggers never capture >> WAL/buffer usage data (only timing), > > After twisting and turning this in my head more, I realize that's > actually not correct - as it stands, trigger instrumentation is > inheriting the instrumentation options from the overall query, and so > that will cause a typical EXPLAIN (ANALYZE) to also capture Buffer/WAL > usage for triggers - it just won't be shown in EXPLAIN. > > Since its not used in practice, we could fix that by explicitly > setting INSTRUMENT_TIMER for triggers, but AFAIR Andres had noted on a > prior iteration that special casing this doesn't seem right, since we > should probably output buffer/WAL usage for triggers anyway. > > So I guess that brings us back to, we should fix it with one of the > ways I mentioned. FWIW, I was able to create a test case in the > pg_session_buffer_usage module to that effect, so there is indeed a > current issue where activity during triggers gets lost and won't be > added to the overall totals on abort. I'm looking at this finalize at resowner part of this patch, and this maybe a stupid question, but: Why does the instrumentation need to be "finalized" on abort? If you run EXPLAIN ANALYZE and the query aborts, you don't get to see the stats anyway. - Heikki
-
Re: Stack-based tracking of per-node WAL/buffer usage
Zsolt Parragi <zsolt.parragi@percona.com> — 2026-03-23T19:07:02Z
> I'm looking at this finalize at resowner part of this patch, and this > maybe a stupid question, but: > > Why does the instrumentation need to be "finalized" on abort? If you run > EXPLAIN ANALYZE and the query aborts, you don't get to see the stats anyway. The pg_session_buffer_usage in 0009 makes the information available, I was able to see the issue with failing triggers with that. Even if that part doesn't get committed in the end, a 3rd party extension could still implement the same thing, and notice the missing statistics. (And maybe it is useful to see some statistics about failing queries?)
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-23T20:03:21Z
On Mon, Mar 23, 2026 at 12:07 PM Zsolt Parragi <zsolt.parragi@percona.com> wrote: > > > I'm looking at this finalize at resowner part of this patch, and this > > maybe a stupid question, but: > > > > Why does the instrumentation need to be "finalized" on abort? If you run > > EXPLAIN ANALYZE and the query aborts, you don't get to see the stats anyway. > > The pg_session_buffer_usage in 0009 makes the information available, I > was able to see the issue with failing triggers with that. Even if > that part doesn't get committed in the end, a 3rd party extension > could still implement the same thing, and notice the missing > statistics. (And maybe it is useful to see some statistics about > failing queries?) Right, there are basically two reasons we need the resource owner logic, or something equivalent: 1) To ensure the active stack entry gets reset correctly to where it was before, so that we don't corrupt it after an abort (if that's not done, we'll fail during regular regression tests) 2) To accumulate statistics to parent stack entries that did not participate in the abort As Zsolt noted, (2) matters for the pg_session_buffer_usage module, which is mainly intended to ensure that the logic we're adding keeps a top-level instrumentation available that includes the activity of aborted transactions/queries, since we're removing pgBufferUsage. It also matters for some edge cases in-tree today, e.g. procedures being tracked in pg_stat_statements. And I do see us being interested in tracking failed query activities in the future as Zsolt noted. --- FWIW, on the topic of resource owners and allocations, I've done a test over the weekend, and here is a question: It seems we could switch the Instrumentation allocations we're doing when inside a portal to PortalContext, and CurrentMemoryContext when outside a portal - instead of allocating in TopMemoryContext/TopTransactionContext. That works in practice, because resource owner cleanup happens before PortalContext cleanup, and simplifies the code a bit since we can skip copying into the current memory context (because the caller wants to be able to use the result after the finalize call). And if we leak we'd only leak until PortalContext gets cleaned up, instead of TopMemoryContext. To expand on that, in the previously posted v9 we have the following allocations: A) InstrStackState allocated under TopMemoryContext (long-lived, never freed) B) QueryInstrumentation allocated under TopMemoryContext (short-lived during query execution, explicitly freed up on abort or finalize call) C) NodeInstrumentation allocated under TopTransactionContext (short-lived during query execution, explicitly freed up on abort or finalize call) D) In other use cases, e.g. ANALYZE command that logs buffer usage, QueryInstrumentation allocated under TopMemoryContext (short-lived during command execution, explicitly freed up on abort or finalize call) And we could switch it instead to: A) InstrStackState allocated under TopMemoryContext (long-lived, never freed) B) QueryInstrumentation allocated under PortalContext (short-lived during query execution, *automatically* freed up on abort, manually on ExecutorEnd to avoid waiting for holdable cursors to free PortalContext) C) NodeInstrumentation allocated under PortalContext (short-lived during query execution, *automatically* freed up on abort, manually on ExecutorEnd to avoid waiting for holdable cursors to free PortalContext) D) In other use cases, e.g. ANALYZE command that logs buffer usage, QueryInstrumentation allocated under CurrentMemoryContext (short-lived during command execution, *automatically* freed up on abort and success case) However, this goes against the principle noted by Heikki over in [0] that ResOwners should use TopMemoryContext to avoid relying on the ordering of clean up operations. Thoughts? Thanks, Lukas [0]: https://www.postgresql.org/message-id/flat/a3197b31-f40d-4164-872d-906d8e9b374a%40iki.fi#526984c1be0662a7526bcfe0b358564b -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-24T06:03:16Z
On Mon, Mar 23, 2026 at 1:03 PM Lukas Fittl <lukas@fittl.com> wrote: > FWIW, on the topic of resource owners and allocations, I've done a > test over the weekend, and here is a question: > > It seems we could switch the Instrumentation allocations we're doing > when inside a portal to PortalContext, and CurrentMemoryContext when > outside a portal - instead of allocating in > TopMemoryContext/TopTransactionContext. That works in practice, > because resource owner cleanup happens before PortalContext cleanup, > and simplifies the code a bit since we can skip copying into the > current memory context (because the caller wants to be able to use the > result after the finalize call). And if we leak we'd only leak until > PortalContext gets cleaned up, instead of TopMemoryContext. > > To expand on that, in the previously posted v9 we have the following > allocations: > > A) InstrStackState allocated under TopMemoryContext (long-lived, never freed) > B) QueryInstrumentation allocated under TopMemoryContext (short-lived > during query execution, explicitly freed up on abort or finalize call) > C) NodeInstrumentation allocated under TopTransactionContext > (short-lived during query execution, explicitly freed up on abort or > finalize call) > D) In other use cases, e.g. ANALYZE command that logs buffer usage, > QueryInstrumentation allocated under TopMemoryContext (short-lived > during command execution, explicitly freed up on abort or finalize > call) > > And we could switch it instead to: > > A) InstrStackState allocated under TopMemoryContext (long-lived, never freed) > B) QueryInstrumentation allocated under PortalContext (short-lived > during query execution, *automatically* freed up on abort, manually on > ExecutorEnd to avoid waiting for holdable cursors to free > PortalContext) > C) NodeInstrumentation allocated under PortalContext (short-lived > during query execution, *automatically* freed up on abort, manually on > ExecutorEnd to avoid waiting for holdable cursors to free > PortalContext) > D) In other use cases, e.g. ANALYZE command that logs buffer usage, > QueryInstrumentation allocated under CurrentMemoryContext (short-lived > during command execution, *automatically* freed up on abort and > success case) > > However, this goes against the principle noted by Heikki over in [0] > that ResOwners should use TopMemoryContext to avoid relying on the > ordering of clean up operations. I've pondered this question more today, and I think maybe this complexity isn't the right way to approach this. Instead I've tried introducing a memory context for instrumentation managed as a resource owner, and I am now (for now) convinced that this is the right trade-off for the problem at hand. The benefit of using our own memory context is that we can free it all at once (which is a lot less brittle when different types of instrumentation are involved), *and* we can re-assign the context parent to be that of the current context on finalize, cleanly moving it out of TopMemoryContext without doing a copy. It also makes it easier for callers to allocate in the right context, without having to introduce a bunch more "Alloc" methods (e.g. relevant for the table stack tracking for index scans). We also have precedence for the use of small memory contexts in the executor with the existence of per-tuple memory contexts. The main downside is that for the cases where we don't have child instrumentation, but want the resource owner logic (e.g. ANALYZE command, or regular query execution with pg_stat_statements enabled), we have more memory overhead: 1kB (ALLOCSET_SMALL_SIZES minimum) for what could otherwise be ~200B. I think that's probably okay for current use cases, but we could avoid that by only using the separate contexts when we have child instrumentations that will be tracked. See attached v10, rebased, with these additional changes: In 0001/0002 I've added forward declarations in execnodes.h, which are necessary since fba4233c8328. In 0005 (stack-based instrumentation) I've also addressed the previously raised concerns about trigger and EXPLAIN (SERIALIZE) handling, and it now treats both kinds as children of the query's instrumentation context. To assist with initializing that, we have to add a query instrumentation reference to EState, but I think that's acceptable. To reduce code churn I've repurposed the existing es_instrument field for that, and we now remember the instrumentation options on QueryInstrumentation. In 0007 (Optimize ExecProcNodeInstr instructions by inlining) I've adjusted the ExecProcNodeInstr logic to use a single function that contains the logic, with separate callers that pass in fixed constants, to let the compiler figure out the different variants with less code duplication, per an off-list suggestion from Andres. In 0008 (Index scans: Show table buffer accesses) this now utilizes the fact that f026fbf059f2 made IndexScanInstrumentation a heap allocation, and puts that allocation in the instrumentation memory context, so it can participate directly in the stack with an inlined Instrumentation field to track table access, avoiding a duplicate field previously necessary. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Zsolt Parragi <zsolt.parragi@percona.com> — 2026-03-24T22:59:45Z
I like the new approach, but doesn't `EXPLAIN (BUFFERS)` leak some memory because the resource owner isn't registered on that path? It seems to be visible with pg_log_backend_memory_contexts. #define INSTR_BUFUSAGE_ADD(fld,val) do { \ - pgBufferUsage.fld += val; \ + instr_stack.current->bufusage.fld += val; \ #define INSTR_WALUSAGE_ADD(fld,val) do { \ pgWalUsage.fld += val; \ + instr_stack.current->walusage.fld += val; \ Nitpick, but these could use += (val) -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-25T05:34:29Z
Hi Zsolt, On Tue, Mar 24, 2026 at 3:59 PM Zsolt Parragi <zsolt.parragi@percona.com> wrote: > I like the new approach, but doesn't `EXPLAIN (BUFFERS)` leak some > memory because the resource owner isn't registered on that path? It > seems to be visible with pg_log_backend_memory_contexts. Ah, yes, good catch! Its nice how the separate memory context makes this very clear now. I think this was actually an existing problem that only surfaced now. The issue is that EXPLAIN (BUFFERS) will allocate the per-query instrumentation, but not actually use it, since the buffer tracking is only relevant for planning, which has its own instrumentation. I can fix this locally by adding the following to FreeExecutorState: /* * Make sure the instrumentation context gets freed. This usually gets * re-parented under the per-query context in InstrQueryStopFinalize, but * that won't happen during EXPLAIN (BUFFERS) since ExecutorFinish never * gets called, so we would otherwise leak it in TopMemoryContext. */ if (estate->es_instrument && estate->es_instrument->instr.need_stack) MemoryContextDelete(estate->es_instrument->instr_cxt); I'll include this in the next revision unless I come up with a better idea. FWIW, I also considered just not setting INSTRUMENT_BUFFERS in ExplainOnePlan unless ANALYZE is active, but I think there might be other cases where that doesn't work as expected, so I think the explicit delete is better. > > #define INSTR_BUFUSAGE_ADD(fld,val) do { \ > - pgBufferUsage.fld += val; \ > + instr_stack.current->bufusage.fld += val; \ > > #define INSTR_WALUSAGE_ADD(fld,val) do { \ > pgWalUsage.fld += val; \ > + instr_stack.current->walusage.fld += val; \ > > Nitpick, but these could use += (val) Ack, makes sense - I'll adjust in the next revision. I'll give it a day or so for further feedback before posting the next update. Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Heikki Linnakangas <hlinnaka@iki.fi> — 2026-03-25T10:47:01Z
On 24/03/2026 08:03, Lukas Fittl wrote: > Instead I've tried introducing a memory context for instrumentation > managed as a resource owner, and I am now (for now) convinced that > this is the right trade-off for the problem at hand. Yes, that seems better. This patch could use an overview README file, I'm struggling to understand how the this all works. Here's my understanding so far, please correct me if I'm wrong: There are *two* data structures tracking the Instrumentation nodes. The patch only talks about a stack, but I think there's also implicitly a tree in there. Tree ---- All Instrumentation nodes are part of a tree. For example, if you have two portals open, the tree might look like this: Session - Query A - NestLoop - Seq Scan A - Seq Scan B - Query B - Seq Scan C When a node is "finalized", its counters are added to its parent. This tree is a somewhat implicit in the patch. Each QueryInstrumentation has a list of child nodes, but only unfinalized ones. Don't we need that at the session level too? When a Query is released on abort, its counters need to be added to the parent too. If I understand correctly, the patch tries to use the stack for that, but it's confusing. I think it would make the patch more clear to talk explicitly about the tree, and represent it explicitly in the Instrumentation nodes. I.e. add a "parent" pointer, or a "children" list, or both to the Instrumentation struct. Stack ----- At all times, there's a stack that tracks what is the Instrumentation in the tree that is *currently* executing. For example, while executing the Seq Scan B, the stack would look like this: 0: Session 1: Query A 2: NestLoop 3: Seq Scan B And when the code is sending a result row back to the client, while the query is being executed, the stack would be just: 0: Session In the patch, the stack is represented by an array. It could also be implemented with a CurrentInstrumentation global variable, similar to CurrentMemoryContext and CurrentResourceOwner. Abort handling -------------- On abort, two things need to happen: 1. Reset the stack to the appropriate level. This ensures that any we don't later try to update the counters on an Instrumentation nodes that is going away with the abort. In the above example, the stack would be reset to the 0: Session level. 2. Finalize all the Instrumentation nodes as part of the ResourceOwner cleanup. All Instrumentation nodes that are released roll up their counters to their parents. Questions: Is the stack always a path from the root of the tree, down to some node? Or could you have e.g. recursion like A -> B -> C -> A? (I don't know if it makes a difference, just wondering) What happens if you release e.g. the NestLoop before its children? All the Instrumentation nodes belonging to a query would usually be part of the same ResourceOwner and there's no guarantee on what order the resources are released. - Heikki -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-26T00:41:00Z
Hi Heikki, On Wed, Mar 25, 2026 at 3:47 AM Heikki Linnakangas <hlinnaka@iki.fi> wrote: > > On 24/03/2026 08:03, Lukas Fittl wrote: > > Instead I've tried introducing a memory context for instrumentation > > managed as a resource owner, and I am now (for now) convinced that > > this is the right trade-off for the problem at hand. > > Yes, that seems better. Thanks for reviewing! > This patch could use an overview README file, I'm struggling to > understand how the this all works. Here's my understanding so far, > please correct me if I'm wrong: Sure, happy to put this together - I wonder where would place that best - probably src/backend/executor/README.instrument ? > There are *two* data structures tracking the Instrumentation nodes. The > patch only talks about a stack, but I think there's also implicitly a > tree in there. > > Tree > ---- > > All Instrumentation nodes are part of a tree. For example, if you have > two portals open, the tree might look like this: > > Session - Query A - NestLoop - Seq Scan A > - Seq Scan B > > - Query B - Seq Scan C > > When a node is "finalized", its counters are added to its parent. > > This tree is a somewhat implicit in the patch. Each QueryInstrumentation > has a list of child nodes, but only unfinalized ones. Don't we need that > at the session level too? When a Query is released on abort, its > counters need to be added to the parent too. If I understand correctly, > the patch tries to use the stack for that, but it's confusing. If I follow you correctly, we're talking about the work that InstrStopFinalize is doing (both in regular flow, and in abort): void InstrStopFinalize(Instrumentation *instr) { ... InstrAccumStack(instr_stack.current, instr); } The "instr_stack.current" global referenced here is effectively the instrumentation that was active before InstrStart was called, and would be a parent in the tree in that sense. Its worth noting that on abort we don't care about the tree structure below the aborted activity, i.e. each QueryInstrumentation acts as a finalization point of sorts, with any tree structure below (e.g. that of executor nodes) not being finalized to their respective parents, but instead just getting added to the QueryInstrumentation they were attached to (which then gets finalized into "instr_stack.current"). > I think it would make the patch more clear to talk explicitly about the > tree, and represent it explicitly in the Instrumentation nodes. I.e. add > a "parent" pointer, or a "children" list, or both to the Instrumentation > struct. I'm happy to clarify the mechanism, but I'm hesitant to add more pointers to Instrumentation, since its a base struct that gets re-used in different places, and also gets copied to parallel workers (so any pointer requires extra scrutiny to avoid mis-use) - and I don't think we actually need to track the parent pointer, since in practice it will always be the current stack entry. > > > Stack > ----- > > At all times, there's a stack that tracks what is the Instrumentation in > the tree that is *currently* executing. For example, while executing the > Seq Scan B, the stack would look like this: > > 0: Session > 1: Query A > 2: NestLoop > 3: Seq Scan B > > And when the code is sending a result row back to the client, while the > query is being executed, the stack would be just: > > 0: Session > > > In the patch, the stack is represented by an array. It could also be > implemented with a CurrentInstrumentation global variable, similar to > CurrentMemoryContext and CurrentResourceOwner. It could be, and in fact earlier iterations were closer to that, but I modified that to the current version based on Andres' feedback - The array structure is a lot easier to work with during abort when things execute out-of-order (as you also note later). > > > Abort handling > -------------- > > On abort, two things need to happen: > > 1. Reset the stack to the appropriate level. This ensures that any we > don't later try to update the counters on an Instrumentation nodes that > is going away with the abort. In the above example, the stack would be > reset to the 0: Session level. Correct, but just to clarify, the main problem we deal with in terms of reset is making sure that we cancel out any InstrPushStack that was done, but will now no longer have a matching InstrPopStack getting called. We need to make sure that we get to the stack entry that was active before the aborted activity started. > 2. Finalize all the Instrumentation nodes as part of the ResourceOwner > cleanup. All Instrumentation nodes that are released roll up their > counters to their parents. > > > Questions: > > Is the stack always a path from the root of the tree, down to some node? > Or could you have e.g. recursion like A -> B -> C -> A? (I don't know if > it makes a difference, just wondering) I don't think this happens in practice - I think for the stack itself that'd probably be fine (since you're just putting the entry back on that was on before, in a sense), but it'd e.g. result in timer instrumentation behaving incorrectly. We could probably add an assert to explicitly prevent that if we're worried about it, but the existing Start/Stop instrumentation calls haven't seen this issue I think, and they'd already have had a problem with that. > What happens if you release e.g. the NestLoop before its children? All > the Instrumentation nodes belonging to a query would usually be part of > the same ResourceOwner and there's no guarantee on what order the > resources are released. Correct, and in fact prior versions of the patch struggled with that exact problem. Its both an issue for resource owner managed cleanup, and when you have PG_FINALLY in the picture (e.g. pg_stat_statements). But that's exactly why its not really a full tree - in the abort case we do not care about the relationship of child instrumentations underneath the QueryInstrumentation - we just make sure that the stack is reset to the entry that was active before the QueryInstrumentation started, and that all activity that occurred is added to the QueryInstrumentation. If you had a situation that had two QueryInstrumentations active (i.e. both registered as resource owner), we go up to whichever one of the two is higher up in the stack, per logic in InstrStopFinalize. Thanks for thinking this through & hopefully this clarifies things a bit? Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-03-27T07:21:23Z
On Wed, Mar 25, 2026 at 5:41 PM Lukas Fittl <lukas@fittl.com> wrote: > On Wed, Mar 25, 2026 at 3:47 AM Heikki Linnakangas <hlinnaka@iki.fi> wrote: > > This patch could use an overview README file, I'm struggling to > > understand how the this all works. Here's my understanding so far, > > please correct me if I'm wrong: > > Sure, happy to put this together - I wonder where would place that > best - probably src/backend/executor/README.instrument ? I've gone ahead and added that in src/backend/executor/README.instrument for now, trying to take some of your prior email as inspiration, whilst not fully committing to describing it as a tree - but happy to revise that if we feel its important for clarity. See attached v11, rebased after the pgBufferUsage calls were moved in df09452c3209, and also fixing the issues that Zsolt noted in a previous email reviewing v10. I've also moved pg_session_buffer_usage to be a test_session_buffer_usage module instead, since its not intended as a user accessible module. If we wanted to commit that (not sure if its worth the cycles), we could potentially merge it with the 0004 commit that expands the main regression tests. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-04-04T09:43:50Z
Hi, Attached v12, rebased, otherwise no changes. I realize time to freeze is getting close, and whilst I'd love to see this go in, I'm also realistic - so I'll just do my best to support review in the off chance we can make it for this release. On that note, I think 0001 and 0002 are independently useful refactorings to split the different kinds of instrumentation that should be ready to go, and I don't think should conflict much with other patches in this commitfest. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Andres Freund <andres@anarazel.de> — 2026-04-04T19:39:16Z
Hi, On 2026-04-04 02:43:50 -0700, Lukas Fittl wrote: > Attached v12, rebased, otherwise no changes. > > I realize time to freeze is getting close, and whilst I'd love to see > this go in, I'm also realistic - so I'll just do my best to support > review in the off chance we can make it for this release. I unfortunately think there's enough nontrivial design decisions - that I don't have a sufficiently confident assesment of - that I would be pretty hesitant to commit this at this stage of the cycle without some architectural review by senior folks. If Heikki did another round or two of review, it'd be a different story. I think the high level design is a huge improvement and goes in the right direction, but some of the lower level stuff I'm far less confident about. > On that note, I think 0001 and 0002 are independently useful > refactorings to split the different kinds of instrumentation that > should be ready to go, and I don't think should conflict much with > other patches in this commitfest. Yea, I'll see that those get committed. I could also see 0004 as potentially worth getting committed separately, although I'm a bit worried about test stability. I recently looked at a coverage report, in the context of the index prefetching patch, and was a it surprised that prominent parallel executor nodes have no coverage for EXPLAIN ANALYZE. parallel BHS is not covered: https://coverage.postgresql.org/src/backend/executor/nodeBitmapHeapscan.c.gcov.html#L536 parallel IOS is not covered: https://coverage.postgresql.org/src/backend/executor/nodeIndexonlyscan.c.gcov.html#L430 > From 90a7ed18f14c09c8a1299db3a015747fc6b6761c Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Tue, 9 Sep 2025 02:16:59 -0700 > Subject: [PATCH v12 5/9] Optimize measuring WAL/buffer usage through > stack-based instrumentation > > 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 the > function BufferUsageAccumDiff showing up in profiles and in some cases > adding up to 10% overhead to an EXPLAIN (ANALYZE, BUFFERS) run. > > 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 InstrEndNode. 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. > > This also drops the global pgBufferUsage, any callers interested in > measuring buffer activity should instead utilize InstrStart/InstrStop. > > 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. Probably worth stating what the performance overhead of WAL and BUFFERS is after this patch? > @@ -1015,19 +994,9 @@ pgss_ExecutorStart(QueryDesc *queryDesc, int eflags) > */ > if (pgss_enabled(nesting_level) && queryDesc->plannedstmt->queryId != INT64CONST(0)) > { > - /* > - * Set up to track total elapsed time in ExecutorRun. Make sure the > - * space is allocated in the per-query context so it will go away at > - * ExecutorEnd. > - */ > + /* Set up to track total elapsed time in ExecutorRun. */ > if (queryDesc->totaltime == NULL) > - { > - MemoryContext oldcxt; > - > - oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt); > - queryDesc->totaltime = InstrAlloc(INSTRUMENT_ALL); > - MemoryContextSwitchTo(oldcxt); > - } > + queryDesc->totaltime = InstrQueryAlloc(INSTRUMENT_ALL); > } > } Not at all the fault of this patch, but it does seem somewhat odd to me that we handle pgss/auto_explain wanting instrumentation by them updating the QueryDesc->totaltime, rather than having extensions add an eflag to ask standard_ExecutorStart to do so. > @@ -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)); > @@ -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); Again not your fault, but it feels like the parallel index build infrastructure is all wrong. Reimplementing this stuff for every index type makes no sense. > @@ -324,14 +324,16 @@ standard_ExplainOneQuery(Query *query, int cursorOptions, > QueryEnvironment *queryEnv) > { > PlannedStmt *plan; > - instr_time planstart, > - planduration; > - BufferUsage bufusage_start, > - bufusage; > + QueryInstrumentation *instr = NULL; > MemoryContextCounters mem_counters; > MemoryContext planner_ctx = NULL; > MemoryContext saved_ctx = NULL; > > + if (es->buffers) > + instr = InstrQueryAlloc(INSTRUMENT_TIMER | INSTRUMENT_BUFFERS); > + else > + instr = InstrQueryAlloc(INSTRUMENT_TIMER); I was momentarily confused why this only checks es->buffers, not es->wal, but I now see this is just for the planning, and we haven't displayed WAL there so far, even if it's possible that we would emit some WAL. Probably would name it plan_instr or such. And I'd probably go for one InstrQueryAlloc() with a flags variable that's set depending on es->buffers, because it seems likely we'll add more stuff to track over time... > if (es->memory) > { > /* > @@ -348,15 +350,12 @@ standard_ExplainOneQuery(Query *query, int cursorOptions, > saved_ctx = MemoryContextSwitchTo(planner_ctx); > } > > - if (es->buffers) > - bufusage_start = pgBufferUsage; > - INSTR_TIME_SET_CURRENT(planstart); > + InstrQueryStart(instr); > > /* plan the query */ > plan = pg_plan_query(query, queryString, cursorOptions, params, es); > > - INSTR_TIME_SET_CURRENT(planduration); > - INSTR_TIME_SUBTRACT(planduration, planstart); > + InstrQueryStopFinalize(instr); > > if (es->memory) > { > @@ -364,16 +363,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), > + &instr->instr.total, (es->buffers ? &instr->instr.bufusage : NULL), > es->memory ? &mem_counters : NULL); > } Kinda wonder if some of this could be moved into a preliminary patch, without depending on the stack infrastructure. Even with the current instrumentation buffers and timing could be handled that way. > @@ -590,7 +582,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)); > + } The current code just returning a made up zeroed metrics in that case is somewhat weird... > +++ b/src/backend/executor/README.instrument > @@ -0,0 +1,227 @@ > +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, > + and counter updates from activity get written to the currently > + active instrumentation and accumulated upward to parent nodes when > + finalized, considering aborts due to errors. The second paragraph assumes implementation choices that haven't been introduced yet. Without knowing that it's something stack based it's very unclear what "currently active" and "accumulate upward" mean. I'd probably just say that nested instrumentation needs to work including in the case of errors getting thrown. > +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. Not for now, but it seems like es->memory really should also be implemented this way, rather than be implemented ad-hoc. > +Struct Hierarchy > +---------------- > + > +There are four instrumentation structs, each specialized for a different > +scope: I'd just say "the following", otherwise the "four" will inevitably not get updated when another type of instrumentation is introduced :) > +Stack-based instrumentation > +=========================== > + > +For tracking WAL or buffer usage counters, the specialized stack-based > +instrumentation is used. I think I'd add a sentence explaining why a stack is used, i.e. that the alternative approach of taking a snapshot of all stats at the start of the instrumented section and diffing it at the end & accumulating the differences, is quite expensive. And then explain that the solution, i.e. to point to a struct that should receive stats, has the problem of not supporting nesting, if done naively. Without those it's a bit hard to understand the motivation for all this. > +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 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. *(other than instr_top)? > +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. Hm. This seems like a somewhat random example, why would one want this? > +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. Reset the stack to the appropriate level. This ensures that we don't s/Reset the stack to/The stack is reset to/ And maybe something like: s/appropriate/to the level saved at the start of the aborting (sub-)transaction/ > + 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 highest surviving Instrumentation, so that data is not lost. I was about to say that to me it's the lowest surviving one, but I guess that's just a question of whether you think of stacks as growing up or down... Perhaps it should be something like "innermost surviving"? > +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 stack and accumulates Query A's counters to instr_top. s/stack/instrumentation stack/, otherwise it might be confused with the C callstack. > +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 -- important because ResourceOwner cleanup does > +not guarantee a particular release order. s/important/this is important/ > The per-node breakdown is lost, +but the query-level total is what survives > the abort. Is that actually the typical scenario? Most of the time - including afaict in your example above - there won't be a query-level instrumentation that survives, but the stats are accumulated into instr_top. > +If multiple QueryInstrumentations are active on the stack (e.g. nested > +portals), each one's abort handler uses InstrStopFinalize to unwind to > +whichever entry is higher up, so they compose correctly regardless of > +release order. Maybe "the abort handler of each uses InstrStopFinalize() to accumulate the statics to its parent entry"? > +Resource Owner (QueryInstrumentation) > +------------------------------------- > + > +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 I guess the "both" here refers to "Resource Owner" and "PG_FINALLY"? Given this paragraph looks to be in the PG_FINALLY section, that's not quite obvious. Might just need another newline or such to make it clearer that this is not in the PG_FINALLY section. Or maybe the two options should be in a bulleted list or such. > +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 > +-------------- > + > +Parallel workers get their own QueryInstrumentation so they can measure > +buffer and WAL activity independently, then copy the totals into shared > +memory at shutdown. The leader accumulates these into its own stack. s/shared/dynamic shared/ Maybe s/shutdown/worker shutdown/? > +When per-node instrumentation is active, parallel workers skip per-node > +finalization at shutdown to avoid double-counting; the per-node data is > +aggregated separately through InstrAggNode(). That's a bit gnarly, but I don't really see a better option. > +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) as a child > +of TopMemoryContext. All child instrumentation (nodes, triggers) should be > +allocated in this context. > +On successful completion, instr_cxt is reparented to CurrentMemoryContext > +so its lifetime is tied to the caller's context. On abort, the > +ResourceOwner cleanup frees it after accumulating the instrumentation data > +to the current stack entry after resetting the stack. Makes sense. I mildly wonder if we should create one minimally sized "Instrumentations" node under TopMemoryContext, below which the "Instrumentation" contexts are created, instead of doing so directly under TopMemoryContext. But that's something that can easily be evolved later. > @@ -247,9 +248,19 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags) > estate->es_snapshot = RegisterSnapshot(queryDesc->snapshot); > estate->es_crosscheck_snapshot = RegisterSnapshot(queryDesc->crosscheck_snapshot); > estate->es_top_eflags = eflags; > - estate->es_instrument = queryDesc->instrument_options; > estate->es_jit_flags = queryDesc->plannedstmt->jitFlags; > > + /* > + * Set up query-level instrumentation if needed. We do this before > + * InitPlan so that node and trigger instrumentation can be allocated > + * within the query's dedicated instrumentation memory context. > + */ > + if (!queryDesc->totaltime && queryDesc->instrument_options) > + { > + queryDesc->totaltime = InstrQueryAlloc(queryDesc->instrument_options); > + estate->es_instrument = queryDesc->totaltime; > + } > + > /* > * Set up an AFTER-trigger statement context, unless told not to, or > * unless it's EXPLAIN-only mode (when ExecutorFinish won't be called). It seems pretty weird to still have queryDesc->totaltime *sometimes* created by pgss etc, but also create it in standard_ExecutorStart if not already created. What if the explain options aren't compatible? Sure pgss/auto_explain use ALL, but that's not a given. > + /* Start up instrumentation for this execution run */ > if (queryDesc->totaltime) > - InstrStart(queryDesc->totaltime); > + { > + InstrQueryStart(queryDesc->totaltime); > + > + /* > + * Remember all node entries for abort recovery. We do this once here > + * after InstrQueryStart has pushed the parent stack entry. > + */ > + if (estate->es_instrument && > + estate->es_instrument->instr.need_stack && > + !queryDesc->already_executed) > + ExecRememberNodeInstrumentation(queryDesc->planstate, > + queryDesc->totaltime); > + } Hm. Was briefly worried about the overhead of ExecRememberNodeInstrumentation() in the context of cursors. But I see it's only done once. But why do we not just associate the NodeInstrumentation's with the QueryInstrumentation during the creation of the NodeInstrumentation? > + /* > + * Accumulate per-node and trigger statistics to their respective parent > + * instrumentation stacks. > > + * We skip this in parallel workers because their per-node stats are > + * reported individually via ExecParallelReportInstrumentation, and the > + * leader's own ExecFinalizeNodeInstrumentation handles propagation. If > + * we accumulated here, the leader would double-count: worker parent nodes > + * would already include their children's stats, and then the leader's > + * accumulation would add the children again. > + */ Haven't looked into how this all works in sufficient detail, so I'm just asking you: This works correctly even when using EXPLAIN (ANALYZE, VERBOSE) showing per-worker "subtrees"? > + if (queryDesc->totaltime && estate->es_instrument && !IsParallelWorker()) > + { > + ExecFinalizeNodeInstrumentation(queryDesc->planstate); > + > + ExecFinalizeTriggerInstrumentation(estate); > + } > + > if (queryDesc->totaltime) > - InstrStop(queryDesc->totaltime); > + InstrQueryStopFinalize(queryDesc->totaltime); I'd probably move the estate->es_instrument && !IsParallelWorker() check into the if (queryDesc->totaltime). > @@ -1284,8 +1325,8 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, > palloc0_array(FmgrInfo, n); > resultRelInfo->ri_TrigWhenExprs = (ExprState **) > palloc0_array(ExprState *, n); > - if (instrument_options) > - resultRelInfo->ri_TrigInstrument = InstrAllocTrigger(n, instrument_options); > + if (qinstr) > + resultRelInfo->ri_TrigInstrument = InstrAllocTrigger(qinstr, n); Hm. Why do we not need to pass down the instrument_options anymore? I guess the assumption is that we always are going to use the flags from qinstr? Is that right? Because right now pgss/auto_explain use _ALL, even when an EXPLAIN ANALYZE doesn't. > +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); Maybe ExecGetTriggerResultRel() needs a comment about needing to update ExecFinalizeTriggerInstrumentation() if trigger stuff were to be stored in yet another place? > @@ -1081,14 +1081,28 @@ ExecParallelRetrieveInstrumentation(PlanState *planstate, > instrument = GetInstrumentationArray(instrumentation); > instrument += i * instrumentation->num_workers; > for (n = 0; n < instrumentation->num_workers; ++n) > + { > InstrAggNode(planstate->instrument, &instrument[n]); > > + /* > + * Also add worker WAL usage to the global pgWalUsage counter. > + * > + * When per-node instrumentation is active, parallel workers skip > + * ExecFinalizeNodeInstrumentation (to avoid double-counting in > + * EXPLAIN), so per-node WAL activity is not rolled up into the > + * query-level stats that InstrAccumParallelQuery receives. Without > + * this, pgWalUsage would under-report WAL generated by parallel > + * workers when instrumentation is active. > + */ > + WalUsageAdd(&pgWalUsage, &instrument[n].instr.walusage); > + } I'm not sure I understand why this doesn't also lead to double counting, given that InstrAccumParallelQuery() does also add the worker's usage to pgWalUsage? > +static bool > +ExecFinalizeNodeInstrumentation_walker(PlanState *node, void *context) > +{ > + Instrumentation *parent = (Instrumentation *) context; > + > + Assert(parent != NULL); > + > + if (node == NULL) > + return false; > + > + /* > + * Recurse into children first (bottom-up accumulation), passing our > + * instrumentation as the parent context. This ensures children can > + * accumulate to us even if they were never executed by the leader (e.g. > + * nodes beneath Gather that only workers ran). > + */ > + planstate_tree_walker(node, ExecFinalizeNodeInstrumentation_walker, > + node->instrument ? &node->instrument->instr : parent); I don't think I understand that comment. What changes if the leader's node was never executed? > @@ -227,6 +227,15 @@ FreeExecutorState(EState *estate) > estate->es_partition_directory = NULL; > } > > + /* > + * Make sure the instrumentation context gets freed. This usually gets > + * re-parented under the per-query context in InstrQueryStopFinalize, but > + * that won't happen during EXPLAIN (BUFFERS) since ExecutorFinish never > + * gets called, so we would otherwise leak it in TopMemoryContext. > + */ > + if (estate->es_instrument && estate->es_instrument->instr.need_stack) > + MemoryContextDelete(estate->es_instrument->instr_cxt); > + Ugh. > diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c > index bc551f95a08..6892706a83a 100644 > --- a/src/backend/executor/instrument.c > +++ b/src/backend/executor/instrument.c > @@ -16,30 +16,46 @@ > #include <unistd.h> > > #include "executor/instrument.h" > +#include "utils/memutils.h" > +#include "utils/resowner.h" > > -BufferUsage pgBufferUsage; > -static BufferUsage save_pgBufferUsage; > WalUsage pgWalUsage; Why do we still need pgWalUsage if we have the same data in instr_stack. > -static WalUsage save_pgWalUsage; > +Instrumentation instr_top; > +InstrStackState instr_stack = {0, 0, NULL, &instr_top}; I'd use designated initializers to make this easier to read. > -static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add); > -static void WalUsageAdd(WalUsage *dst, WalUsage *add); > +void > +InstrStackGrow(void) > +{ > + int space = 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; > +} Perhaps worth adding an assert to check that we actually needed space? > +/* > + * 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. > + * > + * We are careful here to achieve two goals: > + * > + * 1) Reset the stack to the parent of whichever of the released stack entries > + * has the lowest index > + * 2) Accumulate all instrumentation to the currently active instrumentation, > + * so that callers get a complete picture of activity, even after an abort > + */ > +void > +InstrStopFinalize(Instrumentation *instr) > +{ > + int idx = -1; > + > + for (int i = instr_stack.stack_size - 1; i >= 0; i--) > + { > + if (instr_stack.entries[i] == instr) > + { > + idx = i; > + break; > + } > + } So this may not find a stack entry, because a prior call to InstrStopFinalize() already removed it from the stack, right? Makes it a bit more error prone. Maybe we should store whether the element is still on the stack in the Instrumentation, that way we a) can error out if we don't find it on the stack b) avoid searching the stack if already removed. > if (instr->need_timer) > + InstrStopTimer(instr); > + > + InstrAccumStack(instr_stack.current, instr); > +} Not that it's a huge issue, but seems like it'd be neater if the need_timer thing weren't duplicated, but implemented by calling InstrStop()? > +void > +InstrQueryStart(QueryInstrumentation *qinstr) > +{ > + InstrStart(&qinstr->instr); > + > + if (qinstr->instr.need_stack) > + { > + Assert(CurrentResourceOwner != NULL); > + qinstr->owner = CurrentResourceOwner; > + > + ResourceOwnerEnlarge(qinstr->owner); > + ResourceOwnerRememberInstrumentation(qinstr->owner, qinstr); > + } > +} > + > +void > +InstrQueryStop(QueryInstrumentation *qinstr) > +{ > + InstrStop(&qinstr->instr); > + > + if (qinstr->instr.need_stack) > + { > + Assert(qinstr->owner != NULL); > + ResourceOwnerForgetInstrumentation(qinstr->owner, qinstr); > + qinstr->owner = NULL; > + } > +} > + > +void > +InstrQueryStopFinalize(QueryInstrumentation *qinstr) > +{ > + InstrStopFinalize(&qinstr->instr); Why are these Instr[Query]StopFinalize() rather than just Instr[Query]Finalize()? > + if (!qinstr->instr.need_stack) > + return; Perhaps worth asserting that qinstr->{instr_cxt,owner} are NULL in this case? > +/* start instrumentation during parallel executor startup */ > +QueryInstrumentation * > +InstrStartParallelQuery(void) > +{ > + QueryInstrumentation *qinstr = InstrQueryAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); > + > + InstrQueryStart(qinstr); > + return qinstr; > +} Why do we hardcode INSTRUMENT_BUFFERS | INSTRUMENT_WAL? > From 80dbf65f79deca08f5e10872cac226d0d8edca0e Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Sun, 15 Mar 2026 21:44:58 -0700 > Subject: [PATCH v12 6/9] instrumentation: Use Instrumentation struct for > parallel workers > > This simplifies the DSM allocations a bit since we don't need to > separately allocate WAL and buffer usage, and allows the easier future > addition of a third stack-based struct being discussed. Does look a bit nicer. > From 16e44d5508f91dd23da780901f3ec0126965628d Mon Sep 17 00:00:00 2001 > From: Lukas Fittl <lukas@fittl.com> > Date: Sat, 7 Mar 2026 17:52:24 -0800 > Subject: [PATCH v12 7/9] instrumentation: Optimize ExecProcNodeInstr > instructions by inlining > > 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 > non-optimal set of instructions to be generated by the compiler. > > Because we already have an existing 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. This results in > the overhead for EXPLAIN (ANALYZE, TIMING OFF, BUFFERS OFF) for a stress > test with a large COUNT(*) that does many ExecProcNode calls from ~ 20% on > top of actual runtime to ~ 3%. When using BUFFERS ON the same query goes > from ~ 20% to ~ 10% on top of actual runtime. I assume this is to a significant degree due to to allowing for inlining. Have you checked how much of the effort you get by just putting ExecProcNodeInstr() into instrument.c? > +/* > + * Specialized handling of instrumented ExecProcNode > + * > + * 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. > + */ > + > +#include "executor/tuptable.h" > +#include "nodes/execnodes.h" > + > +/* 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.stack_size--; > + instr_stack.current = prev; > +} > + > +static inline TupleTableSlot * > +ExecProcNodeInstr(PlanState *node, bool need_timer, bool need_stack) This might need pg_attribute_always_inline to be reliable, the compiler otherwise might decide that it should not actually inline the function... > @@ -1014,7 +1016,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 <quote>lossy</quote> 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 <literal>Table Buffers</literal> > + counts indicate how many operations were performed on the table instead of > + the index. This number is included in the <literal>Buffers</literal> counts. > </para> > > <para> I wonder if listing "Index Buffers" separately, instead of "Table Buffers" would make more sense, because normally the number of index accesses is much smaller and therefore a bit easier to put into relation to "Buffers". > @@ -418,6 +418,29 @@ ExecInitNode(Plan *node, EState *estate, int eflags) > result->instrument = InstrAllocNode(estate->es_instrument, > result->async_capable); > > + /* > + * IndexScan / IndexOnlyScan track table and index access separately. > + * > + * We intentionally don't collect timing for them (even if enabled), since > + * we don't need it, and executor nodes call InstrPushStack / > + * InstrPopStack (instead of the full InstrNode*) to reduce overhead. > + */ > + if (estate->es_instrument && (estate->es_instrument->instrument_options & INSTRUMENT_BUFFERS) != 0) > + { > + if (IsA(result, IndexScanState)) > + { > + IndexScanState *iss = castNode(IndexScanState, result); > + > + InstrInitOptions(&iss->iss_Instrument->table_instr, INSTRUMENT_BUFFERS); > + } > + else if (IsA(result, IndexOnlyScanState)) > + { > + IndexOnlyScanState *ioss = castNode(IndexOnlyScanState, result); > + > + InstrInitOptions(&ioss->ioss_Instrument->table_instr, INSTRUMENT_BUFFERS); > + } > + } > + > return result; > } Why do this is in ExecInitNode(), rather than ExecInitIndexScan(), ExecInitIndexOnlyScan()? > @@ -165,11 +169,22 @@ IndexOnlyNext(IndexOnlyScanState *node) > ItemPointerGetBlockNumber(tid), > &node->ioss_VMBuffer)) > { > + bool found; > + > /* > * Rats, we have to visit the heap to check visibility. > */ > InstrCountTuples2(node, 1); > - if (!index_fetch_heap(scandesc, node->ioss_TableSlot)) > + > + if (table_instr) > + InstrPushStack(table_instr); > + > + found = index_fetch_heap(scandesc, node->ioss_TableSlot); > + > + if (table_instr) > + InstrPopStack(table_instr); > + > + if (!found) > continue; /* no visible tuple, try next index entry */ > > ExecClearTuple(node->ioss_TableSlot); As-is this will unfortunately rather terribly conflict with the way the index prefetching patch is restructuring things, as after it neither index nor indexonly scan does the equivalent of index_fetch_heap() anymore. This all goes through a tableam interface, which in turn will call to the index to get the tids (to allow for tableam specific prefetching logic, obviously). I think this would require putting this into the IndexScanDesc via the IndexScanInstrumentation etc. Might be good for you to look at how that stuff works after the index prefetching patch and comment if you see a problem. Greetings, Andres Freund -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-04-05T12:31:53Z
Hi Andres, Thanks for reviewing! On Sat, Apr 4, 2026 at 12:39 PM Andres Freund <andres@anarazel.de> wrote: > > Hi, > > On 2026-04-04 02:43:50 -0700, Lukas Fittl wrote: > > Attached v12, rebased, otherwise no changes. > > > > I realize time to freeze is getting close, and whilst I'd love to see > > this go in, I'm also realistic - so I'll just do my best to support > > review in the off chance we can make it for this release. > > I unfortunately think there's enough nontrivial design decisions - that I > don't have a sufficiently confident assesment of - that I would be pretty > hesitant to commit this at this stage of the cycle without some architectural > review by senior folks. If Heikki did another round or two of review, it'd be a > different story. Ack - I'll keep it updated as needed in the next days to help, but understand that there many competing priorities :) FWIW, I do feel like Heikki has taken a look at the memory management aspects, and Zsolt also had some good detailed feedback on lower level logic and OOM behaviour - so I'm actually less worried about these now. Heikki, your further review is very welcome, if you have the time. It'd also be great if you could review the README.instrument (now in v13/0008) to see if that makes sense to you. > I think the high level design is a huge improvement and goes in the right > direction, but some of the lower level stuff I'm far less confident about. Glad to hear - I also think that the direction here is right, and I don't think there is a lot of variance on architectural choices anymore. > > > On that note, I think 0001 and 0002 are independently useful > > refactorings to split the different kinds of instrumentation that > > should be ready to go, and I don't think should conflict much with > > other patches in this commitfest. > > Yea, I'll see that those get committed. > > I could also see 0004 as potentially worth getting committed separately, > although I'm a bit worried about test stability. Yeah, I understand. FWIW, the current approach has been stable in CI runs, but that doesn't mean something in the buildfarm won't complain. > I recently looked at a coverage report, in the context of the index > prefetching patch, and was a it surprised that prominent parallel executor > nodes have no coverage for EXPLAIN ANALYZE. > parallel BHS is not covered: > https://coverage.postgresql.org/src/backend/executor/nodeBitmapHeapscan.c.gcov.html#L536 > parallel IOS is not covered: > https://coverage.postgresql.org/src/backend/executor/nodeIndexonlyscan.c.gcov.html#L430 Ugh. Good catch, that lack of coverage is not good. I've added two tests for that, and guess what, I found a bug (unrelated to stack-based instrumentation) - show_tidbitmap_info doesn't correctly accumulate Heap Blocks information from the worker instrumentation - it only ever shows that of the leader. For such auxiliary information in a parallel context it needs to do the extra work, e.g. like show_indexsearches_info does. I've put that bugfix and BHS coverage into its own commit (0004) before the other tests, because I suspect we may even want to backpatch that. I've added coverage of IOS via a check for Index Searches as a new patch as well (0005). Let me know if you prefer if I start a new thread for those. See attached v13, with feedback addressed, unless otherwise noted below. I've also slightly simplified InstrAggNode, since I realized it is never called when running=true. > > > From 90a7ed18f14c09c8a1299db3a015747fc6b6761c Mon Sep 17 00:00:00 2001 > > From: Lukas Fittl <lukas@fittl.com> > > Date: Tue, 9 Sep 2025 02:16:59 -0700 > > Subject: [PATCH v12 5/9] Optimize measuring WAL/buffer usage through > > stack-based instrumentation > > > > 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 the > > function BufferUsageAccumDiff showing up in profiles and in some cases > > adding up to 10% overhead to an EXPLAIN (ANALYZE, BUFFERS) run. > > > > 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 InstrEndNode. 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. > > > > This also drops the global pgBufferUsage, any callers interested in > > measuring buffer activity should instead utilize InstrStart/InstrStop. > > > > 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. > > Probably worth stating what the performance overhead of WAL and BUFFERS is > after this patch? I've added a note re: BUFFERS referencing the COUNT(*) numbers from earlier in the thread - not sure if WAL is really worth it to talk about (its already quite a long commit message). > > > > @@ -1015,19 +994,9 @@ pgss_ExecutorStart(QueryDesc *queryDesc, int eflags) > > */ > > if (pgss_enabled(nesting_level) && queryDesc->plannedstmt->queryId != INT64CONST(0)) > > { > > - /* > > - * Set up to track total elapsed time in ExecutorRun. Make sure the > > - * space is allocated in the per-query context so it will go away at > > - * ExecutorEnd. > > - */ > > + /* Set up to track total elapsed time in ExecutorRun. */ > > if (queryDesc->totaltime == NULL) > > - { > > - MemoryContext oldcxt; > > - > > - oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt); > > - queryDesc->totaltime = InstrAlloc(INSTRUMENT_ALL); > > - MemoryContextSwitchTo(oldcxt); > > - } > > + queryDesc->totaltime = InstrQueryAlloc(INSTRUMENT_ALL); > > } > > } > > Not at all the fault of this patch, but it does seem somewhat odd to me that > we handle pgss/auto_explain wanting instrumentation by them updating the > QueryDesc->totaltime, rather than having extensions add an eflag to ask > standard_ExecutorStart to do so. Agreed, that interaction is a bit odd. I think it'd be reasonable to do this as a separate refactoring, especially now that I've stopped utilizing totaltime as the parent for per-node instrumentation, per later notes. > > > @@ -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)); > > @@ -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); > > Again not your fault, but it feels like the parallel index build > infrastructure is all wrong. Reimplementing this stuff for every index type > makes no sense. Fully agreed, the duplication here is quite something. The 0006 patch cleans this up a little bit by at least using the Instrumentation struct consistently. That is not required for the stack-based commit, but would be helpful if e.g. we were to put IO stats next to Buffer/WAL stats in the future. > > +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. > > Hm. This seems like a somewhat random example, why would one want this? > Hmm, yeah. I mainly included this because the fact that accumulation for the individual nodes in the EXPLAIN happens to be in a tree-like structure is a choice, no longer a requirement. It would be just as easy to only accumulate to the parent QueryInstrumentation, and let explain.c present you a choice of "BUFFERS SELF" / etc - we couldn't have done that previously. I've left this in for now, but maybe its better to drop it to avoid confusion? > > +If multiple QueryInstrumentations are active on the stack (e.g. nested > > +portals), each one's abort handler uses InstrStopFinalize to unwind to > > +whichever entry is higher up, so they compose correctly regardless of > > +release order. > > Maybe "the abort handler of each uses InstrStopFinalize() to accumulate the > statics to its parent entry"? I revised this as follows: 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. i.e. its worth noting that its explicitly not the parent of the stack entry being released, since that parent may already have been released itself (since cleanup can be out of order). > > +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) as a child > > +of TopMemoryContext. All child instrumentation (nodes, triggers) should be > > +allocated in this context. > > > +On successful completion, instr_cxt is reparented to CurrentMemoryContext > > +so its lifetime is tied to the caller's context. On abort, the > > +ResourceOwner cleanup frees it after accumulating the instrumentation data > > +to the current stack entry after resetting the stack. > > Makes sense. > > I mildly wonder if we should create one minimally sized "Instrumentations" > node under TopMemoryContext, below which the "Instrumentation" contexts are > created, instead of doing so directly under TopMemoryContext. But that's > something that can easily be evolved later. > Sure, grouping the instrumentation memory contexts could make sense, though the existing handling already serves the purpose of clearly showing when there is an instrumentation leak. I'll not make this change for now to avoid code churn, but as you note we could always adjust that part later. > > > @@ -247,9 +248,19 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags) > > estate->es_snapshot = RegisterSnapshot(queryDesc->snapshot); > > estate->es_crosscheck_snapshot = RegisterSnapshot(queryDesc->crosscheck_snapshot); > > estate->es_top_eflags = eflags; > > - estate->es_instrument = queryDesc->instrument_options; > > estate->es_jit_flags = queryDesc->plannedstmt->jitFlags; > > > > + /* > > + * Set up query-level instrumentation if needed. We do this before > > + * InitPlan so that node and trigger instrumentation can be allocated > > + * within the query's dedicated instrumentation memory context. > > + */ > > + if (!queryDesc->totaltime && queryDesc->instrument_options) > > + { > > + queryDesc->totaltime = InstrQueryAlloc(queryDesc->instrument_options); > > + estate->es_instrument = queryDesc->totaltime; > > + } > > + > > /* > > * Set up an AFTER-trigger statement context, unless told not to, or > > * unless it's EXPLAIN-only mode (when ExecutorFinish won't be called). > > It seems pretty weird to still have queryDesc->totaltime *sometimes* created > by pgss etc, but also create it in standard_ExecutorStart if not already > created. What if the explain options aren't compatible? Sure > pgss/auto_explain use ALL, but that's not a given. Yeah, I think in practice all use cases I've ever seen pass INSTRUMENT_ALL (and in fact it won't behave sane if this differs between extensions), but you're right there is no guarantee. Overall, there are two aspects to this: 1) Query instrumentation as the parent for node instrumentation, driven by use of EXPLAIN or auto_explain setting queryDesc->instrument_options 2) Instrumentation as a mechanism to measure the activity of a query, as used by pg_stat_statements or auto_explain (to get the runtime / aggregate buffer usage) I could see two solutions: A) Keep two separate QueryInstrumentations (EXPLAIN/auto_explain get es_instrument, any extensions measuring aggregate activity get query->totaltime) B) Have one internal QueryInstrumentation (that's responsible to be the abort "parent" to both node instrumentation, and query->totaltime) I was initially thinking we could maybe combine them creatively (i.e. expand on what we've done so far), but I'm not sure there is a reasonable design that isn't convoluted. We could also have a way for extensions to "request" a certain level of instrumentation (instead of directly allocating it), but it seems the current hooks are insufficient for that. I've gone with solution (A) for now, with es_instrument being allocated when per-node instrumentation is needed. Obviously that gets us two ResOwner cleanups instead of one when e.g. auto_explain is active, but I think that's still acceptable. It also shows how its easy to do an extra level of nesting with the stack-based instrumentation, without too much expense. With this in place, I do wonder if we should avoid the full memory context setup in InstrQueryAlloc (i.e. instead just make a direct allocation), unless we know that children are going to be attached. The downside of that would be that we can't just re-assign the instr_cxt in InstrQueryStopFinalize (we'd have to go back to the previous logic of doing a memcpy into the callers context, for the no-children case), but it might make a notable performance difference? > > > + /* Start up instrumentation for this execution run */ > > if (queryDesc->totaltime) > > - InstrStart(queryDesc->totaltime); > > + { > > + InstrQueryStart(queryDesc->totaltime); > > + > > + /* > > + * Remember all node entries for abort recovery. We do this once here > > + * after InstrQueryStart has pushed the parent stack entry. > > + */ > > + if (estate->es_instrument && > > + estate->es_instrument->instr.need_stack && > > + !queryDesc->already_executed) > > + ExecRememberNodeInstrumentation(queryDesc->planstate, > > + queryDesc->totaltime); > > + } > > Hm. Was briefly worried about the overhead of > ExecRememberNodeInstrumentation() in the context of cursors. But I see it's > only done once. > > But why do we not just associate the NodeInstrumentation's with the > QueryInstrumentation during the creation of the NodeInstrumentation? That's a good point - if I recall correctly that was structured differently in an earlier commit, hence the complexity. But this is no longer necessary, and allows us to drop the ExecRememberNodeInstrumentation machinery. Nice :) > > > + /* > > + * Accumulate per-node and trigger statistics to their respective parent > > + * instrumentation stacks. > > > > + * We skip this in parallel workers because their per-node stats are > > + * reported individually via ExecParallelReportInstrumentation, and the > > + * leader's own ExecFinalizeNodeInstrumentation handles propagation. If > > + * we accumulated here, the leader would double-count: worker parent nodes > > + * would already include their children's stats, and then the leader's > > + * accumulation would add the children again. > > + */ > > Haven't looked into how this all works in sufficient detail, so I'm just > asking you: This works correctly even when using EXPLAIN (ANALYZE, VERBOSE) > showing per-worker "subtrees"? Yeah, that's a good question, and you indeed found a bug - that was not correctly accumulating up for the per-worker node information. The main complexity here is the avoidance of double counting. I can think of two very different approaches to solve this: 1) Have finalization only be responsible for accumulating into the overall query instrumentation (or whichever instrumentation is active), and not bother with adding per-node instrumentation to the parent node at all. Then, in explain.c, do the accumulation. If we ever wanted to invent a "BUFFERS SELF" type option (i.e. don't add them to the parent), that would be the way to go. It'd also make it easier to support accumulation for other types of statistics being added (e.g. "EXPLAIN (IO)"). 2) Specifically walk the worker instrumentation after it has been retrieved (to avoid double counting), and add to each nodes parents. For now I've gone with (2) and added a dedicated ExecFinalizeWorkerInstrumentation function to deal with this. > > > > @@ -1284,8 +1325,8 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, > > palloc0_array(FmgrInfo, n); > > resultRelInfo->ri_TrigWhenExprs = (ExprState **) > > palloc0_array(ExprState *, n); > > - if (instrument_options) > > - resultRelInfo->ri_TrigInstrument = InstrAllocTrigger(n, instrument_options); > > + if (qinstr) > > + resultRelInfo->ri_TrigInstrument = InstrAllocTrigger(qinstr, n); > > Hm. Why do we not need to pass down the instrument_options anymore? I guess > the assumption is that we always are going to use the flags from qinstr? > > Is that right? Because right now pgss/auto_explain use _ALL, even when an > EXPLAIN ANALYZE doesn't. > With the solution mentioned earlier, where es_instrument is a separate allocation, this problem now goes away without any extra changes needed. Overall, I think its reasonable to make node/trigger instrumentation be attached to a query instrumentation that has the instrumentation options set that should be applied. That way we don't have think about edge cases like a query instrumentation that doesn't need a stack, but children that do. > > > @@ -1081,14 +1081,28 @@ ExecParallelRetrieveInstrumentation(PlanState *planstate, > > instrument = GetInstrumentationArray(instrumentation); > > instrument += i * instrumentation->num_workers; > > for (n = 0; n < instrumentation->num_workers; ++n) > > + { > > InstrAggNode(planstate->instrument, &instrument[n]); > > > > + /* > > + * Also add worker WAL usage to the global pgWalUsage counter. > > + * > > + * When per-node instrumentation is active, parallel workers skip > > + * ExecFinalizeNodeInstrumentation (to avoid double-counting in > > + * EXPLAIN), so per-node WAL activity is not rolled up into the > > + * query-level stats that InstrAccumParallelQuery receives. Without > > + * this, pgWalUsage would under-report WAL generated by parallel > > + * workers when instrumentation is active. > > + */ > > + WalUsageAdd(&pgWalUsage, &instrument[n].instr.walusage); > > + } > > I'm not sure I understand why this doesn't also lead to double counting, given > that InstrAccumParallelQuery() does also add the worker's usage to pgWalUsage? > That can be explained by the somewhat hard to follow difference between InstrAccumParallelQuery and InstrAggNode, which is a pre-existing situation: InstrAccumParallelQuery is used for accumulating the top level worker instrumentation into the instrumentation that's active when ExecParallelFinish runs. The active instrumentation at that point is either the query's instrumentation (or if not used, instr_top), or the Gather node. InstrAggNode is used for accumulating each worker's per-node instrumentation into the leader's per-node instrumentation. When per-node instrumentation is active (node->instrument is initialized), the WalUsageAdd occurs in both InstrAccumParallelQuery and InstrAggNode - but per the comment in standard_ExecutorFinish, we don't aggregate the per-node instrumentation to the top level of the parallel worker - and therefore InstrAccumParallelQuery would report basically no activity. I tried to explain this in the comment above WalUsageAdd, but maybe this needs further clarification? > > > +static bool > > +ExecFinalizeNodeInstrumentation_walker(PlanState *node, void *context) > > +{ > > + Instrumentation *parent = (Instrumentation *) context; > > + > > + Assert(parent != NULL); > > + > > + if (node == NULL) > > + return false; > > + > > + /* > > + * Recurse into children first (bottom-up accumulation), passing our > > + * instrumentation as the parent context. This ensures children can > > + * accumulate to us even if they were never executed by the leader (e.g. > > + * nodes beneath Gather that only workers ran). > > + */ > > + planstate_tree_walker(node, ExecFinalizeNodeInstrumentation_walker, > > + node->instrument ? &node->instrument->instr : parent); > > I don't think I understand that comment. What changes if the leader's node > was never executed? I think that was a timing issue in an earlier iteration, where the stack-based instrumentation data was a separate allocation from the main node instrumentation. Since that is no longer an issue, we can just require node->instrument to be initialized here. Reworded the comment and added an assert. > > > diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c > > index bc551f95a08..6892706a83a 100644 > > --- a/src/backend/executor/instrument.c > > +++ b/src/backend/executor/instrument.c > > @@ -16,30 +16,46 @@ > > #include <unistd.h> > > > > #include "executor/instrument.h" > > +#include "utils/memutils.h" > > +#include "utils/resowner.h" > > > > -BufferUsage pgBufferUsage; > > -static BufferUsage save_pgBufferUsage; > > WalUsage pgWalUsage; > > Why do we still need pgWalUsage if we have the same data in instr_stack. Yeah. That is because of two reasons: 1) The questionable use of pgWalUsage to inform pruneheap.c whether an FPI occurred. I think using pgWalUsage for this is just wrong, it should use its own flag/counter. This can't use the top level instrumentation stack since it'd be updated too late (only on executor finish, not as writes are going on). 2) The use of pgWalUsage to update cumulative WAL usage statistics. We could adjust this by having separate "pgstat_count_wal_.." functions (mirroring how we deal with cumulative buffer usage statistics), or by pulling the information from instrumentation stack and accepting that WAL statistics won't be refreshed whilst a query is executing (which is probably not okay? i.e. we might then have to invent some mechanism to periodically "flush" before the actual finalize). Addressing (1) would be somewhat straightforward, so maybe the best way fowrard is to do that, and then refactor this to use separate "pgstat_count_wal_.." functions instead of keeping the pgWalUsage global. I'll not do that here for now, since I don't think the double writing of WAL stats is performance critical, and we'd still do that anyway when having separate "pgstat_count_wal_.." functions. > > > +/* > > + * 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. > > + * > > + * We are careful here to achieve two goals: > > + * > > + * 1) Reset the stack to the parent of whichever of the released stack entries > > + * has the lowest index > > + * 2) Accumulate all instrumentation to the currently active instrumentation, > > + * so that callers get a complete picture of activity, even after an abort > > + */ > > +void > > +InstrStopFinalize(Instrumentation *instr) > > +{ > > + int idx = -1; > > + > > + for (int i = instr_stack.stack_size - 1; i >= 0; i--) > > + { > > + if (instr_stack.entries[i] == instr) > > + { > > + idx = i; > > + break; > > + } > > + } > > So this may not find a stack entry, because a prior call to > InstrStopFinalize() already removed it from the stack, right? > > Makes it a bit more error prone. Maybe we should store whether the element is > still on the stack in the Instrumentation, that way we a) can error out if we > don't find it on the stack b) avoid searching the stack if already removed. Yeah, that seems doable, added that as suggested. It does add an extra instruction to InstrPushStack/InstrPopStack, but that's probably not significant enough. We could always turn it into an assert-only check if that's the case. > > if (instr->need_timer) > > + InstrStopTimer(instr); > > + > > + InstrAccumStack(instr_stack.current, instr); > > +} > > Not that it's a huge issue, but seems like it'd be neater if the need_timer > thing weren't duplicated, but implemented by calling InstrStop()? That'd be a problem since InstrStop also pops the stack (if need_stack=true), and InstrStopFinalize already popped the stack right before. I think the only alternative here would be adding a flag on InstrStop, but that seems worse to me. > > > +void > > +InstrQueryStart(QueryInstrumentation *qinstr) > > +{ > > + InstrStart(&qinstr->instr); > > + > > + if (qinstr->instr.need_stack) > > + { > > + Assert(CurrentResourceOwner != NULL); > > + qinstr->owner = CurrentResourceOwner; > > + > > + ResourceOwnerEnlarge(qinstr->owner); > > + ResourceOwnerRememberInstrumentation(qinstr->owner, qinstr); > > + } > > +} > > + > > +void > > +InstrQueryStop(QueryInstrumentation *qinstr) > > +{ > > + InstrStop(&qinstr->instr); > > + > > + if (qinstr->instr.need_stack) > > + { > > + Assert(qinstr->owner != NULL); > > + ResourceOwnerForgetInstrumentation(qinstr->owner, qinstr); > > + qinstr->owner = NULL; > > + } > > +} > > + > > +void > > +InstrQueryStopFinalize(QueryInstrumentation *qinstr) > > +{ > > + InstrStopFinalize(&qinstr->instr); > > Why are these Instr[Query]StopFinalize() rather than just > Instr[Query]Finalize()? If you're coming at this from a naming perspective: Mainly to make it clear that these both stop the instrumentation, and finalize it. If we only called it "Instr[Query]Finalize" it wouldn't be clear that there isn't a missing "Stop" call. Alternatively we could: 1) Require callers to do two separate function calls 2) Have a "finalize" argument to the Stop function. I had that in a prior iteration, but felt it was easier to miss the subtle true/false difference. > > +/* start instrumentation during parallel executor startup */ > > +QueryInstrumentation * > > +InstrStartParallelQuery(void) > > +{ > > + QueryInstrumentation *qinstr = InstrQueryAlloc(INSTRUMENT_BUFFERS | INSTRUMENT_WAL); > > + > > + InstrQueryStart(qinstr); > > + return qinstr; > > +} > > Why do we hardcode INSTRUMENT_BUFFERS | INSTRUMENT_WAL? > That's reflecting the fact that parallel workers can only transport these two instrumentation types. The 0006 patch removes that hardcoding. I'll add a comment in the earlier patch for now, for clarity. > > > From 16e44d5508f91dd23da780901f3ec0126965628d Mon Sep 17 00:00:00 2001 > > From: Lukas Fittl <lukas@fittl.com> > > Date: Sat, 7 Mar 2026 17:52:24 -0800 > > Subject: [PATCH v12 7/9] instrumentation: Optimize ExecProcNodeInstr > > instructions by inlining > > > > 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 > > non-optimal set of instructions to be generated by the compiler. > > > > Because we already have an existing 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. This results in > > the overhead for EXPLAIN (ANALYZE, TIMING OFF, BUFFERS OFF) for a stress > > test with a large COUNT(*) that does many ExecProcNode calls from ~ 20% on > > top of actual runtime to ~ 3%. When using BUFFERS ON the same query goes > > from ~ 20% to ~ 10% on top of actual runtime. > > I assume this is to a significant degree due to to allowing for inlining. Have > you checked how much of the effort you get by just putting ExecProcNodeInstr() > into instrument.c? Worth a try - I haven't tested that yet - I'll come back to this separately and verify how much that buys us, vs spelling out the different variants. > > > @@ -1014,7 +1016,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 <quote>lossy</quote> 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 <literal>Table Buffers</literal> > > + counts indicate how many operations were performed on the table instead of > > + the index. This number is included in the <literal>Buffers</literal> counts. > > </para> > > > > <para> > > I wonder if listing "Index Buffers" separately, instead of "Table Buffers" > would make more sense, because normally the number of index accesses is much > smaller and therefore a bit easier to put into relation to "Buffers". > I don't think changing this to be focused on index buffers makes sense (but my opinion is weakly held). My arguments for why it doesn't make sense: 1) The primary activity of the node is the index (only) scan. The fact that it also does table access is what we're trying to call out, just like we're calling out heap fetches. 2) For index only scans the inverse of what you noted is true, i.e. you'd expect many more index buffers with very little table buffers. The fact that there were any table buffers at all is worth calling out. > > > @@ -165,11 +169,22 @@ IndexOnlyNext(IndexOnlyScanState *node) > > ItemPointerGetBlockNumber(tid), > > &node->ioss_VMBuffer)) > > { > > + bool found; > > + > > /* > > * Rats, we have to visit the heap to check visibility. > > */ > > InstrCountTuples2(node, 1); > > - if (!index_fetch_heap(scandesc, node->ioss_TableSlot)) > > + > > + if (table_instr) > > + InstrPushStack(table_instr); > > + > > + found = index_fetch_heap(scandesc, node->ioss_TableSlot); > > + > > + if (table_instr) > > + InstrPopStack(table_instr); > > + > > + if (!found) > > continue; /* no visible tuple, try next index entry */ > > > > ExecClearTuple(node->ioss_TableSlot); > > As-is this will unfortunately rather terribly conflict with the way the index > prefetching patch is restructuring things, as after it neither index nor > indexonly scan does the equivalent of index_fetch_heap() anymore. This all > goes through a tableam interface, which in turn will call to the index to get > the tids (to allow for tableam specific prefetching logic, obviously). > > I think this would require putting this into the IndexScanDesc via the > IndexScanInstrumentation etc. > > > Might be good for you to look at how that stuff works after the index > prefetching patch and comment if you see a problem. Agreed, I'll look at that tomorrow. Well, today, I suppose, looking at the clock.. Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Andres Freund <andres@anarazel.de> — 2026-04-05T18:13:51Z
Hi, Not a real reply to your email, just looking at committing 0001/0002 to get them out of the way. Unfortunately I think 0001 on its own doesn't actually work correctly. I luckily tried an EXPLAIN ANALYZE with triggers and noticed that the time is reported as zeroes. The only reason I tried is because I misread the diff and though you'd changed the calls=%.3f to calls=%d, even though the old state is calls=%.0f... The reason it doesn't work is that explain shows tginstr->instr.total, but with the patch the trigger instrumentation just computes tginstr->instr.{counter,firsttuple}. And of course we don't have any tests even showing trigger output. Not that such a test would have been likely to catch this issue, as something like the the amount of time is nontrivial to test. This is actually fixed by 0002, as it makes InstrStop() update ->total, rather than ->counter as before. But I'd prefer not to break the intermediary state ;). I guess we could squash both patches? But probably the least bad solution is to add an InstrEndLoop() to in 0001 and remove it again in 0002. Re 0002 In passing, drop the "n" argument to InstrAlloc, as all remaining callers need exactly one Instrumentation struct. I think that probably should be in 0001? I'm kinda wondering whether, to keep the line lenghts manageable, --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -1837,7 +1837,7 @@ ExplainNode(PlanState *planstate, List *ancestors, { double nloops = planstate->instrument->nloops; double startup_ms = INSTR_TIME_GET_MILLISEC(planstate->instrument->startup) / nloops; - double total_ms = INSTR_TIME_GET_MILLISEC(planstate->instrument->total) / nloops; + double total_ms = INSTR_TIME_GET_MILLISEC(planstate->instrument->instr.total) / nloops; double rows = planstate->instrument->ntuples / nloops; Should store planstate->instrument in a local var and wrap after =. But not sure it's worth bothering with. Greetings, Andres Freund -
Re: Stack-based tracking of per-node WAL/buffer usage
Heikki Linnakangas <hlinnaka@iki.fi> — 2026-04-05T18:22:25Z
On 05/04/2026 15:31, Lukas Fittl wrote: > Heikki, your further review is very welcome, if you have the time. > It'd also be great if you could review the README.instrument (now in > v13/0008) to see if that makes sense to you. I don't have very substantial comments to make, an haven't had a chance to review the latest patch, but I did read your replies. I think I understand the stack vs. tree model now and why it is the way it is, but I still find it pretty confusing and I don't know what to about it. - Heikki
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-04-05T19:38:58Z
On Sun, Apr 5, 2026 at 11:13 AM Andres Freund <andres@anarazel.de> wrote: > Unfortunately I think 0001 on its own doesn't actually work correctly. I > luckily tried an EXPLAIN ANALYZE with triggers and noticed that the time is > reported as zeroes. > > The only reason I tried is because I misread the diff and though you'd changed > the calls=%.3f to calls=%d, even though the old state is calls=%.0f... > > > The reason it doesn't work is that explain shows tginstr->instr.total, but > with the patch the trigger instrumentation just computes > tginstr->instr.{counter,firsttuple}. Argh, good catch. That's on me for not manually testing it when I factored it out. I've confirmed this works now, both with 0001 only, and with 0001+0002. > But probably the least bad solution is to add an InstrEndLoop() to in 0001 and > remove it again in 0002. Yeah, I've done that for now. > > Re 0002 > > In passing, drop the "n" argument to InstrAlloc, as all remaining callers > need exactly one Instrumentation struct. > > I think that probably should be in 0001? Ack, done. > > > I'm kinda wondering whether, to keep the line lenghts manageable, > --- a/src/backend/commands/explain.c > +++ b/src/backend/commands/explain.c > @@ -1837,7 +1837,7 @@ ExplainNode(PlanState *planstate, List *ancestors, > { > double nloops = planstate->instrument->nloops; > double startup_ms = INSTR_TIME_GET_MILLISEC(planstate->instrument->startup) / nloops; > - double total_ms = INSTR_TIME_GET_MILLISEC(planstate->instrument->total) / nloops; > + double total_ms = INSTR_TIME_GET_MILLISEC(planstate->instrument->instr.total) / nloops; > double rows = planstate->instrument->ntuples / nloops; > > Should store planstate->instrument in a local var and wrap after =. > > But not sure it's worth bothering with. Sure, seems easy enough. See attached v14 with changes to 0001 and 0002 only. I've also moved the PBHS/PIOS patches to their own thread [0]. Thanks, Lukas [0]: https://www.postgresql.org/message-id/CAP53PkxRrRKLXECGNFTVOtUusBoWLutZiPfnbejX40ocLuFMQA@mail.gmail.com -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Andres Freund <andres@anarazel.de> — 2026-04-05T21:02:28Z
Hi, On 2026-04-05 12:38:58 -0700, Lukas Fittl wrote: > On Sun, Apr 5, 2026 at 11:13 AM Andres Freund <andres@anarazel.de> wrote: > > Unfortunately I think 0001 on its own doesn't actually work correctly. I > > luckily tried an EXPLAIN ANALYZE with triggers and noticed that the time is > > reported as zeroes. > > > > The only reason I tried is because I misread the diff and though you'd changed > > the calls=%.3f to calls=%d, even though the old state is calls=%.0f... > > > > > > The reason it doesn't work is that explain shows tginstr->instr.total, but > > with the patch the trigger instrumentation just computes > > tginstr->instr.{counter,firsttuple}. > > Argh, good catch. That's on me for not manually testing it when I > factored it out. > > I've confirmed this works now, both with 0001 only, and with 0001+0002. I made 'firings' an an int64, rather than int. Could have made it unsigned, but ExplainPropertyInteger accepts an int64... Because the patch did change those lines anyway, I replaced palloc0(sizeof(Instrumentation)) with palloc_object(), and palloc0(n * sizeof(TriggerInstrumentation)) with palloc_array(). It also seemed silly to have an if around the assingments of need_*: if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER | INSTRUMENT_WAL)) { instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0; instr->need_walusage = (instrument_options & INSTRUMENT_WAL) != 0; instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0; instr->async_mode = async_mode; but that gets cleared up in 0002 anyway. But it did lead me to notice a pre-existing bug: We only set async_mode in the if (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER | INSTRUMENT_WAL) branch. It looks like that doesn't matter today, because all async_mode is used for is /* * In async mode, if the plan node hadn't emitted any tuples before, * this might be the first tuple */ if (instr->async_mode && save_tuplecount < 1.0) instr->firsttuple = instr->counter; and without INSTRUMENT_TIMER instr->counter would be zero anyway. But I guess it's worth noting that in the commit message for 0002? I felt a bit silly leaving the instr->need_* stuff in InstrAlloc(), when there is InstrInit() directly afterwards that does the same thing, but then that leads to removing the redundant memset etc, so I left it for 0002. With that I pushed 0001. Greetings, Andres Freund -
Re: Stack-based tracking of per-node WAL/buffer usage
Andres Freund <andres@anarazel.de> — 2026-04-05T23:12:08Z
Hi, On 2026-04-05 17:02:28 -0400, Andres Freund wrote: > With that I pushed 0001. For 0002 I: - fixed a few comments still refering to node in the generic Instr* functions - added comment about the async_mode buglet to the commit message - added an async_mode argument to InstrInitNode(), as its callsite already needed to be touched, and it felt wrong that InstrAllocNode() could do things that were not possible with InstrInitNode() - Deduplicated the code between InstrStop() and InstrStotNode() by introducing InstrStopCommon() After those (and some testing) I pushed this. Greetings, Andres Freund
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-04-06T09:26:20Z
On Sun, Apr 5, 2026 at 5:31 AM Lukas Fittl <lukas@fittl.com> wrote: > > On Sat, Apr 4, 2026 at 12:39 PM Andres Freund <andres@anarazel.de> wrote: > > > > > @@ -247,9 +248,19 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags) > > > estate->es_snapshot = RegisterSnapshot(queryDesc->snapshot); > > > estate->es_crosscheck_snapshot = RegisterSnapshot(queryDesc->crosscheck_snapshot); > > > estate->es_top_eflags = eflags; > > > - estate->es_instrument = queryDesc->instrument_options; > > > estate->es_jit_flags = queryDesc->plannedstmt->jitFlags; > > > > > > + /* > > > + * Set up query-level instrumentation if needed. We do this before > > > + * InitPlan so that node and trigger instrumentation can be allocated > > > + * within the query's dedicated instrumentation memory context. > > > + */ > > > + if (!queryDesc->totaltime && queryDesc->instrument_options) > > > + { > > > + queryDesc->totaltime = InstrQueryAlloc(queryDesc->instrument_options); > > > + estate->es_instrument = queryDesc->totaltime; > > > + } > > > + > > > /* > > > * Set up an AFTER-trigger statement context, unless told not to, or > > > * unless it's EXPLAIN-only mode (when ExecutorFinish won't be called). > > > > It seems pretty weird to still have queryDesc->totaltime *sometimes* created > > by pgss etc, but also create it in standard_ExecutorStart if not already > > created. What if the explain options aren't compatible? Sure > > pgss/auto_explain use ALL, but that's not a given. > > Yeah, I think in practice all use cases I've ever seen pass > INSTRUMENT_ALL (and in fact it won't behave sane if this differs > between extensions), but you're right there is no guarantee. > > Overall, there are two aspects to this: > > 1) Query instrumentation as the parent for node instrumentation, > driven by use of EXPLAIN or auto_explain setting > queryDesc->instrument_options > > 2) Instrumentation as a mechanism to measure the activity of a query, > as used by pg_stat_statements or auto_explain (to get the runtime / > aggregate buffer usage) > > I could see two solutions: > > A) Keep two separate QueryInstrumentations (EXPLAIN/auto_explain get > es_instrument, any extensions measuring aggregate activity get > query->totaltime) > > B) Have one internal QueryInstrumentation (that's responsible to be > the abort "parent" to both node instrumentation, and query->totaltime) > > I was initially thinking we could maybe combine them creatively (i.e. > expand on what we've done so far), but I'm not sure there is a > reasonable design that isn't convoluted. We could also have a way for > extensions to "request" a certain level of instrumentation (instead of > directly allocating it), but it seems the current hooks are > insufficient for that. > > I've gone with solution (A) for now, with es_instrument being > allocated when per-node instrumentation is needed. Obviously that gets > us two ResOwner cleanups instead of one when e.g. auto_explain is > active, but I think that's still acceptable. It also shows how its > easy to do an extra level of nesting with the stack-based > instrumentation, without too much expense. > > With this in place, I do wonder if we should avoid the full memory > context setup in InstrQueryAlloc (i.e. instead just make a direct > allocation), unless we know that children are going to be attached. > The downside of that would be that we can't just re-assign the > instr_cxt in InstrQueryStopFinalize (we'd have to go back to the > previous logic of doing a memcpy into the callers context, for the > no-children case), but it might make a notable performance difference? I've done a stress test of the logic I had added here in v13 (two separate QueryInstrumentations to not mess with query->totaltime), specifically "pgbench -n -j 32 -c 32 -f select1.sql -T 60 postgres" with auto_explain enabled with all log_* settings (so its both exercising query->totaltime and instrument_options), and unfortunately that showed about a 1 to 2% impact. So I don't think this was the right direction. I'll go back to what I had before, but fix the specific issue you pointed out when instrumentation options differ. Specifically, I'll add a preparatory patch to stop extensions from allocating queryDesc->totaltime themselves, and add queryDesc->totaltime_options that they use to request which level of totaltime instrumentation they need. If they request less than INSTRUMENT_ALL, they might still get more instrumentation actually collected, when the query in question is an EXPLAIN (ANALYZE). But since they don't have to read those fields from query->totaltime, I think that's acceptable. > > > > > > > > @@ -1284,8 +1325,8 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, > > > palloc0_array(FmgrInfo, n); > > > resultRelInfo->ri_TrigWhenExprs = (ExprState **) > > > palloc0_array(ExprState *, n); > > > - if (instrument_options) > > > - resultRelInfo->ri_TrigInstrument = InstrAllocTrigger(n, instrument_options); > > > + if (qinstr) > > > + resultRelInfo->ri_TrigInstrument = InstrAllocTrigger(qinstr, n); > > > > Hm. Why do we not need to pass down the instrument_options anymore? I guess > > the assumption is that we always are going to use the flags from qinstr? > > > > Is that right? Because right now pgss/auto_explain use _ALL, even when an > > EXPLAIN ANALYZE doesn't. > > > > With the solution mentioned earlier, where es_instrument is a separate > allocation, this problem now goes away without any extra changes > needed. > > Overall, I think its reasonable to make node/trigger instrumentation > be attached to a query instrumentation that has the instrumentation > options set that should be applied. That way we don't have think about > edge cases like a query instrumentation that doesn't need a stack, but > children that do. Because we now again have a query->totaltime that may have more instrumentation_options than the per-node/per-trigger instrumentation need, we need to explicitly pass the instrumentation options that were requested. To support that I'll bring back "es_instrument" with its prior meaning, and instead add "es_query_instr" to pass down the query instrumentation to the trigger instrumentation calls. > > > > > From 16e44d5508f91dd23da780901f3ec0126965628d Mon Sep 17 00:00:00 2001 > > > From: Lukas Fittl <lukas@fittl.com> > > > Date: Sat, 7 Mar 2026 17:52:24 -0800 > > > Subject: [PATCH v12 7/9] instrumentation: Optimize ExecProcNodeInstr > > > instructions by inlining > > > > > > 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 > > > non-optimal set of instructions to be generated by the compiler. > > > > > > Because we already have an existing 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. This results in > > > the overhead for EXPLAIN (ANALYZE, TIMING OFF, BUFFERS OFF) for a stress > > > test with a large COUNT(*) that does many ExecProcNode calls from ~ 20% on > > > top of actual runtime to ~ 3%. When using BUFFERS ON the same query goes > > > from ~ 20% to ~ 10% on top of actual runtime. > > > > I assume this is to a significant degree due to to allowing for inlining. Have > > you checked how much of the effort you get by just putting ExecProcNodeInstr() > > into instrument.c? > > Worth a try - I haven't tested that yet - I'll come back to this > separately and verify how much that buys us, vs spelling out the > different variants. I've run a test of just putting ExecProcNodeInstr into instrument.c (and adding an inline keyword to the functions it calls), and it does help over not doing it at all, but its not the full experience: CREATE TABLE lotsarows(key int not null); INSERT INTO lotsarows SELECT generate_series(1, 50000000); VACUUM FREEZE lotsarows; EXPLAIN (ANALYZE, ...) SELECT count(*) FROM lotsarows; Below measurements are best out of three, for these three versions: (1) with stack only (2) with stack + move ExecProcNodeInstr with no changes (your idea) (3) with stack + move + avoid branches (current patch set) BUFFERS OFF, TIMING OFF: (1): 309ms (2): 292ms (3): 283ms BUFFERS ON, TIMING OFF: (1): 322ms (2): 314ms (3): 294ms BUFFERS ON, TIMING ON: (1): 829ms (2): 814ms (3): 803ms I suspect the discrepancy for BUFFERS in particular is because the commit has an optimized form of the stack popping (InstrPopStackTo), but I have not taken a close look at the assembly differences here. For now I'll keep this as-is, but that can be changed quickly. Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-04-06T09:58:39Z
On Sun, Apr 5, 2026 at 4:12 PM Andres Freund <andres@anarazel.de> wrote: > > Hi, > > On 2026-04-05 17:02:28 -0400, Andres Freund wrote: > > With that I pushed 0001. > > For 0002 I: > - fixed a few comments still refering to node in the generic Instr* functions > - added comment about the async_mode buglet to the commit message > - added an async_mode argument to InstrInitNode(), as its callsite already > needed to be touched, and it felt wrong that InstrAllocNode() could do > things that were not possible with InstrInitNode() > - Deduplicated the code between InstrStop() and InstrStotNode() by introducing > InstrStopCommon() > > After those (and some testing) I pushed this. > Thanks for pushing these two! And appreciate the refinements, they make sense to me. Attached v15. Quick summary: 0001 converts direct users of pgBufferUsage/pgWalUsage to the new general purpose Instrumentation just pushed. 0002 introduces the macros needed for the stack-based instrumentation, same as before. 0003 adds additional test coverage for buffer usage, same as before. 0004 is new, and adds queryDesc->totaltime_options for extensions to request a certain level of totaltime measurement (this solves the problem Andres noted in a review comment) 0005 is the stack-based instrumentation commit, now smaller and more digestible, with the same performance benefits. -- if we get up to here, we get the main benefit -- 0006 is the parallel instrumentation cleanup. I don't think we need this right now unless the EXPLAIN (IO) work changes course. 0007 is the same ExecProcNodeInstr change as before (this one we could simplify by simply moving the function, getting about half the possible speedup) 0008 is the table-specific buffer measurement for index scans (for current master) 0009 is the test module for top level instrumentation data. I've also attached an alternate for 0008, that works on top of the index prefetch work (v23) - the change actually gets smaller because heap fetches are better encapsulated then. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Zsolt Parragi <zsolt.parragi@percona.com> — 2026-04-06T22:46:46Z
I couldn't find any issues with v15, all comments are stylistic/minor, except maybe the first one. + /* Abort handling: link in parent QueryInstrumentation's unfinalized list */ + dlist_node unfinalized_entry; Is it okay to store a pointer in shared memory, even if it seems to be always NULL there? #ifndef INSTRUMENT_NODE_H #define INSTRUMENT_NODE_H + +#include "executor/tuptable.h" +#include "nodes/execnodes.h" + Is it okay to incude files in the middle of the file, is there a good reason why these can't be at the top of the file? + * Recurse into children first (bottom-up accumulation), and accummulate + * to this nodes instrumentation as the parent context. Two typos (accumulate / this node's) #define RELEASE_PRIO_FILES 600 #define RELEASE_PRIO_WAITEVENTSETS 700 +#define RELEASE_PRIO_INSTRUMENTATION 800 This is mainly a generic observation, not strictly related to this patch, but this list could use some explanation which of these priorities are actually required by dependencies, and which are just "put the new entry at the end of the list".
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-04-07T00:39:15Z
On Mon, Apr 6, 2026 at 3:46 PM Zsolt Parragi <zsolt.parragi@percona.com> wrote: > > I couldn't find any issues with v15, all comments are stylistic/minor, > except maybe the first one. Thanks for reviewing! > > + /* Abort handling: link in parent QueryInstrumentation's unfinalized list */ > + dlist_node unfinalized_entry; > > Is it okay to store a pointer in shared memory, even if it seems to be > always NULL there? Its not ideal, mainly because a caller might interpret it incorrectly, but as long as we don't read from it, its safe in practice. In the parallel instrumentation we just use the Instrumentation struct as a way to transport data (with the 0006 patch applied), and we copy/accumulate from it before it gets used elsewhere. I've previously avoided putting the unfinalized_entry value in the Instrumentation struct for that reason, but I don't think there is a good way to avoid that without complicating the design. > > #ifndef INSTRUMENT_NODE_H > #define INSTRUMENT_NODE_H > > + > +#include "executor/tuptable.h" > +#include "nodes/execnodes.h" > + > > Is it okay to incude files in the middle of the file, is there a good > reason why these can't be at the top of the file? Yeah, those need to be on the top of the file, good catch. > > + * Recurse into children first (bottom-up accumulation), and accummulate > + * to this nodes instrumentation as the parent context. > > Two typos (accumulate / this node's) Good catch, agreed those are typos. > > #define RELEASE_PRIO_FILES 600 > #define RELEASE_PRIO_WAITEVENTSETS 700 > +#define RELEASE_PRIO_INSTRUMENTATION 800 > > This is mainly a generic observation, not strictly related to this > patch, but this list could use some explanation which of these > priorities are actually required by dependencies, and which are just > "put the new entry at the end of the list". Agreed, that would be helpful. It'll require more investigation to confirm particular ordering reasons that exist today, but it seems worth explaining more clearly. I'll hold off on posting another patch round since what you raised were just small stylistic issues, and they don't apply to the remaining prep patches before the stack patch itself. Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-04-07T20:30:11Z
On Mon, Apr 6, 2026 at 5:39 PM Lukas Fittl <lukas@fittl.com> wrote: > > On Mon, Apr 6, 2026 at 3:46 PM Zsolt Parragi <zsolt.parragi@percona.com> wrote: > > > > I couldn't find any issues with v15, all comments are stylistic/minor, > > except maybe the first one. > > Thanks for reviewing! > > ... > > I'll hold off on posting another patch round since what you raised > were just small stylistic issues, and they don't apply to the > remaining prep patches before the stack patch itself. Attached v16, rebased with Zsolt's feedback addressed. I've also re-ordered as follows: 0001 is the change to make queryDesc->totaltime be allocated by ExecutorStart instead of plugins themselves, and adds a queryDesc->totaltime_options to have plugins request which level of summary instrumentation they need. This change is pretty simple, and could still make sense to get into 19. Because of the earlier Instrumentation refactoring that was pushed (thanks!) we're already asking extensions allocating queryDesc->totaltime to modify their use of InstrAlloc, so I think we might as well clean this up now. 0002 is just ExecProcNodeInstr moved to instrument.c, as Andres had suggested previously. We still get some quick performance wins from doing that (see end of email), and again, its a simple change, so could be considered if someone has bandwidth remaining. I've added a later patch that then does the more complex inlining and gets us the full speed up. At this point I'd say its safe to say that we should push out later changes to PG20, because it needs another good look over, and I don't think Andres or Heikki have the capacity for that today (but I really appreciate all the effort put in by both of you!). --- 0002 measurements (with current master and TSC clock source used for timing, best of three): CREATE TABLE lotsarows(key int not null); INSERT INTO lotsarows SELECT generate_series(1, 50000000); VACUUM FREEZE lotsarows; master: 265.319 ms actual runtime 308.532 ms TIMING OFF, BUFFERS OFF 375.810 ms TIMING OFF, BUFFERS ON 381.701 ms TIMING ON, BUFFERS OFF 437.722 ms TIMING ON, BUFFERS ON 0002: 265.207 ms actual runtime 291.799 ms TIMING OFF, BUFFERS OFF 364.653 ms TIMING OFF, BUFFERS ON 359.759 ms TIMING ON, BUFFERS OFF 433.023 ms TIMING ON, BUFFERS ON full patch set: 265.763 ms actual runtime 273.222 ms TIMING OFF, BUFFERS OFF 293.621 ms TIMING OFF, BUFFERS ON 331.926 ms TIMING ON, BUFFERS OFF 363.055 ms TIMING ON, BUFFERS ON Thanks, Lukas -- Lukas Fittl
-
Re: Stack-based tracking of per-node WAL/buffer usage
Andres Freund <andres@anarazel.de> — 2026-04-07T22:19:06Z
Hi, On 2026-04-07 13:30:11 -0700, Lukas Fittl wrote: > 0001 is the change to make queryDesc->totaltime be allocated by > ExecutorStart instead of plugins themselves, and adds a > queryDesc->totaltime_options to have plugins request which level of > summary instrumentation they need. This change is pretty simple, and > could still make sense to get into 19. Because of the earlier > Instrumentation refactoring that was pushed (thanks!) we're already > asking extensions allocating queryDesc->totaltime to modify their use > of InstrAlloc, so I think we might as well clean this up now. Hm. That's a fair argument. They indeed would have to again change next release It's not a complicated change and removes more lines than it adds. I guess one thing I'm not sure is whether the fields shouldn't be renamed at the same time: a) To prevent extensions from continuing to set it, most of them do not test against assert enabled builds. With a different name they would get a compiler error. b) "totaltime" and "totaltime_options" are pretty poor descriptors of tracking query level statistics. If everyone has to change anyway, this is a good occasion. 'query_instr[_options]'? Any opinions? > 0002 is just ExecProcNodeInstr moved to instrument.c, as Andres had > suggested previously. We still get some quick performance wins from > doing that (see end of email), and again, its a simple change, so > could be considered if someone has bandwidth remaining. I've added a > later patch that then does the more complex inlining and gets us the > full speed up. Here it needs a few more inlines to get the full performance, otherwise it doesn't inline all the helpers. I think on balance I didn't like the prototype in instrument.h, that's too widely included, and it might even cause some circularity issues. It seems better to do the somewhat ugly thing and have the prototype be in executor.h. > 0002 measurements (with current master and TSC clock source used for > timing, best of three): > > CREATE TABLE lotsarows(key int not null); > INSERT INTO lotsarows SELECT generate_series(1, 50000000); > VACUUM FREEZE lotsarows; With the somewhat more extreme benchmark I used in the rdtsc thread and the added inline mentioned above I see a bit bigger wins. See the attached explainbench.sql - it doesn't quite cover all the combinations, but I think it gives a good enough overview. c=1 pgbench -f ~/tmp/explainbench.sql -P5 -r -t 10 master: statement latencies in milliseconds and failures: 200.800 0 SELECT pg_prewarm('pgbench_accounts'); 0.098 0 PREPARE query AS SELECT * FROM pgbench_accounts OFFSET 5000000 LIMIT 1; 212.010 0 EXPLAIN (ANALYZE, BUFFERS OFF, WAL OFF, TIMING OFF) 268.648 0 EXPLAIN (ANALYZE, BUFFERS OFF, WAL OFF, TIMING ON) 232.421 0 EXPLAIN (ANALYZE, BUFFERS ON, WAL ON, TIMING OFF) 283.531 0 EXPLAIN (ANALYZE, BUFFERS ON, WAL ON, TIMING ON) 0.030 0 DEALLOCATE query; 0002: statement latencies in milliseconds and failures: 201.558 0 SELECT pg_prewarm('pgbench_accounts'); 0.103 0 PREPARE query AS SELECT * FROM pgbench_accounts OFFSET 5000000 LIMIT 1; 188.696 0 EXPLAIN (ANALYZE, BUFFERS OFF, WAL OFF, TIMING OFF) 244.479 0 EXPLAIN (ANALYZE, BUFFERS OFF, WAL OFF, TIMING ON) 223.773 0 EXPLAIN (ANALYZE, BUFFERS ON, WAL ON, TIMING OFF) 266.947 0 EXPLAIN (ANALYZE, BUFFERS ON, WAL ON, TIMING ON) 0.034 0 DEALLOCATE query; That's something like 4-12%. Pretty nice for a patch that just adds a few lines around and adds a few inlines. > At this point I'd say its safe to say that we should push out later > changes to PG20, because it needs another good look over, and I don't > think Andres or Heikki have the capacity for that today (but I really > appreciate all the effort put in by both of you!). Indeed. > @@ -334,6 +334,9 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags) > > if (auto_explain_enabled()) > { > + /* We're always interested in runtime */ > + queryDesc->totaltime_options |= INSTRUMENT_TIMER; > - queryDesc->totaltime = InstrAlloc(INSTRUMENT_ALL); Not that it's going to make a significant difference, but it is nice that this now would need to track less. Kinda wonder about having EXPLAIN (ANALYZE BUFFERS totals_only, WAL totals_only) ...; in plenty cases that'd be all one needs, at substantially lower cost. Greetings, Andres Freund -
Re: Stack-based tracking of per-node WAL/buffer usage
Lukas Fittl <lukas@fittl.com> — 2026-04-07T22:27:45Z
On Tue, Apr 7, 2026 at 3:19 PM Andres Freund <andres@anarazel.de> wrote: > > Hi, > > On 2026-04-07 13:30:11 -0700, Lukas Fittl wrote: > > 0001 is the change to make queryDesc->totaltime be allocated by > > ExecutorStart instead of plugins themselves, and adds a > > queryDesc->totaltime_options to have plugins request which level of > > summary instrumentation they need. This change is pretty simple, and > > could still make sense to get into 19. Because of the earlier > > Instrumentation refactoring that was pushed (thanks!) we're already > > asking extensions allocating queryDesc->totaltime to modify their use > > of InstrAlloc, so I think we might as well clean this up now. > > Hm. That's a fair argument. They indeed would have to again change next > release > > It's not a complicated change and removes more lines than it adds. > > I guess one thing I'm not sure is whether the fields shouldn't be renamed at > the same time: > > a) To prevent extensions from continuing to set it, most of them do not test > against assert enabled builds. With a different name they would get a > compiler error. > > b) "totaltime" and "totaltime_options" are pretty poor descriptors of tracking > query level statistics. If everyone has to change anyway, this is a good > occasion. > > 'query_instr[_options]'? > > > Any opinions? I think renaming makes sense - both to make sure extensions reconsider how they use it, and because "totaltime" is a bad name anyway, because its not just about timing (and hasn't been for many releases). "query_instr[_options]" seems reasonable to me, although we could drop the "query_" since it'd be "queryDesc->query_instr" vs "queryDesc->instr". > > > 0002 is just ExecProcNodeInstr moved to instrument.c, as Andres had > > suggested previously. We still get some quick performance wins from > > doing that (see end of email), and again, its a simple change, so > > could be considered if someone has bandwidth remaining. I've added a > > later patch that then does the more complex inlining and gets us the > > full speed up. > > Here it needs a few more inlines to get the full performance, otherwise it > doesn't inline all the helpers. I think on balance I didn't like the > prototype in instrument.h, that's too widely included, and it might even cause > some circularity issues. It seems better to do the somewhat ugly thing and > have the prototype be in executor.h. Yeah, that makes sense. > > > 0002 measurements (with current master and TSC clock source used for > > timing, best of three): > > > > CREATE TABLE lotsarows(key int not null); > > INSERT INTO lotsarows SELECT generate_series(1, 50000000); > > VACUUM FREEZE lotsarows; > > With the somewhat more extreme benchmark I used in the rdtsc thread and the > added inline mentioned above I see a bit bigger wins. See the attached > explainbench.sql - it doesn't quite cover all the combinations, but I think it > gives a good enough overview. > > c=1 pgbench -f ~/tmp/explainbench.sql -P5 -r -t 10 > > master: > statement latencies in milliseconds and failures: > 200.800 0 SELECT pg_prewarm('pgbench_accounts'); > 0.098 0 PREPARE query AS SELECT * FROM pgbench_accounts OFFSET 5000000 LIMIT 1; > 212.010 0 EXPLAIN (ANALYZE, BUFFERS OFF, WAL OFF, TIMING OFF) > 268.648 0 EXPLAIN (ANALYZE, BUFFERS OFF, WAL OFF, TIMING ON) > 232.421 0 EXPLAIN (ANALYZE, BUFFERS ON, WAL ON, TIMING OFF) > 283.531 0 EXPLAIN (ANALYZE, BUFFERS ON, WAL ON, TIMING ON) > 0.030 0 DEALLOCATE query; > > > 0002: > > statement latencies in milliseconds and failures: > 201.558 0 SELECT pg_prewarm('pgbench_accounts'); > 0.103 0 PREPARE query AS SELECT * FROM pgbench_accounts OFFSET 5000000 LIMIT 1; > 188.696 0 EXPLAIN (ANALYZE, BUFFERS OFF, WAL OFF, TIMING OFF) > 244.479 0 EXPLAIN (ANALYZE, BUFFERS OFF, WAL OFF, TIMING ON) > 223.773 0 EXPLAIN (ANALYZE, BUFFERS ON, WAL ON, TIMING OFF) > 266.947 0 EXPLAIN (ANALYZE, BUFFERS ON, WAL ON, TIMING ON) > 0.034 0 DEALLOCATE query; > > That's something like 4-12%. > > Pretty nice for a patch that just adds a few lines around and adds a few > inlines. Agreed. > > @@ -334,6 +334,9 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags) > > > > if (auto_explain_enabled()) > > { > > + /* We're always interested in runtime */ > > + queryDesc->totaltime_options |= INSTRUMENT_TIMER; > > > - queryDesc->totaltime = InstrAlloc(INSTRUMENT_ALL); > > Not that it's going to make a significant difference, but it is nice that this > now would need to track less. Yup. > > Kinda wonder about having > EXPLAIN (ANALYZE BUFFERS totals_only, WAL totals_only) ...; > > in plenty cases that'd be all one needs, at substantially lower cost. True. I don't like the name "totals_only", but I like the concept. Today someone has to go to pg_stat_statements to get just the total numbers, without running them for all nodes with EXPLAIN ANALYZE (and incurring its overhead). Thanks, Lukas -- Lukas Fittl -
Re: Stack-based tracking of per-node WAL/buffer usage
Andres Freund <andres@anarazel.de> — 2026-04-08T04:09:53Z
Hi, On 2026-04-07 15:27:45 -0700, Lukas Fittl wrote: > On Tue, Apr 7, 2026 at 3:19 PM Andres Freund <andres@anarazel.de> wrote: > I think renaming makes sense - both to make sure extensions reconsider > how they use it, and because "totaltime" is a bad name anyway, because > its not just about timing (and hasn't been for many releases). > > "query_instr[_options]" seems reasonable to me, although we could drop > the "query_" since it'd be "queryDesc->query_instr" vs > "queryDesc->instr". Done that way. I earlier pushed 0002 too. > > Kinda wonder about having > > EXPLAIN (ANALYZE BUFFERS totals_only, WAL totals_only) ...; > > > > in plenty cases that'd be all one needs, at substantially lower cost. > > True. I don't like the name "totals_only", but I like the concept. I spent all of three seconds coming up with it... :) > Today someone has to go to pg_stat_statements to get just the total > numbers, without running them for all nodes with EXPLAIN ANALYZE (and > incurring its overhead). Yep. Greetings, Andres Freund