Show index search count in EXPLAIN ANALYZE, take 2.

Expose the count of index searches/index descents in EXPLAIN ANALYZE's
output for index scan/index-only scan/bitmap index scan nodes.  This
information is particularly useful with scans that use ScalarArrayOp
quals, where the number of index searches can be unpredictable due to
implementation details that interact with physical index characteristics
(at least with nbtree SAOP scans, since Postgres 17 commit 5bf748b).
The information shown also provides useful context when EXPLAIN ANALYZE
runs a plan with an index scan node that successfully applied the skip
scan optimization (set to be added to nbtree by an upcoming patch).

The instrumentation works by teaching all index AMs to increment a new
nsearches counter whenever a new index search begins.  The counter is
incremented at exactly the same point that index AMs already increment
the pg_stat_*_indexes.idx_scan counter (we're counting the same event,
but at the scan level rather than the relation level).  Parallel queries
have workers copy their local counter struct into shared memory when an
index scan node ends -- even when it isn't a parallel aware scan node.
An earlier version of this patch that only worked with parallel aware
scans became commit 5ead85f (though that was quickly reverted by commit
d00107c following "debug_parallel_query=regress" buildfarm failures).

Our approach doesn't match the approach used when tracking other index
scan related costs (e.g., "Rows Removed by Filter:").  It is comparable
to the approach used in similar cases involving costs that are only
readily accessible inside an access method, not from the executor proper
(e.g., "Heap Blocks:" output for a Bitmap Heap Scan, which was recently
enhanced to show per-worker costs by commit 5a1e6df, using essentially
the same scheme as the one used here).  It is necessary for index AMs to
have direct responsibility for maintaining the new counter, since the
counter might need to be incremented multiple times per amgettuple call
(or per amgetbitmap call).  But it is also necessary for the executor
proper to manage the shared memory now used to transfer each worker's
counter struct to the leader.

Author: Peter Geoghegan <pg@bowt.ie>
Reviewed-By: Robert Haas <robertmhaas@gmail.com>
Reviewed-By: Tomas Vondra <tomas@vondra.me>
Reviewed-By: Masahiro Ikeda <ikedamsh@oss.nttdata.com>
Reviewed-By: Matthias van de Meent <boekewurm+postgres@gmail.com>
Discussion: https://postgr.es/m/CAH2-WzkRqvaqR2CTNqTZP0z6FuL4-3ED6eQB0yx38XBNj1v-4Q@mail.gmail.com
Discussion: https://postgr.es/m/CAH2-Wz=PKR6rB7qbx+Vnd7eqeB5VTcrW=iJvAsTsKbdG+kW_UA@mail.gmail.com

Author: petergeoghegan

contrib/bloom/blscan.c

@@ -116,6 +116,8 @@ blgetbitmap(IndexScanDesc scan, TIDBitmap *tbm)
 	bas = GetAccessStrategy(BAS_BULKREAD);
 	npages = RelationGetNumberOfBlocks(scan->indexRelation);
 	pgstat_count_index_scan(scan->indexRelation);
