Thread
-
[RFC PATCH v0 3/7] Attribute EXPLAIN WAITS to plan nodes
Ilmar Y <tanswis42@gmail.com> — 2026-05-08T23:22:33Z
--- src/backend/commands/explain.c | 6 +- src/backend/executor/execAsync.c | 22 ++++ src/backend/executor/execParallel.c | 131 ++++++++++++++++++--- src/backend/executor/execProcnode.c | 31 ++++- src/backend/executor/instrument.c | 7 ++ src/backend/executor/nodeBitmapAnd.c | 7 ++ src/backend/executor/nodeBitmapIndexscan.c | 7 ++ src/backend/executor/nodeBitmapOr.c | 7 ++ src/backend/executor/nodeHash.c | 7 ++ src/backend/utils/activity/wait_event.c | 49 +++++++- src/include/executor/instrument.h | 1 + src/include/nodes/execnodes.h | 1 + src/include/utils/wait_event.h | 4 + src/test/regress/expected/explain.out | 52 +++++++- src/test/regress/sql/explain.sql | 29 +++++ 15 files changed, 333 insertions(+), 28 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 9d7372f5415..0575ae8368b 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -530,6 +530,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, instrument_option |= INSTRUMENT_WAL; if (es->io) instrument_option |= INSTRUMENT_IO; + if (es->waits) + instrument_option |= INSTRUMENT_WAITS; /* * We always collect timing for the entire statement, even when node-level @@ -2332,6 +2334,8 @@ ExplainNode(PlanState *planstate, List *ancestors, show_buffer_usage(es, &planstate->instrument->instr.bufusage); if (es->wal && planstate->instrument) show_wal_usage(es, &planstate->instrument->instr.walusage); + if (es->waits) + show_wait_event_usage(es, planstate->wait_event_usage); /* Prepare per-worker buffer/WAL usage */ if (es->workers_state && (es->buffers || es->wal) && es->verbose) @@ -4559,7 +4563,7 @@ show_wait_event_usage(ExplainState *es, const WaitEventUsage *usage) if (usage == NULL) return; - if (es->format == EXPLAIN_FORMAT_TEXT && usage->nentries == 0) + if (usage->nentries == 0) return; if (usage->nentries > 0) diff --git a/src/backend/executor/execAsync.c b/src/backend/executor/execAsync.c index cf7ddbb01f4..e73ea55cf92 100644 --- a/src/backend/executor/execAsync.c +++ b/src/backend/executor/execAsync.c @@ -19,6 +19,7 @@ #include "executor/instrument.h" #include "executor/nodeAppend.h" #include "executor/nodeForeignscan.h" +#include "utils/wait_event.h" /* * Asynchronously request a tuple from a designed async-capable node. @@ -26,12 +27,17 @@ void ExecAsyncRequest(AsyncRequest *areq) { + WaitEventUsage *previous_wait_event_usage = NULL; + if (areq->requestee->chgParam != NULL) /* something changed? */ ExecReScan(areq->requestee); /* let ReScan handle this */ /* must provide our own instrumentation support */ if (areq->requestee->instrument) InstrStartNode(areq->requestee->instrument); + if (areq->requestee->wait_event_usage) + previous_wait_event_usage = + pgstat_enter_wait_event_usage(areq->requestee->wait_event_usage); switch (nodeTag(areq->requestee)) { @@ -47,6 +53,8 @@ ExecAsyncRequest(AsyncRequest *areq) ExecAsyncResponse(areq); /* must provide our own instrumentation support */ + if (areq->requestee->wait_event_usage) + pgstat_restore_wait_event_usage(previous_wait_event_usage); if (areq->requestee->instrument) InstrStopNode(areq->requestee->instrument, TupIsNull(areq->result) ? 0.0 : 1.0); @@ -62,9 +70,14 @@ ExecAsyncRequest(AsyncRequest *areq) void ExecAsyncConfigureWait(AsyncRequest *areq) { + WaitEventUsage *previous_wait_event_usage = NULL; + /* must provide our own instrumentation support */ if (areq->requestee->instrument) InstrStartNode(areq->requestee->instrument); + if (areq->requestee->wait_event_usage) + previous_wait_event_usage = + pgstat_enter_wait_event_usage(areq->requestee->wait_event_usage); switch (nodeTag(areq->requestee)) { @@ -78,6 +91,8 @@ ExecAsyncConfigureWait(AsyncRequest *areq) } /* must provide our own instrumentation support */ + if (areq->requestee->wait_event_usage) + pgstat_restore_wait_event_usage(previous_wait_event_usage); if (areq->requestee->instrument) InstrStopNode(areq->requestee->instrument, 0.0); } @@ -88,9 +103,14 @@ ExecAsyncConfigureWait(AsyncRequest *areq) void ExecAsyncNotify(AsyncRequest *areq) { + WaitEventUsage *previous_wait_event_usage = NULL; + /* must provide our own instrumentation support */ if (areq->requestee->instrument) InstrStartNode(areq->requestee->instrument); + if (areq->requestee->wait_event_usage) + previous_wait_event_usage = + pgstat_enter_wait_event_usage(areq->requestee->wait_event_usage); switch (nodeTag(areq->requestee)) { @@ -106,6 +126,8 @@ ExecAsyncNotify(AsyncRequest *areq) ExecAsyncResponse(areq); /* must provide our own instrumentation support */ + if (areq->requestee->wait_event_usage) + pgstat_restore_wait_event_usage(previous_wait_event_usage); if (areq->requestee->instrument) InstrStopNode(areq->requestee->instrument, TupIsNull(areq->result) ? 0.0 : 1.0); diff --git a/src/backend/executor/execParallel.c b/src/backend/executor/execParallel.c index 8213565a708..f77f539dd27 100644 --- a/src/backend/executor/execParallel.c +++ b/src/backend/executor/execParallel.c @@ -83,6 +83,12 @@ typedef struct FixedParallelExecutorState int jit_flags; } FixedParallelExecutorState; +typedef struct SharedWaitEventUsageWorker +{ + int nentries; + dsa_pointer entries; +} SharedWaitEventUsageWorker; + /* * DSM structure for accumulating per-PlanState instrumentation. * @@ -92,6 +98,10 @@ typedef struct FixedParallelExecutorState * of the first NodeInstrumentation object. This will depend on the length of * the plan_node_id array. * + * wait_event_usage_offset: Offset, relative to the start of this structure, + * of the first SharedWaitEventUsageWorker object, or 0 if wait event usage is + * not being collected. + * * num_workers: Number of workers. * * num_plan_nodes: Number of plan nodes. @@ -103,6 +113,7 @@ struct SharedExecutorInstrumentation { int instrument_options; int instrument_offset; + int wait_event_usage_offset; int num_workers; int num_plan_nodes; int plan_node_id[FLEXIBLE_ARRAY_MEMBER]; @@ -110,17 +121,17 @@ struct SharedExecutorInstrumentation /* * Array of num_plan_nodes * num_workers NodeInstrumentation objects * follows. + * + * If wait_event_usage_offset is non-zero, an array of num_plan_nodes * + * num_workers SharedWaitEventUsageWorker objects follows. */ }; #define GetInstrumentationArray(sei) \ (StaticAssertVariableIsOfTypeMacro(sei, SharedExecutorInstrumentation *), \ (NodeInstrumentation *) (((char *) sei) + sei->instrument_offset)) - -typedef struct SharedWaitEventUsageWorker -{ - int nentries; - dsa_pointer entries; -} SharedWaitEventUsageWorker; +#define GetInstrumentationWaitEventUsageArray(sei) \ + (StaticAssertVariableIsOfTypeMacro(sei, SharedExecutorInstrumentation *), \ + (SharedWaitEventUsageWorker *) (((char *) sei) + sei->wait_event_usage_offset)) struct SharedWaitEventUsage { @@ -143,6 +154,12 @@ typedef struct ExecParallelInitializeDSMContext int nnodes; } ExecParallelInitializeDSMContext; +typedef struct ExecParallelRetrieveInstrumentationContext +{ + SharedExecutorInstrumentation *instrumentation; + dsa_area *area; +} ExecParallelRetrieveInstrumentationContext; + /* Helper functions that run in the parallel leader. */ static char *ExecSerializePlan(Plan *plan, EState *estate); static bool ExecParallelEstimate(PlanState *planstate, @@ -154,8 +171,11 @@ static shm_mq_handle **ExecParallelSetupTupleQueues(ParallelContext *pcxt, static bool ExecParallelReInitializeDSM(PlanState *planstate, ParallelContext *pcxt); static bool ExecParallelRetrieveInstrumentation(PlanState *planstate, - SharedExecutorInstrumentation *instrumentation); + ExecParallelRetrieveInstrumentationContext *r); static void ExecParallelRetrieveWaitEventUsage(ParallelExecutorInfo *pei); +static void ExecParallelReportWaitEventUsageWorker(SharedWaitEventUsageWorker *worker, + dsa_area *area, + const WaitEventUsage *usage); static void ExecParallelReportWaitEventUsage(SharedWaitEventUsage *shared, dsa_area *area, const WaitEventUsage *usage); @@ -691,6 +711,7 @@ ExecInitParallelPlan(PlanState *planstate, EState *estate, int instrumentation_len = 0; int jit_instrumentation_len = 0; int instrument_offset = 0; + int wait_event_usage_offset = 0; Size dsa_minsize = dsa_minimum_size(); char *query_string; int query_len; @@ -798,6 +819,14 @@ ExecInitParallelPlan(PlanState *planstate, EState *estate, instrumentation_len += mul_size(sizeof(NodeInstrumentation), mul_size(e.nnodes, nworkers)); + if (estate->es_instrument & INSTRUMENT_WAITS) + { + instrumentation_len = MAXALIGN(instrumentation_len); + wait_event_usage_offset = instrumentation_len; + instrumentation_len += + mul_size(sizeof(SharedWaitEventUsageWorker), + mul_size(e.nnodes, nworkers)); + } shm_toc_estimate_chunk(&pcxt->estimator, instrumentation_len); shm_toc_estimate_keys(&pcxt->estimator, 1); @@ -903,11 +932,23 @@ ExecInitParallelPlan(PlanState *planstate, EState *estate, instrumentation = shm_toc_allocate(pcxt->toc, instrumentation_len); instrumentation->instrument_options = estate->es_instrument; instrumentation->instrument_offset = instrument_offset; + instrumentation->wait_event_usage_offset = wait_event_usage_offset; instrumentation->num_workers = nworkers; instrumentation->num_plan_nodes = e.nnodes; instrument = GetInstrumentationArray(instrumentation); for (i = 0; i < nworkers * e.nnodes; ++i) InstrInitNode(&instrument[i], estate->es_instrument, false); + if (wait_event_usage_offset != 0) + { + SharedWaitEventUsageWorker *worker_usage; + + worker_usage = GetInstrumentationWaitEventUsageArray(instrumentation); + for (i = 0; i < nworkers * e.nnodes; ++i) + { + worker_usage[i].nentries = 0; + worker_usage[i].entries = InvalidDsaPointer; + } + } shm_toc_insert(pcxt->toc, PARALLEL_KEY_INSTRUMENTATION, instrumentation); pei->instrumentation = instrumentation; @@ -1137,9 +1178,11 @@ ExecParallelReInitializeDSM(PlanState *planstate, */ static bool ExecParallelRetrieveInstrumentation(PlanState *planstate, - SharedExecutorInstrumentation *instrumentation) + ExecParallelRetrieveInstrumentationContext *r) { + SharedExecutorInstrumentation *instrumentation = r->instrumentation; NodeInstrumentation *instrument; + SharedWaitEventUsageWorker *wait_event_usage = NULL; int i; int n; int ibytes; @@ -1159,6 +1202,30 @@ ExecParallelRetrieveInstrumentation(PlanState *planstate, for (n = 0; n < instrumentation->num_workers; ++n) InstrAggNode(planstate->instrument, &instrument[n]); + /* Accumulate the wait event usage from all workers. */ + if (instrumentation->wait_event_usage_offset != 0 && + planstate->wait_event_usage != NULL) + { + wait_event_usage = GetInstrumentationWaitEventUsageArray(instrumentation); + wait_event_usage += i * instrumentation->num_workers; + for (n = 0; n < instrumentation->num_workers; ++n) + { + SharedWaitEventUsageWorker *worker = &wait_event_usage[n]; + WaitEventUsageEntry *entries; + + if (worker->nentries <= 0 || !DsaPointerIsValid(worker->entries)) + continue; + + entries = dsa_get_address(r->area, worker->entries); + pgstat_accumulate_wait_event_usage(planstate->wait_event_usage, + entries, + worker->nentries); + dsa_free(r->area, worker->entries); + worker->nentries = 0; + worker->entries = InvalidDsaPointer; + } + } + /* * Also store the per-worker detail. * @@ -1216,7 +1283,7 @@ ExecParallelRetrieveInstrumentation(PlanState *planstate, } return planstate_tree_walker(planstate, ExecParallelRetrieveInstrumentation, - instrumentation); + r); } /* @@ -1290,25 +1357,21 @@ ExecParallelRetrieveWaitEventUsage(ParallelExecutorInfo *pei) } static void -ExecParallelReportWaitEventUsage(SharedWaitEventUsage *shared, - dsa_area *area, - const WaitEventUsage *usage) +ExecParallelReportWaitEventUsageWorker(SharedWaitEventUsageWorker *worker, + dsa_area *area, + const WaitEventUsage *usage) { - SharedWaitEventUsageWorker *worker; WaitEventUsageEntry *entries; dsa_pointer entries_dsa; Size entries_size; - Assert(shared != NULL); + Assert(worker != NULL); Assert(area != NULL); Assert(usage != NULL); - Assert(IsParallelWorker()); - Assert(ParallelWorkerNumber < shared->num_workers); if (usage->nentries <= 0) return; - worker = &shared->worker_usage[ParallelWorkerNumber]; entries_size = mul_size(sizeof(WaitEventUsageEntry), usage->nentries); entries_dsa = dsa_allocate(area, entries_size); entries = dsa_get_address(area, entries_dsa); @@ -1320,6 +1383,20 @@ ExecParallelReportWaitEventUsage(SharedWaitEventUsage *shared, worker->entries = entries_dsa; } +static void +ExecParallelReportWaitEventUsage(SharedWaitEventUsage *shared, + dsa_area *area, + const WaitEventUsage *usage) +{ + Assert(shared != NULL); + Assert(IsParallelWorker()); + Assert(ParallelWorkerNumber < shared->num_workers); + + ExecParallelReportWaitEventUsageWorker(&shared->worker_usage[ParallelWorkerNumber], + area, + usage); +} + /* * Finish parallel execution. We wait for parallel workers to finish, and * accumulate their buffer/WAL usage. @@ -1385,8 +1462,13 @@ ExecParallelCleanup(ParallelExecutorInfo *pei) { /* Accumulate instrumentation, if any. */ if (pei->instrumentation) - ExecParallelRetrieveInstrumentation(pei->planstate, - pei->instrumentation); + { + ExecParallelRetrieveInstrumentationContext r; + + r.instrumentation = pei->instrumentation; + r.area = pei->area; + ExecParallelRetrieveInstrumentation(pei->planstate, &r); + } /* Accumulate JIT instrumentation, if any. */ if (pei->jit_instrumentation) @@ -1495,6 +1577,17 @@ ExecParallelReportInstrumentation(PlanState *planstate, Assert(IsParallelWorker()); Assert(ParallelWorkerNumber < instrumentation->num_workers); InstrAggNode(&instrument[ParallelWorkerNumber], planstate->instrument); + if (instrumentation->wait_event_usage_offset != 0 && + planstate->wait_event_usage != NULL) + { + SharedWaitEventUsageWorker *wait_event_usage; + + wait_event_usage = GetInstrumentationWaitEventUsageArray(instrumentation); + wait_event_usage += i * instrumentation->num_workers; + ExecParallelReportWaitEventUsageWorker(&wait_event_usage[ParallelWorkerNumber], + planstate->state->es_query_dsa, + planstate->wait_event_usage); + } return planstate_tree_walker(planstate, ExecParallelReportInstrumentation, instrumentation); diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index 7c4c66e323f..081855b3fed 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -118,6 +118,7 @@ #include "executor/nodeWindowAgg.h" #include "executor/nodeWorktablescan.h" #include "miscadmin.h" +#include "utils/wait_event.h" #include "nodes/nodeFuncs.h" static TupleTableSlot *ExecProcNodeFirst(PlanState *node); @@ -415,6 +416,16 @@ ExecInitNode(Plan *node, EState *estate, int eflags) if (estate->es_instrument) result->instrument = InstrAllocNode(estate->es_instrument, result->async_capable); + if (estate->es_instrument & INSTRUMENT_WAITS) + { + MemoryContext oldcontext; + + oldcontext = MemoryContextSwitchTo(estate->es_query_cxt); + result->wait_event_usage = palloc_object(WaitEventUsage); + pgstat_init_wait_event_usage(result->wait_event_usage, + estate->es_query_cxt); + MemoryContextSwitchTo(oldcontext); + } return result; } @@ -481,7 +492,8 @@ ExecProcNodeFirst(PlanState *node) * This has essentially the same responsibilities as ExecProcNode, * but it does not do InstrStartNode/InstrStopNode (mainly because * it can't tell how many returned tuples to count). Each per-node - * function must provide its own instrumentation support. + * function must provide its own instrumentation support, including + * wait event attribution when enabled. * ---------------------------------------------------------------- */ Node * @@ -758,6 +770,9 @@ ExecShutdownNode(PlanState *node) static bool ExecShutdownNode_walker(PlanState *node, void *context) { + bool node_running; + WaitEventUsage *previous_wait_event_usage = NULL; + if (node == NULL) return false; @@ -773,8 +788,14 @@ ExecShutdownNode_walker(PlanState *node, void *context) * has never been executed, so as to avoid incorrectly making it appear * that it has. */ - if (node->instrument && node->instrument->running) + node_running = node->instrument && node->instrument->running; + if (node_running) + { InstrStartNode(node->instrument); + if (node->wait_event_usage) + previous_wait_event_usage = + pgstat_enter_wait_event_usage(node->wait_event_usage); + } planstate_tree_walker(node, ExecShutdownNode_walker, context); @@ -803,8 +824,12 @@ ExecShutdownNode_walker(PlanState *node, void *context) } /* Stop the node if we started it above, reporting 0 tuples. */ - if (node->instrument && node->instrument->running) + if (node_running) + { + if (node->wait_event_usage) + pgstat_restore_wait_event_usage(previous_wait_event_usage); InstrStopNode(node->instrument, 0); + } return false; } diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index ffbcd572133..a1f22180f82 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -21,6 +21,7 @@ #include "nodes/execnodes.h" #include "portability/instr_time.h" #include "utils/guc_hooks.h" +#include "utils/wait_event.h" BufferUsage pgBufferUsage; static BufferUsage save_pgBufferUsage; @@ -181,11 +182,17 @@ TupleTableSlot * ExecProcNodeInstr(PlanState *node) { TupleTableSlot *result; + WaitEventUsage *previous_wait_event_usage = NULL; InstrStartNode(node->instrument); + if (node->wait_event_usage) + previous_wait_event_usage = + pgstat_enter_wait_event_usage(node->wait_event_usage); result = node->ExecProcNodeReal(node); + if (node->wait_event_usage) + pgstat_restore_wait_event_usage(previous_wait_event_usage); InstrStopNode(node->instrument, TupIsNull(result) ? 0.0 : 1.0); return result; diff --git a/src/backend/executor/nodeBitmapAnd.c b/src/backend/executor/nodeBitmapAnd.c index 9007dda3802..e2b442bd378 100644 --- a/src/backend/executor/nodeBitmapAnd.c +++ b/src/backend/executor/nodeBitmapAnd.c @@ -32,6 +32,7 @@ #include "executor/instrument.h" #include "executor/nodeBitmapAnd.h" #include "nodes/tidbitmap.h" +#include "utils/wait_event.h" /* ---------------------------------------------------------------- @@ -115,10 +116,14 @@ MultiExecBitmapAnd(BitmapAndState *node) int nplans; int i; TIDBitmap *result = NULL; + WaitEventUsage *previous_wait_event_usage = NULL; /* must provide our own instrumentation support */ if (node->ps.instrument) InstrStartNode(node->ps.instrument); + if (node->ps.wait_event_usage) + previous_wait_event_usage = + pgstat_enter_wait_event_usage(node->ps.wait_event_usage); /* * get information from the node @@ -162,6 +167,8 @@ MultiExecBitmapAnd(BitmapAndState *node) elog(ERROR, "BitmapAnd doesn't support zero inputs"); /* must provide our own instrumentation support */ + if (node->ps.wait_event_usage) + pgstat_restore_wait_event_usage(previous_wait_event_usage); if (node->ps.instrument) InstrStopNode(node->ps.instrument, 0 /* XXX */ ); diff --git a/src/backend/executor/nodeBitmapIndexscan.c b/src/backend/executor/nodeBitmapIndexscan.c index 7978514e1bc..c2798a81e97 100644 --- a/src/backend/executor/nodeBitmapIndexscan.c +++ b/src/backend/executor/nodeBitmapIndexscan.c @@ -28,6 +28,7 @@ #include "executor/nodeIndexscan.h" #include "miscadmin.h" #include "nodes/tidbitmap.h" +#include "utils/wait_event.h" /* ---------------------------------------------------------------- @@ -54,10 +55,14 @@ MultiExecBitmapIndexScan(BitmapIndexScanState *node) IndexScanDesc scandesc; double nTuples = 0; bool doscan; + WaitEventUsage *previous_wait_event_usage = NULL; /* must provide our own instrumentation support */ if (node->ss.ps.instrument) InstrStartNode(node->ss.ps.instrument); + if (node->ss.ps.wait_event_usage) + previous_wait_event_usage = + pgstat_enter_wait_event_usage(node->ss.ps.wait_event_usage); /* * extract necessary information from index scan node @@ -116,6 +121,8 @@ MultiExecBitmapIndexScan(BitmapIndexScanState *node) } /* must provide our own instrumentation support */ + if (node->ss.ps.wait_event_usage) + pgstat_restore_wait_event_usage(previous_wait_event_usage); if (node->ss.ps.instrument) InstrStopNode(node->ss.ps.instrument, nTuples); diff --git a/src/backend/executor/nodeBitmapOr.c b/src/backend/executor/nodeBitmapOr.c index 148c80fdae6..e9ee934a6f6 100644 --- a/src/backend/executor/nodeBitmapOr.c +++ b/src/backend/executor/nodeBitmapOr.c @@ -33,6 +33,7 @@ #include "executor/nodeBitmapOr.h" #include "nodes/tidbitmap.h" #include "miscadmin.h" +#include "utils/wait_event.h" /* ---------------------------------------------------------------- @@ -116,10 +117,14 @@ MultiExecBitmapOr(BitmapOrState *node) int nplans; int i; TIDBitmap *result = NULL; + WaitEventUsage *previous_wait_event_usage = NULL; /* must provide our own instrumentation support */ if (node->ps.instrument) InstrStartNode(node->ps.instrument); + if (node->ps.wait_event_usage) + previous_wait_event_usage = + pgstat_enter_wait_event_usage(node->ps.wait_event_usage); /* * get information from the node @@ -180,6 +185,8 @@ MultiExecBitmapOr(BitmapOrState *node) elog(ERROR, "BitmapOr doesn't support zero inputs"); /* must provide our own instrumentation support */ + if (node->ps.wait_event_usage) + pgstat_restore_wait_event_usage(previous_wait_event_usage); if (node->ps.instrument) InstrStopNode(node->ps.instrument, 0 /* XXX */ ); diff --git a/src/backend/executor/nodeHash.c b/src/backend/executor/nodeHash.c index 8825bb6fa23..6e9e4b4218f 100644 --- a/src/backend/executor/nodeHash.c +++ b/src/backend/executor/nodeHash.c @@ -105,9 +105,14 @@ ExecHash(PlanState *pstate) Node * MultiExecHash(HashState *node) { + WaitEventUsage *previous_wait_event_usage = NULL; + /* must provide our own instrumentation support */ if (node->ps.instrument) InstrStartNode(node->ps.instrument); + if (node->ps.wait_event_usage) + previous_wait_event_usage = + pgstat_enter_wait_event_usage(node->ps.wait_event_usage); if (node->parallel_state != NULL) MultiExecParallelHash(node); @@ -115,6 +120,8 @@ MultiExecHash(HashState *node) MultiExecPrivateHash(node); /* must provide our own instrumentation support */ + if (node->ps.wait_event_usage) + pgstat_restore_wait_event_usage(previous_wait_event_usage); if (node->ps.instrument) InstrStopNode(node->ps.instrument, node->hashtable->reportTuples); diff --git a/src/backend/utils/activity/wait_event.c b/src/backend/utils/activity/wait_event.c index eb01bc3d88c..3d5a10b44c4 100644 --- a/src/backend/utils/activity/wait_event.c +++ b/src/backend/utils/activity/wait_event.c @@ -27,6 +27,7 @@ #include "storage/shmem.h" #include "storage/subsystems.h" #include "storage/spin.h" +#include "utils/memutils.h" #include "utils/wait_event.h" @@ -47,6 +48,7 @@ uint32 *my_wait_event_info = &local_my_wait_event_info; int pgstat_wait_event_usage_depth = 0; static WaitEventUsage *pgstat_wait_event_usage = NULL; +static WaitEventUsage *pgstat_wait_event_node_usage = NULL; static uint32 pgstat_wait_event_usage_current = 0; static instr_time pgstat_wait_event_usage_start; @@ -358,6 +360,28 @@ pgstat_reset_wait_event_storage(void) my_wait_event_info = &local_my_wait_event_info; } +/* + * Initialize a wait event usage accumulator. + */ +void +pgstat_init_wait_event_usage(WaitEventUsage *usage, MemoryContext memcontext) +{ + Assert(usage != NULL); + Assert(memcontext != NULL); + + memset(usage, 0, sizeof(WaitEventUsage)); + + /* + * Wait events may end inside critical sections, for example while + * performing synchronous I/O. Keep usage entries in a dedicated context + * where the memory manager permits that accounting path to grow. + */ + usage->memcontext = AllocSetContextCreate(memcontext, + "Wait Event Usage", + ALLOCSET_SMALL_SIZES); + MemoryContextAllowInCriticalSection(usage->memcontext, true); +} + /* * Start collecting exact wait event timings in this backend. * @@ -375,9 +399,9 @@ pgstat_begin_wait_event_usage(WaitEventUsage *usage, MemoryContext memcontext) if (pgstat_wait_event_usage_depth++ == 0) { - memset(usage, 0, sizeof(WaitEventUsage)); - usage->memcontext = memcontext; + pgstat_init_wait_event_usage(usage, memcontext); pgstat_wait_event_usage = usage; + pgstat_wait_event_node_usage = NULL; pgstat_wait_event_usage_current = 0; INSTR_TIME_SET_ZERO(pgstat_wait_event_usage_start); } @@ -398,11 +422,27 @@ pgstat_end_wait_event_usage(WaitEventUsage *usage) pgstat_count_wait_event_end(); pgstat_wait_event_usage = NULL; + pgstat_wait_event_node_usage = NULL; pgstat_wait_event_usage_current = 0; INSTR_TIME_SET_ZERO(pgstat_wait_event_usage_start); } } +WaitEventUsage * +pgstat_enter_wait_event_usage(WaitEventUsage *usage) +{ + WaitEventUsage *previous = pgstat_wait_event_node_usage; + + pgstat_wait_event_node_usage = usage; + return previous; +} + +void +pgstat_restore_wait_event_usage(WaitEventUsage *usage) +{ + pgstat_wait_event_node_usage = usage; +} + /* * Record the beginning of a wait event for exact EXPLAIN-style accounting. */ @@ -444,6 +484,11 @@ pgstat_count_wait_event_end(void) pgstat_wait_event_usage_current, 1, &elapsed); + if (pgstat_wait_event_node_usage != NULL) + WaitEventUsageAdd(pgstat_wait_event_node_usage, + pgstat_wait_event_usage_current, + 1, + &elapsed); pgstat_wait_event_usage_current = 0; INSTR_TIME_SET_ZERO(pgstat_wait_event_usage_start); diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index f093a52aae0..f46ee03d2c1 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -65,6 +65,7 @@ typedef enum InstrumentOption INSTRUMENT_ROWS = 1 << 2, /* needs row count */ INSTRUMENT_WAL = 1 << 3, /* needs WAL usage */ INSTRUMENT_IO = 1 << 4, /* needs IO usage */ + INSTRUMENT_WAITS = 1 << 5, /* needs wait event usage */ INSTRUMENT_ALL = PG_INT32_MAX } InstrumentOption; diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h index 781c8c79132..56f9dcbef88 100644 --- a/src/include/nodes/execnodes.h +++ b/src/include/nodes/execnodes.h @@ -1212,6 +1212,7 @@ typedef struct PlanState NodeInstrumentation *instrument; /* Optional runtime stats for this * node */ + WaitEventUsage *wait_event_usage; /* Optional wait event usage */ WorkerNodeInstrumentation *worker_instrument; /* per-worker * instrumentation */ diff --git a/src/include/utils/wait_event.h b/src/include/utils/wait_event.h index 63992137ee7..64411288403 100644 --- a/src/include/utils/wait_event.h +++ b/src/include/utils/wait_event.h @@ -36,12 +36,16 @@ static inline void pgstat_report_wait_start(uint32 wait_event_info); static inline void pgstat_report_wait_end(void); extern void pgstat_set_wait_event_storage(uint32 *wait_event_info); extern void pgstat_reset_wait_event_storage(void); +extern void pgstat_init_wait_event_usage(WaitEventUsage *usage, + MemoryContext memcontext); extern void pgstat_begin_wait_event_usage(WaitEventUsage *usage, MemoryContext memcontext); extern void pgstat_end_wait_event_usage(WaitEventUsage *usage); extern void pgstat_accumulate_wait_event_usage(WaitEventUsage *usage, const WaitEventUsageEntry *entries, int nentries); +extern WaitEventUsage *pgstat_enter_wait_event_usage(WaitEventUsage *usage); +extern void pgstat_restore_wait_event_usage(WaitEventUsage *usage); extern void pgstat_count_wait_event_start(uint32 wait_event_info); extern void pgstat_count_wait_event_end(void); diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out index e3847e222be..c086fa48d80 100644 --- a/src/test/regress/expected/explain.out +++ b/src/test/regress/expected/explain.out @@ -101,12 +101,14 @@ select explain_filter('explain (buffers, format text) select * from int8_tbl i8' -- WAITS option select explain_filter('explain (analyze, waits, costs off, summary off, timing off, buffers off) select pg_sleep(0.01)'); - explain_filter ---------------------------------------- + explain_filter +----------------------------------------- Result (actual rows=N.N loops=N) + Wait Events: + Timeout:PgSleep calls=N time=N.N ms Wait Events: Timeout:PgSleep calls=N time=N.N ms -(3 rows) +(5 rows) select explain_filter_to_json('explain (analyze, waits, costs off, summary off, timing off, buffers off, format json) select pg_sleep(0.01)') #> '{0,Wait Events,0}'; ?column? @@ -114,6 +116,12 @@ select explain_filter_to_json('explain (analyze, waits, costs off, summary off, {"Time": 0.0, "Calls": 0, "Wait Event": "PgSleep", "Wait Event Type": "Timeout"} (1 row) +select explain_filter_to_json('explain (analyze, waits, costs off, summary off, timing off, buffers off, format json) select pg_sleep(0.01)') #> '{0,Plan,Wait Events,0}'; + ?column? +---------------------------------------------------------------------------------- + {"Time": 0.0, "Calls": 0, "Wait Event": "PgSleep", "Wait Event Type": "Timeout"} +(1 row) + begin; create function pg_temp.parallel_pg_sleep(float8) returns void language internal volatile parallel safe as 'pg_sleep'; @@ -130,6 +138,44 @@ select jsonb_path_query_first( {"Time": 0.0, "Calls": 0, "Wait Event": "PgSleep", "Wait Event Type": "Timeout"} (1 row) +select jsonb_path_query_first( + explain_filter_to_json('explain (analyze, waits, costs off, summary off, timing off, buffers off, format json) + select pg_temp.parallel_pg_sleep(0.01) + from tenk1 where unique1 = 1') #> '{0,Plan}', + '$.**."Wait Events"[*] ? (@."Wait Event" == "PgSleep")' +); + jsonb_path_query_first +---------------------------------------------------------------------------------- + {"Time": 0.0, "Calls": 0, "Wait Event": "PgSleep", "Wait Event Type": "Timeout"} +(1 row) + +rollback; +begin; +-- This test deliberately creates a Bitmap Index Scan runtime-key wait. +-- The STABLE PL/pgSQL wrapper is test scaffolding: STABLE lets the +-- expression be used as an index runtime key, while PL/pgSQL prevents SQL +-- inlining from moving pg_sleep() out of the Bitmap Index Scan boundary. +-- The planner GUCs below are likewise test-only scaffolding to make the +-- node shape deterministic. +create function pg_temp.explain_waits_sleep_int(int) returns int + language plpgsql stable as $$begin perform pg_sleep(0.01); return $1; end$$; +create temp table explain_waits_bitmap (a int); +insert into explain_waits_bitmap select g from generate_series(1, 10) g; +create index explain_waits_bitmap_a_idx on explain_waits_bitmap(a); +analyze explain_waits_bitmap; +set local enable_seqscan = off; +set local enable_indexscan = off; +select jsonb_path_query_first( + explain_filter_to_json('explain (analyze, waits, costs off, summary off, timing off, buffers off, format json) + select * from explain_waits_bitmap + where a = pg_temp.explain_waits_sleep_int(1)') #> '{0,Plan}', + '$.** ? (@."Node Type" == "Bitmap Index Scan")."Wait Events"[*] ? (@."Wait Event" == "PgSleep")' +); + jsonb_path_query_first +---------------------------------------------------------------------------------- + {"Time": 0.0, "Calls": 0, "Wait Event": "PgSleep", "Wait Event Type": "Timeout"} +(1 row) + rollback; explain (waits) select 1; ERROR: EXPLAIN option WAITS requires ANALYZE diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql index 8821250bcef..bd196f248db 100644 --- a/src/test/regress/sql/explain.sql +++ b/src/test/regress/sql/explain.sql @@ -71,6 +71,7 @@ select explain_filter('explain (buffers, format text) select * from int8_tbl i8' -- WAITS option select explain_filter('explain (analyze, waits, costs off, summary off, timing off, buffers off) select pg_sleep(0.01)'); select explain_filter_to_json('explain (analyze, waits, costs off, summary off, timing off, buffers off, format json) select pg_sleep(0.01)') #> '{0,Wait Events,0}'; +select explain_filter_to_json('explain (analyze, waits, costs off, summary off, timing off, buffers off, format json) select pg_sleep(0.01)') #> '{0,Plan,Wait Events,0}'; begin; create function pg_temp.parallel_pg_sleep(float8) returns void language internal volatile parallel safe as 'pg_sleep'; @@ -82,6 +83,34 @@ select jsonb_path_query_first( from tenk1 where unique1 = 1') #> '{0,Wait Events}', '$[*] ? (@."Wait Event" == "PgSleep")' ); +select jsonb_path_query_first( + explain_filter_to_json('explain (analyze, waits, costs off, summary off, timing off, buffers off, format json) + select pg_temp.parallel_pg_sleep(0.01) + from tenk1 where unique1 = 1') #> '{0,Plan}', + '$.**."Wait Events"[*] ? (@."Wait Event" == "PgSleep")' +); +rollback; +begin; +-- This test deliberately creates a Bitmap Index Scan runtime-key wait. +-- The STABLE PL/pgSQL wrapper is test scaffolding: STABLE lets the +-- expression be used as an index runtime key, while PL/pgSQL prevents SQL +-- inlining from moving pg_sleep() out of the Bitmap Index Scan boundary. +-- The planner GUCs below are likewise test-only scaffolding to make the +-- node shape deterministic. +create function pg_temp.explain_waits_sleep_int(int) returns int + language plpgsql stable as $$begin perform pg_sleep(0.01); return $1; end$$; +create temp table explain_waits_bitmap (a int); +insert into explain_waits_bitmap select g from generate_series(1, 10) g; +create index explain_waits_bitmap_a_idx on explain_waits_bitmap(a); +analyze explain_waits_bitmap; +set local enable_seqscan = off; +set local enable_indexscan = off; +select jsonb_path_query_first( + explain_filter_to_json('explain (analyze, waits, costs off, summary off, timing off, buffers off, format json) + select * from explain_waits_bitmap + where a = pg_temp.explain_waits_sleep_int(1)') #> '{0,Plan}', + '$.** ? (@."Node Type" == "Bitmap Index Scan")."Wait Events"[*] ? (@."Wait Event" == "PgSleep")' +); rollback; explain (waits) select 1; -- 2.52.0