From 8cb0f58254f789c78ef271a47b4e76322ff49e78 Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Fri, 2 Oct 2026 21:27:08 -0700 Subject: [PATCH v18 7/9] Index scans: Show table buffer accesses separately in EXPLAIN ANALYZE This sets up a separate instrumentation stack that is used while an Index Scan fetches heap tuples, or an Index Only Scan checks the visibility map and fetches heap tuples for pages that are are not all-visible. EXPLAIN ANALYZE will now show "Table Buffers" that represent such activity. The activity is also included in regular "Buffers" together with index activity and that of any child nodes. Author: Lukas Fittl Suggested-by: Andres Freund (in an earlier version) Reviewed-by: Zsolt Parragi (in an earlier version) Reviewed-by: Tomas Vondra (in an earlier version) Discussion: https://postgr.es/m/CAP53PkzdBK8VJ1fS4AZ481LgMN8f9mJiC39ZRHqkFUSYq6KWmg%40mail.gmail.com --- doc/src/sgml/perform.sgml | 13 +- doc/src/sgml/ref/explain.sgml | 1 + src/backend/access/heap/heapam_indexscan.c | 29 +++++ src/backend/commands/explain.c | 47 ++++++-- src/backend/executor/execProcnode.c | 46 +++++++ src/backend/executor/nodeBitmapIndexscan.c | 2 +- src/backend/executor/nodeIndexonlyscan.c | 55 ++++++++- src/backend/executor/nodeIndexscan.c | 55 ++++++++- src/include/executor/instrument_node.h | 6 + src/test/regress/expected/explain.out | 132 +++++++++++++++++++++ src/test/regress/sql/explain.sql | 75 ++++++++++++ 11 files changed, 441 insertions(+), 20 deletions(-) diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml index ea8da01b779..8087dd60403 100644 --- a/doc/src/sgml/perform.sgml +++ b/doc/src/sgml/perform.sgml @@ -735,6 +735,7 @@ WHERE t1.unique1 < 10 AND t1.unique2 = t2.unique2; -> Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..7.90 rows=1 width=244) (actual time=0.003..0.003 rows=1.00 loops=10) Index Cond: (unique2 = t1.unique2) Index Searches: 10 + Table Buffers: shared hit=10 Buffers: shared hit=24 read=6 Planning: Buffers: shared hit=15 dirtied=9 @@ -1006,7 +1007,8 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @> polygon '(0.5,2.0)'; Index Cond: (f1 @> '((0.5,2))'::polygon) Rows Removed by Index Recheck: 1 Index Searches: 1 - Buffers: shared hit=1 + Table Buffers: shared hit=1 + Buffers: shared hit=2 Planning Time: 0.039 ms Execution Time: 0.098 ms @@ -1015,7 +1017,9 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @> polygon '(0.5,2.0)'; then rejected by a recheck of the index condition. This happens because a GiST index is lossy for polygon containment tests: it actually returns the rows with polygons that overlap the target, and then we have - to do the exact containment test on those rows. + to do the exact containment test on those rows. The Table Buffers + counts indicate how many operations were performed on the table instead of + the index. This number is included in the Buffers counts. @@ -1204,13 +1208,14 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE unique1 < 100 AND unique2 > 9000 QUERY PLAN -------------------------------------------------------------------&zwsp;------------------------------------------------------------ Limit (cost=0.29..14.33 rows=2 width=244) (actual time=0.051..0.071 rows=2.00 loops=1) - Buffers: shared hit=16 + Buffers: shared hit=14 -> Index Scan using tenk1_unique2 on tenk1 (cost=0.29..70.50 rows=10 width=244) (actual time=0.051..0.070 rows=2.00 loops=1) Index Cond: (unique2 > 9000) Filter: (unique1 < 100) Rows Removed by Filter: 287 Index Searches: 1 - Buffers: shared hit=16 + Table Buffers: shared hit=11 + Buffers: shared hit=14 Planning Time: 0.077 ms Execution Time: 0.086 ms diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index f38d31e106a..2c300792238 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -528,6 +528,7 @@ EXPLAIN ANALYZE EXECUTE query(100, 200); -> Index Scan using test_pkey on test (cost=0.29..10.27 rows=99 width=8) (actual time=0.009..0.025 rows=99.00 loops=1) Index Cond: ((id > 100) AND (id < 200)) Index Searches: 1 + Table Buffers: shared hit=1 Buffers: shared hit=4 Planning Time: 0.244 ms Execution Time: 0.073 ms diff --git a/src/backend/access/heap/heapam_indexscan.c b/src/backend/access/heap/heapam_indexscan.c index 49981525c67..179e70f8d10 100644 --- a/src/backend/access/heap/heapam_indexscan.c +++ b/src/backend/access/heap/heapam_indexscan.c @@ -19,6 +19,7 @@ #include "access/relscan.h" #include "access/tableam_indexscan.h" #include "access/visibilitymap.h" +#include "executor/instrument.h" #include "pgstat.h" #include "storage/predicate.h" @@ -330,6 +331,7 @@ heapam_index_getnext_slot(IndexScanDesc scan, ScanDirection direction, { IndexScanHeapData *hscan; bool all_visible; + Instrumentation *table_instr = NULL; /* * Get the next TID from the index, unless we're still working through @@ -356,6 +358,16 @@ heapam_index_getnext_slot(IndexScanDesc scan, ScanDirection direction, } else { + /* + * If requested, account buffer/WAL activity on the table's + * visility map separately from the index. + */ + if (scan->instrument && scan->instrument->table_instr.need_stack) + { + table_instr = &scan->instrument->table_instr; + InstrPushStack(table_instr); + } + /* * Note: VM_ALL_VISIBLE does not lock the visibility map buffer, * so the result could be slightly stale. See the comments above @@ -365,6 +377,9 @@ heapam_index_getnext_slot(IndexScanDesc scan, ScanDirection direction, ItemPointerGetBlockNumber(&scan->xs_heaptid), &hscan->xs_vmbuffer); + if (table_instr) + InstrPopStack(table_instr); + if (unlikely(!all_visible)) { /* Page isn't all-visible, so need a heap fetch */ @@ -434,6 +449,7 @@ heapam_index_heap_fetch(IndexScanDesc scan, IndexScanHeapData *hscan, HeapTuple heapTuple; bool got_heap_tuple; bool all_dead; + Instrumentation *table_instr = NULL; if (!index_only) { @@ -453,6 +469,16 @@ heapam_index_heap_fetch(IndexScanDesc scan, IndexScanHeapData *hscan, scan->instrument->ntabletuplefetches++; } + /* + * If requested, account buffer/WAL activity on the table separately from + * that on the index, so EXPLAIN (ANALYZE, BUFFERS) can show them apart. + */ + if (scan->instrument && scan->instrument->table_instr.need_stack) + { + table_instr = &scan->instrument->table_instr; + InstrPushStack(table_instr); + } + /* We can skip the buffer-switching logic if we're on the same page. */ if (hscan->xs_blk != ItemPointerGetBlockNumber(tid)) { @@ -528,6 +554,9 @@ heapam_index_heap_fetch(IndexScanDesc scan, IndexScanHeapData *hscan, heapam_index_kill_item(scan); } + if (table_instr) + InstrPopStack(table_instr); + return got_heap_tuple; } diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 97d56f2bd93..80031a2d4cf 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -147,7 +147,7 @@ static void show_instrumentation_count(const char *qlabel, int which, static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es); static const char *explain_get_index_name(Oid indexId); static bool peek_buffer_usage(ExplainState *es, const BufferUsage *usage); -static void show_buffer_usage(ExplainState *es, const BufferUsage *usage); +static void show_buffer_usage(ExplainState *es, const BufferUsage *usage, const char *title); static void show_wal_usage(ExplainState *es, const WalUsage *usage); static void show_memory_counters(ExplainState *es, const MemoryContextCounters *mem_counters); @@ -625,7 +625,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, } if (bufusage) - show_buffer_usage(es, bufusage); + show_buffer_usage(es, bufusage, NULL); if (mem_counters) show_memory_counters(es, mem_counters); @@ -1042,7 +1042,7 @@ ExplainPrintSerialize(ExplainState *es, SerializeMetrics *metrics) if (es->buffers && peek_buffer_usage(es, &metrics->instr.bufusage)) { es->indent++; - show_buffer_usage(es, &metrics->instr.bufusage); + show_buffer_usage(es, &metrics->instr.bufusage, NULL); es->indent--; } } @@ -1056,7 +1056,7 @@ ExplainPrintSerialize(ExplainState *es, SerializeMetrics *metrics) BYTES_TO_KILOBYTES(metrics->bytesSent), es); ExplainPropertyText("Format", format, es); if (es->buffers) - show_buffer_usage(es, &metrics->instr.bufusage); + show_buffer_usage(es, &metrics->instr.bufusage, NULL); } ExplainCloseGroup("Serialization", "Serialization", true, es); @@ -1986,6 +1986,9 @@ ExplainNode(PlanState *planstate, List *ancestors, show_instrumentation_count("Rows Removed by Filter", 1, planstate, es); show_indexscan_info(planstate, es); + + if (es->buffers && planstate->instrument) + show_buffer_usage(es, &((IndexScanState *) planstate)->iss_Instrument->table_instr.bufusage, "Table"); break; case T_IndexOnlyScan: show_scan_qual(((IndexOnlyScan *) plan)->indexqual, @@ -2000,6 +2003,9 @@ ExplainNode(PlanState *planstate, List *ancestors, show_instrumentation_count("Rows Removed by Filter", 1, planstate, es); show_indexscan_info(planstate, es); + + if (es->buffers && planstate->instrument) + show_buffer_usage(es, &((IndexOnlyScanState *) planstate)->ioss_Instrument->table_instr.bufusage, "Table"); break; case T_BitmapIndexScan: show_scan_qual(((BitmapIndexScan *) plan)->indexqualorig, @@ -2304,7 +2310,7 @@ ExplainNode(PlanState *planstate, List *ancestors, /* Show buffer/WAL usage */ if (es->buffers && planstate->instrument) - show_buffer_usage(es, &planstate->instrument->instr.bufusage); + show_buffer_usage(es, &planstate->instrument->instr.bufusage, NULL); if (es->wal && planstate->instrument) show_wal_usage(es, &planstate->instrument->instr.walusage); @@ -2323,7 +2329,7 @@ ExplainNode(PlanState *planstate, List *ancestors, ExplainOpenWorker(n, es); if (es->buffers) - show_buffer_usage(es, &instrument->instr.bufusage); + show_buffer_usage(es, &instrument->instr.bufusage, NULL); if (es->wal) show_wal_usage(es, &instrument->instr.walusage); ExplainCloseWorker(n, es); @@ -4331,7 +4337,7 @@ peek_buffer_usage(ExplainState *es, const BufferUsage *usage) * Show buffer usage details. This better be sync with peek_buffer_usage. */ static void -show_buffer_usage(ExplainState *es, const BufferUsage *usage) +show_buffer_usage(ExplainState *es, const BufferUsage *usage, const char *title) { if (es->format == EXPLAIN_FORMAT_TEXT) { @@ -4356,6 +4362,8 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) if (has_shared || has_local || has_temp) { ExplainIndentText(es); + if (title) + appendStringInfo(es->str, "%s ", title); appendStringInfoString(es->str, "Buffers:"); if (has_shared) @@ -4411,6 +4419,8 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) if (has_shared_timing || has_local_timing || has_temp_timing) { ExplainIndentText(es); + if (title) + appendStringInfo(es->str, "%s ", title); appendStringInfoString(es->str, "I/O Timings:"); if (has_shared_timing) @@ -4452,6 +4462,14 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) } else { + char *buffers_title = NULL; + + if (title) + { + buffers_title = psprintf("%s Buffers", title); + ExplainOpenGroup(buffers_title, buffers_title, true, es); + } + ExplainPropertyInteger("Shared Hit Blocks", NULL, usage->shared_blks_hit, es); ExplainPropertyInteger("Shared Read Blocks", NULL, @@ -4472,8 +4490,20 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) usage->temp_blks_read, es); ExplainPropertyInteger("Temp Written Blocks", NULL, usage->temp_blks_written, es); + + if (buffers_title) + ExplainCloseGroup(buffers_title, buffers_title, true, es); + if (track_io_timing) { + char *timings_title = NULL; + + if (title) + { + timings_title = psprintf("%s I/O Timings", title); + ExplainOpenGroup(timings_title, timings_title, true, es); + } + ExplainPropertyFloat("Shared I/O Read Time", "ms", INSTR_TIME_GET_MILLISEC(usage->shared_blk_read_time), 3, es); @@ -4492,6 +4522,9 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) ExplainPropertyFloat("Temp I/O Write Time", "ms", INSTR_TIME_GET_MILLISEC(usage->temp_blk_write_time), 3, es); + + if (timings_title) + ExplainCloseGroup(timings_title, timings_title, true, es); } } } diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index 357175ac2cb..57a78325f47 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -847,6 +847,20 @@ ExecFinalizeNodeInstrumentation_walker(PlanState *node, void *context) planstate_tree_walker(node, ExecFinalizeNodeInstrumentation_walker, &node->instrument->instr); + /* IndexScan/IndexOnlyScan have a separate entry to track table access */ + if (IsA(node, IndexScanState)) + { + IndexScanState *iss = castNode(IndexScanState, node); + + InstrFinalizeChild(&iss->iss_Instrument->table_instr, &node->instrument->instr); + } + else if (IsA(node, IndexOnlyScanState)) + { + IndexOnlyScanState *ioss = castNode(IndexOnlyScanState, node); + + InstrFinalizeChild(&ioss->ioss_Instrument->table_instr, &node->instrument->instr); + } + InstrFinalizeChild(&node->instrument->instr, parent); return false; @@ -892,6 +906,38 @@ ExecFinalizeWorkerInstrumentation_walker(PlanState *node, void *context) num_workers = node->worker_instrument->num_workers; + /* + * Fold per-worker IndexScan/IndexOnlyScan table buffer stats into the + * per-worker node stats, matching what ExecFinalizeNodeInstrumentation + * does for the leader. + */ + if (IsA(node, IndexScanState)) + { + IndexScanState *iss = castNode(IndexScanState, node); + + if (iss->iss_SharedInfo) + { + int nworkers = Min(num_workers, iss->iss_SharedInfo->num_workers); + + for (int n = 0; n < nworkers; n++) + InstrAccumStack(&node->worker_instrument->instrument[n].instr, + &iss->iss_SharedInfo->winstrument[n].table_instr); + } + } + else if (IsA(node, IndexOnlyScanState)) + { + IndexOnlyScanState *ioss = castNode(IndexOnlyScanState, node); + + if (ioss->ioss_SharedInfo) + { + int nworkers = Min(num_workers, ioss->ioss_SharedInfo->num_workers); + + for (int n = 0; n < nworkers; n++) + InstrAccumStack(&node->worker_instrument->instrument[n].instr, + &ioss->ioss_SharedInfo->winstrument[n].table_instr); + } + } + /* Accumulate this node's per-worker stats to parent's per-worker stats */ if (parent && parent->worker_instrument) { diff --git a/src/backend/executor/nodeBitmapIndexscan.c b/src/backend/executor/nodeBitmapIndexscan.c index 90b010f9b71..c190a03f47c 100644 --- a/src/backend/executor/nodeBitmapIndexscan.c +++ b/src/backend/executor/nodeBitmapIndexscan.c @@ -277,7 +277,7 @@ ExecInitBitmapIndexScan(BitmapIndexScan *node, EState *estate, int eflags) /* Set up instrumentation of bitmap index scans if requested */ if (estate->es_instrument) - indexstate->biss_Instrument = palloc0_object(IndexScanInstrumentation); + indexstate->biss_Instrument = MemoryContextAllocZero(estate->es_query_instr->instr_cxt, sizeof(IndexScanInstrumentation)); /* Open the index relation. */ lockmode = exec_rt_fetch(node->scan.scanrelid, estate)->rellockmode; diff --git a/src/backend/executor/nodeIndexonlyscan.c b/src/backend/executor/nodeIndexonlyscan.c index b1009027ac8..b57924be781 100644 --- a/src/backend/executor/nodeIndexonlyscan.c +++ b/src/backend/executor/nodeIndexonlyscan.c @@ -262,6 +262,7 @@ ExecEndIndexOnlyScan(IndexOnlyScanState *node) */ winstrument->nsearches += node->ioss_Instrument->nsearches; winstrument->ntabletuplefetches += node->ioss_Instrument->ntabletuplefetches; + InstrAccumStack(&winstrument->table_instr, &node->ioss_Instrument->table_instr); } /* @@ -416,6 +417,29 @@ ExecInitIndexOnlyScan(IndexOnlyScan *node, EState *estate, int eflags) indexstate->recheckqual = ExecInitQual(node->recheckqual, (PlanState *) indexstate); + /* + * Set up instrumentation of index-only scans if requested. Like the + * node's own instrumentation (see ExecInitNode), this must exist even + * when we are only doing EXPLAIN, since EXPLAIN (BUFFERS) reads it + * regardless of whether the plan was run. + */ + if (estate->es_instrument) + { + indexstate->ioss_Instrument = MemoryContextAllocZero(estate->es_query_instr->instr_cxt, sizeof(IndexScanInstrumentation)); + + /* + * Track table and index access separately. We intentionally don't + * collect timing (even if enabled), since we don't need it, and the + * table AM calls InstrPushStack / InstrPopStack around its table + * fetches (instead of the full InstrNode*) to reduce overhead. + */ + if ((estate->es_instrument & INSTRUMENT_BUFFERS) != 0) + { + InstrInitOptions(&indexstate->ioss_Instrument->table_instr, INSTRUMENT_BUFFERS); + InstrQueryRememberChild(estate->es_query_instr, &indexstate->ioss_Instrument->table_instr); + } + } + /* * If we are just doing EXPLAIN (ie, aren't going to run the plan), stop * here. This allows an index-advisor plugin to EXPLAIN a plan containing @@ -424,10 +448,6 @@ ExecInitIndexOnlyScan(IndexOnlyScan *node, EState *estate, int eflags) if (eflags & EXEC_FLAG_EXPLAIN_ONLY) return indexstate; - /* Set up instrumentation of index-only scans if requested */ - if (estate->es_instrument) - indexstate->ioss_Instrument = palloc0_object(IndexScanInstrumentation); - /* Open the index relation. */ lockmode = exec_rt_fetch(node->scan.scanrelid, estate)->rellockmode; indexRelation = index_open(node->indexid, lockmode); @@ -655,6 +675,19 @@ ExecIndexOnlyScanInstrumentInitDSM(IndexOnlyScanState *node, /* Each per-worker area must start out as zeroes */ memset(node->ioss_SharedInfo, 0, size); node->ioss_SharedInfo->num_workers = pcxt->nworkers; + + /* + * Initialize each worker's table_instr with the same options as the + * leader's own entry (see ExecInitIndexOnlyScan), so that accumulating + * from it works once the worker has added its stats. + */ + if ((node->ss.ps.state->es_instrument & INSTRUMENT_BUFFERS) != 0) + { + for (int i = 0; i < pcxt->nworkers; i++) + InstrInitOptions(&node->ioss_SharedInfo->winstrument[i].table_instr, + INSTRUMENT_BUFFERS); + } + shm_toc_insert(pcxt->toc, node->ss.ps.plan->plan_node_id + PARALLEL_KEY_SCAN_INSTRUMENT_OFFSET, @@ -698,4 +731,18 @@ ExecIndexOnlyScanRetrieveInstrumentation(IndexOnlyScanState *node) SharedInfo->num_workers * sizeof(IndexScanInstrumentation); node->ioss_SharedInfo = palloc(size); memcpy(node->ioss_SharedInfo, SharedInfo, size); + + /* + * Aggregate workers' table buffer/WAL usage into leader's entry, which + * ExecFinalizeNodeInstrumentation later rolls up into the node. Record + * the import so that session-level consumers can exclude it (see + * InstrAccumWorkerUsage). + */ + for (int i = 0; i < node->ioss_SharedInfo->num_workers; i++) + { + Instrumentation *winstr = &node->ioss_SharedInfo->winstrument[i].table_instr; + + InstrAccumStack(&node->ioss_Instrument->table_instr, winstr); + InstrAccumWorkerUsage(&winstr->bufusage, &winstr->walusage); + } } diff --git a/src/backend/executor/nodeIndexscan.c b/src/backend/executor/nodeIndexscan.c index 129d005f187..2266befe1bc 100644 --- a/src/backend/executor/nodeIndexscan.c +++ b/src/backend/executor/nodeIndexscan.c @@ -821,6 +821,7 @@ ExecEndIndexScan(IndexScanState *node) */ winstrument->nsearches += node->iss_Instrument->nsearches; Assert(node->iss_Instrument->ntabletuplefetches == 0); + InstrAccumStack(&winstrument->table_instr, &node->iss_Instrument->table_instr); } /* @@ -973,6 +974,29 @@ ExecInitIndexScan(IndexScan *node, EState *estate, int eflags) indexstate->indexorderbyorig = ExecInitExprList(node->indexorderbyorig, (PlanState *) indexstate); + /* + * Set up instrumentation of index scans if requested. Like the node's + * own instrumentation (see ExecInitNode), this must exist even when we + * are only doing EXPLAIN, since EXPLAIN (BUFFERS) reads it regardless of + * whether the plan was run. + */ + if (estate->es_instrument) + { + indexstate->iss_Instrument = MemoryContextAllocZero(estate->es_query_instr->instr_cxt, sizeof(IndexScanInstrumentation)); + + /* + * Track table and index access separately. We intentionally don't + * collect timing (even if enabled), since we don't need it, and the + * table AM calls InstrPushStack / InstrPopStack around its table + * fetches (instead of the full InstrNode*) to reduce overhead. + */ + if ((estate->es_instrument & INSTRUMENT_BUFFERS) != 0) + { + InstrInitOptions(&indexstate->iss_Instrument->table_instr, INSTRUMENT_BUFFERS); + InstrQueryRememberChild(estate->es_query_instr, &indexstate->iss_Instrument->table_instr); + } + } + /* * If we are just doing EXPLAIN (ie, aren't going to run the plan), stop * here. This allows an index-advisor plugin to EXPLAIN a plan containing @@ -981,10 +1005,6 @@ ExecInitIndexScan(IndexScan *node, EState *estate, int eflags) if (eflags & EXEC_FLAG_EXPLAIN_ONLY) return indexstate; - /* Set up instrumentation of index scans if requested */ - if (estate->es_instrument) - indexstate->iss_Instrument = palloc0_object(IndexScanInstrumentation); - /* Open the index relation. */ lockmode = exec_rt_fetch(node->scan.scanrelid, estate)->rellockmode; indexstate->iss_RelationDesc = index_open(node->indexid, lockmode); @@ -1810,6 +1830,19 @@ ExecIndexScanInstrumentInitDSM(IndexScanState *node, /* Each per-worker area must start out as zeroes */ memset(node->iss_SharedInfo, 0, size); node->iss_SharedInfo->num_workers = pcxt->nworkers; + + /* + * Initialize each worker's table_instr with the same options as the + * leader's own entry (see ExecInitIndexScan), so that accumulating from + * it works once the worker has added its stats. + */ + if ((node->ss.ps.state->es_instrument & INSTRUMENT_BUFFERS) != 0) + { + for (int i = 0; i < pcxt->nworkers; i++) + InstrInitOptions(&node->iss_SharedInfo->winstrument[i].table_instr, + INSTRUMENT_BUFFERS); + } + shm_toc_insert(pcxt->toc, node->ss.ps.plan->plan_node_id + PARALLEL_KEY_SCAN_INSTRUMENT_OFFSET, @@ -1853,4 +1886,18 @@ ExecIndexScanRetrieveInstrumentation(IndexScanState *node) SharedInfo->num_workers * sizeof(IndexScanInstrumentation); node->iss_SharedInfo = palloc(size); memcpy(node->iss_SharedInfo, SharedInfo, size); + + /* + * Aggregate workers' table buffer/WAL usage into leader's entry, which + * ExecFinalizeNodeInstrumentation later rolls up into the node. Record + * the import so that session-level consumers can exclude it (see + * InstrAccumWorkerUsage). + */ + for (int i = 0; i < node->iss_SharedInfo->num_workers; i++) + { + Instrumentation *winstr = &node->iss_SharedInfo->winstrument[i].table_instr; + + InstrAccumStack(&node->iss_Instrument->table_instr, winstr); + InstrAccumWorkerUsage(&winstr->bufusage, &winstr->walusage); + } } diff --git a/src/include/executor/instrument_node.h b/src/include/executor/instrument_node.h index 4759a628afe..b9ddf8966f9 100644 --- a/src/include/executor/instrument_node.h +++ b/src/include/executor/instrument_node.h @@ -18,6 +18,8 @@ #ifndef INSTRUMENT_NODE_H #define INSTRUMENT_NODE_H +#include "executor/instrument.h" + /* * Offset added to plan_node_id to create a second TOC key for per-worker scan * instrumentation. Instrumentation and parallel-awareness are independent, so @@ -27,6 +29,7 @@ */ #define PARALLEL_KEY_SCAN_INSTRUMENT_OFFSET UINT64CONST(0xD000000000000000) + /* --------------------- * Instrumentation information for aggregate function execution * --------------------- @@ -108,6 +111,9 @@ typedef struct IndexScanInstrumentation /* Table tuples fetched count (incremented during index-only scans) */ uint64 ntabletuplefetches; + + /* Instrumentation utilized for tracking buffer usage during table access */ + Instrumentation table_instr; } IndexScanInstrumentation; /* diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out index f464baea4c8..3bceef6af90 100644 --- a/src/test/regress/expected/explain.out +++ b/src/test/regress/expected/explain.out @@ -261,6 +261,69 @@ explain_filter ] (1 row) \a +-- Index scans track table buffer accesses separately; make sure EXPLAIN +-- (BUFFERS) copes without ANALYZE, i.e. when the plan was never run +select explain_filter('explain (buffers, costs off) select * from tenk1 where unique1 = 42'); + explain_filter +----------------------------------------- + Index Scan using tenk1_unique1 on tenk1 + Index Cond: (unique1 = N) +(2 rows) + +\a +select explain_filter('explain (buffers, costs off, format json) select * from tenk1 where unique1 = 42'); +explain_filter +[ + { + "Plan": { + "Node Type": "Index Scan", + "Parallel Aware": false, + "Async Capable": false, + "Scan Direction": "Forward", + "Index Name": "tenk1_unique1", + "Relation Name": "tenk1", + "Alias": "tenk1", + "Disabled": false, + "Index Cond": "(unique1 = N)", + "Table Buffers": { + "Shared Hit Blocks": N, + "Shared Read Blocks": N, + "Shared Dirtied Blocks": N, + "Shared Written Blocks": N, + "Local Hit Blocks": N, + "Local Read Blocks": N, + "Local Dirtied Blocks": N, + "Local Written Blocks": N, + "Temp Read Blocks": N, + "Temp Written Blocks": N + }, + "Shared Hit Blocks": N, + "Shared Read Blocks": N, + "Shared Dirtied Blocks": N, + "Shared Written Blocks": N, + "Local Hit Blocks": N, + "Local Read Blocks": N, + "Local Dirtied Blocks": N, + "Local Written Blocks": N, + "Temp Read Blocks": N, + "Temp Written Blocks": N + }, + "Planning": { + "Shared Hit Blocks": N, + "Shared Read Blocks": N, + "Shared Dirtied Blocks": N, + "Shared Written Blocks": N, + "Local Hit Blocks": N, + "Local Read Blocks": N, + "Local Dirtied Blocks": N, + "Local Written Blocks": N, + "Temp Read Blocks": N, + "Temp Written Blocks": N + } + } +] +(1 row) +\a -- Check expansion of window definitions select explain_filter('explain verbose select sum(unique1) over w, sum(unique2) over (w order by hundred), sum(tenthous) over (w order by hundred) from tenk1 window w as (partition by ten)'); explain_filter @@ -1020,3 +1083,72 @@ DROP TRIGGER trig_test_trig ON trig_test_tab; DROP FUNCTION trig_test_func; DROP TABLE trig_test_tab; DROP TABLE trig_work_tab; +-- Parallel index scan buffer usage. +-- Table accesses of an index scan are tracked separately from the index +-- accesses, and parallel workers report them to the leader separately as +-- well. Verify that the total shown for the scan node matches between a +-- serial and a parallel execution where only workers do the scanning. +CREATE TABLE par_idx_buf_test AS SELECT * FROM tenk1; +CREATE INDEX ON par_idx_buf_test (unique1); +VACUUM ANALYZE par_idx_buf_test; +CREATE FUNCTION check_parallel_indexscan_buffers() RETURNS boolean AS $$ +DECLARE + plan_json json; + node json; + serial_buf int; + parallel_buf int; +BEGIN + -- Serial index scan: get the leaf scan node buffers as baseline + SET LOCAL max_parallel_workers_per_gather = 0; + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT count(stringu1) FROM par_idx_buf_test WHERE unique1 >= 0' INTO plan_json; + node := plan_json->0->'Plan'; + WHILE node->'Plans' IS NOT NULL LOOP + node := node->'Plans'->0; + END LOOP; + IF node->>'Node Type' <> 'Index Scan' THEN + RAISE EXCEPTION 'expected Index Scan, got %', node->>'Node Type'; + END IF; + serial_buf := + COALESCE((node->>'Shared Hit Blocks')::int, 0) + + COALESCE((node->>'Shared Read Blocks')::int, 0); + + -- Parallel index scan with only workers scanning + SET LOCAL parallel_setup_cost = 0; + SET LOCAL parallel_tuple_cost = 0; + SET LOCAL min_parallel_index_scan_size = 0; + SET LOCAL min_parallel_table_scan_size = 0; + SET LOCAL max_parallel_workers_per_gather = 2; + SET LOCAL parallel_leader_participation = off; + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT count(stringu1) FROM par_idx_buf_test WHERE unique1 >= 0' INTO plan_json; + node := plan_json->0->'Plan'; + WHILE node->'Plans' IS NOT NULL LOOP + node := node->'Plans'->0; + END LOOP; + IF node->>'Node Type' <> 'Index Scan' OR NOT (node->>'Parallel Aware')::bool THEN + RAISE EXCEPTION 'expected Parallel Index Scan, got %', node->>'Node Type'; + END IF; + parallel_buf := + COALESCE((node->>'Shared Hit Blocks')::int, 0) + + COALESCE((node->>'Shared Read Blocks')::int, 0); + + -- Workers may each fetch some heap pages the other also fetched, so + -- allow for a little slack, but the totals must be in the same ballpark. + RETURN parallel_buf >= serial_buf * 0.9 AND parallel_buf <= serial_buf * 1.5; +END; +$$ LANGUAGE plpgsql; +SET enable_seqscan = off; +SET enable_bitmapscan = off; +SET enable_indexonlyscan = off; +SELECT check_parallel_indexscan_buffers() AS parallel_indexscan_buffers_match; + parallel_indexscan_buffers_match +---------------------------------- + t +(1 row) + +RESET enable_seqscan; +RESET enable_bitmapscan; +RESET enable_indexonlyscan; +DROP FUNCTION check_parallel_indexscan_buffers; +DROP TABLE par_idx_buf_test; diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql index 101914b6d5b..4a9c8a24d4e 100644 --- a/src/test/regress/sql/explain.sql +++ b/src/test/regress/sql/explain.sql @@ -74,6 +74,13 @@ select explain_filter('explain (analyze, serialize, buffers, io, format yaml) se select explain_filter('explain (buffers, format json) select * from int8_tbl i8'); \a +-- Index scans track table buffer accesses separately; make sure EXPLAIN +-- (BUFFERS) copes without ANALYZE, i.e. when the plan was never run +select explain_filter('explain (buffers, costs off) select * from tenk1 where unique1 = 42'); +\a +select explain_filter('explain (buffers, costs off, format json) select * from tenk1 where unique1 = 42'); +\a + -- Check expansion of window definitions select explain_filter('explain verbose select sum(unique1) over w, sum(unique2) over (w order by hundred), sum(tenthous) over (w order by hundred) from tenk1 window w as (partition by ten)'); @@ -379,3 +386,71 @@ DROP TRIGGER trig_test_trig ON trig_test_tab; DROP FUNCTION trig_test_func; DROP TABLE trig_test_tab; DROP TABLE trig_work_tab; + +-- Parallel index scan buffer usage. +-- Table accesses of an index scan are tracked separately from the index +-- accesses, and parallel workers report them to the leader separately as +-- well. Verify that the total shown for the scan node matches between a +-- serial and a parallel execution where only workers do the scanning. +CREATE TABLE par_idx_buf_test AS SELECT * FROM tenk1; +CREATE INDEX ON par_idx_buf_test (unique1); +VACUUM ANALYZE par_idx_buf_test; + +CREATE FUNCTION check_parallel_indexscan_buffers() RETURNS boolean AS $$ +DECLARE + plan_json json; + node json; + serial_buf int; + parallel_buf int; +BEGIN + -- Serial index scan: get the leaf scan node buffers as baseline + SET LOCAL max_parallel_workers_per_gather = 0; + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT count(stringu1) FROM par_idx_buf_test WHERE unique1 >= 0' INTO plan_json; + node := plan_json->0->'Plan'; + WHILE node->'Plans' IS NOT NULL LOOP + node := node->'Plans'->0; + END LOOP; + IF node->>'Node Type' <> 'Index Scan' THEN + RAISE EXCEPTION 'expected Index Scan, got %', node->>'Node Type'; + END IF; + serial_buf := + COALESCE((node->>'Shared Hit Blocks')::int, 0) + + COALESCE((node->>'Shared Read Blocks')::int, 0); + + -- Parallel index scan with only workers scanning + SET LOCAL parallel_setup_cost = 0; + SET LOCAL parallel_tuple_cost = 0; + SET LOCAL min_parallel_index_scan_size = 0; + SET LOCAL min_parallel_table_scan_size = 0; + SET LOCAL max_parallel_workers_per_gather = 2; + SET LOCAL parallel_leader_participation = off; + EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, FORMAT JSON) + SELECT count(stringu1) FROM par_idx_buf_test WHERE unique1 >= 0' INTO plan_json; + node := plan_json->0->'Plan'; + WHILE node->'Plans' IS NOT NULL LOOP + node := node->'Plans'->0; + END LOOP; + IF node->>'Node Type' <> 'Index Scan' OR NOT (node->>'Parallel Aware')::bool THEN + RAISE EXCEPTION 'expected Parallel Index Scan, got %', node->>'Node Type'; + END IF; + parallel_buf := + COALESCE((node->>'Shared Hit Blocks')::int, 0) + + COALESCE((node->>'Shared Read Blocks')::int, 0); + + -- Workers may each fetch some heap pages the other also fetched, so + -- allow for a little slack, but the totals must be in the same ballpark. + RETURN parallel_buf >= serial_buf * 0.9 AND parallel_buf <= serial_buf * 1.5; +END; +$$ LANGUAGE plpgsql; + +SET enable_seqscan = off; +SET enable_bitmapscan = off; +SET enable_indexonlyscan = off; +SELECT check_parallel_indexscan_buffers() AS parallel_indexscan_buffers_match; +RESET enable_seqscan; +RESET enable_bitmapscan; +RESET enable_indexonlyscan; + +DROP FUNCTION check_parallel_indexscan_buffers; +DROP TABLE par_idx_buf_test; -- 2.47.1