+	if (scan->instrument)
+		scan->instrument->nsearches++;
 
 	for (blkno = BLOOM_HEAD_BLKNO; blkno < npages; blkno++)
 	{

doc/src/sgml/bloom.sgml

@@ -173,10 +173,11 @@ CREATE INDEX
    Buffers: shared hit=21864
    ->  Bitmap Index Scan on bloomidx  (cost=0.00..178436.00 rows=1 width=0) (actual time=20.005..20.005 rows=2300.00 loops=1)
          Index Cond: ((i2 = 898732) AND (i5 = 123451))
+         Index Searches: 1
          Buffers: shared hit=19608
  Planning Time: 0.099 ms
  Execution Time: 22.632 ms
-(10 rows)
+(11 rows)
 </programlisting>
   </para>
 
@@ -208,13 +209,15 @@ CREATE INDEX
          Buffers: shared hit=6
          -&gt;  Bitmap Index Scan on btreeidx5  (cost=0.00..4.52 rows=11 width=0) (actual time=0.026..0.026 rows=7.00 loops=1)
                Index Cond: (i5 = 123451)
+               Index Searches: 1
                Buffers: shared hit=3
          -&gt;  Bitmap Index Scan on btreeidx2  (cost=0.00..4.52 rows=11 width=0) (actual time=0.007..0.007 rows=8.00 loops=1)
                Index Cond: (i2 = 898732)
+               Index Searches: 1
                Buffers: shared hit=3
  Planning Time: 0.264 ms
  Execution Time: 0.047 ms
-(13 rows)
+(15 rows)
 </programlisting>
    Although this query runs much faster than with either of the single
    indexes, we pay a penalty in index size.  Each of the single-column

doc/src/sgml/monitoring.sgml

@@ -4234,16 +4234,32 @@ description | Waiting for a newly initialized WAL file to reach durable storage
 
   <note>
    <para>
-    Queries that use certain <acronym>SQL</acronym> constructs to search for
-    rows matching any value out of a list or array of multiple scalar values
-    (see <xref linkend="functions-comparisons"/>) perform multiple
-    <quote>primitive</quote> index scans (up to one primitive scan per scalar
-    value) during query execution.  Each internal primitive index scan
-    increments <structname>pg_stat_all_indexes</structname>.<structfield>idx_scan</structfield>,
+    Index scans may sometimes perform multiple index searches per execution.
+    Each index search increments <structname>pg_stat_all_indexes</structname>.<structfield>idx_scan</structfield>,
     so it's possible for the count of index scans to significantly exceed the
     total number of index scan executor node executions.
    </para>
+   <para>
+    This can happen with queries that use certain <acronym>SQL</acronym>
+    constructs to search for rows matching any value out of a list or array of
+    multiple scalar values (see <xref linkend="functions-comparisons"/>).  It
+    can also happen to queries with a
+    <literal><replaceable>column_name</replaceable> =
+     <replaceable>value1</replaceable> OR
+     <replaceable>column_name</replaceable> =
+     <replaceable>value2</replaceable> ...</literal> construct, though only
+    when the optimizer transforms the construct into an equivalent
+    multi-valued array representation.
+   </para>
   </note>
+  <tip>
+   <para>
+    <command>EXPLAIN ANALYZE</command> outputs the total number of index
+    searches performed by each index scan node.  See
+    <xref linkend="using-explain-analyze"/> for an example demonstrating how
+    this works.
+   </para>
+  </tip>
 
  </sect2>
 

doc/src/sgml/perform.sgml

@@ -729,9 +729,11 @@ WHERE t1.unique1 < 10 AND t1.unique2 = t2.unique2;
          Buffers: shared hit=3 read=5 written=4
          ->  Bitmap Index Scan on tenk1_unique1  (cost=0.00..4.36 rows=10 width=0) (actual time=0.004..0.004 rows=10.00 loops=1)
                Index Cond: (unique1 < 10)
+               Index Searches: 1
                Buffers: shared hit=2
    ->  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
          Buffers: shared hit=24 read=6
  Planning:
    Buffers: shared hit=15 dirtied=9
@@ -790,6 +792,7 @@ WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2 ORDER BY t1.fivethous;
                      Buffers: shared hit=92
                      ->  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=100 width=0) (actual time=0.013..0.013 rows=100.00 loops=1)
                            Index Cond: (unique1 < 100)
+                           Index Searches: 1
                            Buffers: shared hit=2
  Planning:
    Buffers: shared hit=12
@@ -805,6 +808,58 @@ WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2 ORDER BY t1.fivethous;
     shown.)
    </para>
 
+   <para>
+    Index Scan nodes (as well as Bitmap Index Scan and Index-Only Scan nodes)
+    show an <quote>Index Searches</quote> line that reports the total number
+    of searches across <emphasis>all</emphasis> node
+    executions/<literal>loops</literal>:
+
+<screen>
+EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE thousand IN (1, 500, 700, 999);
+                                                            QUERY PLAN
+-------------------------------------------------------------------&zwsp;---------------------------------------------------------------
+ Bitmap Heap Scan on tenk1  (cost=9.45..73.44 rows=40 width=244) (actual time=0.012..0.028 rows=40.00 loops=1)
+   Recheck Cond: (thousand = ANY ('{1,500,700,999}'::integer[]))
+   Heap Blocks: exact=39
+   Buffers: shared hit=47
+   ->  Bitmap Index Scan on tenk1_thous_tenthous  (cost=0.00..9.44 rows=40 width=0) (actual time=0.009..0.009 rows=40.00 loops=1)
+         Index Cond: (thousand = ANY ('{1,500,700,999}'::integer[]))
+         Index Searches: 4
+         Buffers: shared hit=8
+ Planning Time: 0.029 ms
+ Execution Time: 0.034 ms
+</screen>
+
+    Here we see a Bitmap Index Scan node that needed 4 separate index
+    searches.  The scan had to search the index from the
+    <structname>tenk1_thous_tenthous</structname> index root page once per
+    <type>integer</type> value from the predicate's <literal>IN</literal>
+    construct.  However, the number of index searches often won't have such a
+    simple correspondence to the query predicate:
+
+<screen>
+EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE thousand IN (1, 2, 3, 4);
+                                                            QUERY PLAN
+--------------------------------------------------------------------&zwsp;--------------------------------------------------------------
+ Bitmap Heap Scan on tenk1  (cost=9.45..73.44 rows=40 width=244) (actual time=0.009..0.019 rows=40.00 loops=1)
+   Recheck Cond: (thousand = ANY ('{1,2,3,4}'::integer[]))
+   Heap Blocks: exact=38
+   Buffers: shared hit=40
+   ->  Bitmap Index Scan on tenk1_thous_tenthous  (cost=0.00..9.44 rows=40 width=0) (actual time=0.005..0.005 rows=40.00 loops=1)
+         Index Cond: (thousand = ANY ('{1,2,3,4}'::integer[]))
+         Index Searches: 1
+         Buffers: shared hit=2
+ Planning Time: 0.029 ms
+ Execution Time: 0.026 ms
+</screen>
+
+    This variant of our <literal>IN</literal> query performed only 1 index
+    search.  It spent less time traversing the index (compared to the original
+    query) because its <literal>IN</literal> construct uses values matching
+    index tuples stored next to each other, on the same
+    <structname>tenk1_thous_tenthous</structname> index leaf page.
+   </para>
+
    <para>
     Another type of extra information is the number of rows removed by a
     filter condition:
@@ -861,6 +916,7 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @&gt; polygon '(0.5,2.0)';
  Index Scan using gpolygonind on polygon_tbl  (cost=0.13..8.15 rows=1 width=85) (actual time=0.074..0.074 rows=0.00 loops=1)
    Index Cond: (f1 @&gt; '((0.5,2))'::polygon)
    Rows Removed by Index Recheck: 1
+   Index Searches: 1
    Buffers: shared hit=1
  Planning Time: 0.039 ms
  Execution Time: 0.098 ms
@@ -894,8 +950,10 @@ EXPLAIN (ANALYZE, BUFFERS OFF) SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND un
    -&gt;  BitmapAnd  (cost=25.07..25.07 rows=10 width=0) (actual time=0.100..0.101 rows=0.00 loops=1)
          -&gt;  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=100 width=0) (actual time=0.027..0.027 rows=100.00 loops=1)
                Index Cond: (unique1 &lt; 100)
+               Index Searches: 1
          -&gt;  Bitmap Index Scan on tenk1_unique2  (cost=0.00..19.78 rows=999 width=0) (actual time=0.070..0.070 rows=999.00 loops=1)
                Index Cond: (unique2 &gt; 9000)
+               Index Searches: 1
  Planning Time: 0.162 ms
  Execution Time: 0.143 ms
 </screen>
@@ -923,6 +981,7 @@ EXPLAIN ANALYZE UPDATE tenk1 SET hundred = hundred + 1 WHERE unique1 &lt; 100;
          Buffers: shared hit=4 read=2
          -&gt;  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=100 width=0) (actual time=0.031..0.031 rows=100.00 loops=1)
                Index Cond: (unique1 &lt; 100)
+               Index Searches: 1
                Buffers: shared read=2
  Planning Time: 0.151 ms
  Execution Time: 1.856 ms
@@ -1061,6 +1120,7 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique2 &gt; 9000
          Index Cond: (unique2 &gt; 9000)
          Filter: (unique1 &lt; 100)
          Rows Removed by Filter: 287
+         Index Searches: 1
          Buffers: shared hit=16
  Planning Time: 0.077 ms
  Execution Time: 0.086 ms

doc/src/sgml/ref/explain.sgml

@@ -506,10 +506,11 @@ EXPLAIN ANALYZE EXECUTE query(100, 200);
    Buffers: shared hit=4
    ->  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
          Buffers: shared hit=4
  Planning Time: 0.244 ms
  Execution Time: 0.073 ms
-(9 rows)
+(10 rows)
 </programlisting>
   </para>
 

doc/src/sgml/rules.sgml

@@ -1046,6 +1046,7 @@ SELECT count(*) FROM words WHERE word = 'caterpiler';
    ->  Index Only Scan using wrd_word on wrd  (cost=0.42..4.44 rows=1 width=0) (actual time=0.039..0.039 rows=0.00 loops=1)
          Index Cond: (word = 'caterpiler'::text)
          Heap Fetches: 0
+         Index Searches: 1
  Planning time: 0.164 ms
  Execution time: 0.117 ms
 </programlisting>
@@ -1090,6 +1091,7 @@ SELECT word FROM words ORDER BY word &lt;-&gt; 'caterpiler' LIMIT 10;
  Limit  (cost=0.29..1.06 rows=10 width=10) (actual time=187.222..188.257 rows=10.00 loops=1)
    -&gt;  Index Scan using wrd_trgm on wrd  (cost=0.29..37020.87 rows=479829 width=10) (actual time=187.219..188.252 rows=10.00 loops=1)
          Order By: (word &lt;-&gt; 'caterpiler'::text)
+         Index Searches: 1
  Planning time: 0.196 ms
  Execution time: 198.640 ms
 </programlisting>

src/backend/access/brin/brin.c

@@ -592,6 +592,8 @@ bringetbitmap(IndexScanDesc scan, TIDBitmap *tbm)
 	opaque = (BrinOpaque *) scan->opaque;
 	bdesc = opaque->bo_bdesc;
 	pgstat_count_index_scan(idxRel);
+	if (scan->instrument)
+		scan->instrument->nsearches++;
 
 	/*
 	 * We need to know the size of the table so that we know how long to

src/backend/access/gin/ginscan.c

@@ -442,6 +442,8 @@ ginNewScanKey(IndexScanDesc scan)
 	MemoryContextSwitchTo(oldCtx);
 
 	pgstat_count_index_scan(scan->indexRelation);
+	if (scan->instrument)
+		scan->instrument->nsearches++;
 }
 
 void

src/backend/access/gist/gistget.c

@@ -625,6 +625,8 @@ gistgettuple(IndexScanDesc scan, ScanDirection dir)
 		GISTSearchItem fakeItem;
 
 		pgstat_count_index_scan(scan->indexRelation);
+		if (scan->instrument)
+			scan->instrument->nsearches++;
 
 		so->firstCall = false;
 		so->curPageData = so->nPageData = 0;
@@ -750,6 +752,8 @@ gistgetbitmap(IndexScanDesc scan, TIDBitmap *tbm)
 		return 0;
 
 	pgstat_count_index_scan(scan->indexRelation);
+	if (scan->instrument)
+		scan->instrument->nsearches++;
 
 	/* Begin the scan by processing the root page */
 	so->curPageData = so->nPageData = 0;

src/backend/access/hash/hashsearch.c

@@ -298,6 +298,8 @@ _hash_first(IndexScanDesc scan, ScanDirection dir)
 	HashScanPosItem *currItem;
 
 	pgstat_count_index_scan(rel);
+	if (scan->instrument)
+		scan->instrument->nsearches++;
 
 	/*
 	 * We do not support hash scans with no index qualification, because we

src/backend/access/heap/heapam_handler.c

@@ -749,7 +749,7 @@ heapam_relation_copy_for_cluster(Relation OldHeap, Relation NewHeap,
 
 		tableScan = NULL;
 		heapScan = NULL;
-		indexScan = index_beginscan(OldHeap, OldIndex, SnapshotAny, 0, 0);
+		indexScan = index_beginscan(OldHeap, OldIndex, SnapshotAny, NULL, 0, 0);
 		index_rescan(indexScan, NULL, 0, NULL, 0);
 	}
 	else

src/backend/access/index/genam.c

@@ -119,6 +119,7 @@ RelationGetIndexScan(Relation indexRelation, int nkeys, int norderbys)
 	scan->ignore_killed_tuples = !scan->xactStartedInRecovery;
 
 	scan->opaque = NULL;
+	scan->instrument = NULL;
 
 	scan->xs_itup = NULL;
 	scan->xs_itupdesc = NULL;
@@ -446,7 +447,7 @@ systable_beginscan(Relation heapRelation,
 		}
 
 		sysscan->iscan = index_beginscan(heapRelation, irel,
-										 snapshot, nkeys, 0);
+										 snapshot, NULL, nkeys, 0);
 		index_rescan(sysscan->iscan, idxkey, nkeys, NULL, 0);
 		sysscan->scan = NULL;
 
@@ -711,7 +712,7 @@ systable_beginscan_ordered(Relation heapRelation,
 	}
 
 	sysscan->iscan = index_beginscan(heapRelation, indexRelation,
-									 snapshot, nkeys, 0);
+									 snapshot, NULL, nkeys, 0);
 	index_rescan(sysscan->iscan, idxkey, nkeys, NULL, 0);
 	sysscan->scan = NULL;