Show index search count in EXPLAIN ANALYZE.

Expose the count of index searches/index descents in EXPLAIN ANALYZE's
output for index scan nodes.  This information is particularly useful
with scans that use ScalarArrayOp quals, where the number of index scans
isn't predictable in advance (at least not with optimizations like the
one added to nbtree by Postgres 17 commit 5bf748b).  It will also be
useful when EXPLAIN ANALYZE shows details of an nbtree index scan that
uses skip scan optimizations set to be introduced by an upcoming patch.

The instrumentation works by teaching 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 must already
increment the index's pg_stat_*_indexes.idx_scan counter (we're counting
the same event, but at the scan level rather than the relation level).
The new counter is stored in the scan descriptor (IndexScanDescData),
which explain.c reaches by going through the scan node's PlanState.

This approach doesn't match the approach used when tracking other index
scan specific costs (e.g., "Rows Removed by Filter:").  It is similar to
the approach used in other cases where we must track costs that are only
readily accessible inside an access method, and not from the executor
(e.g., "Heap Blocks:" output for a Bitmap Heap Scan).  It is inherently
necessary to maintain a counter that can be incremented multiple times
during a single amgettuple call (or amgetbitmap call), and directly
exposing PlanState.instrument to index access methods seems unappealing.

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

Author: petergeoghegan

contrib/bloom/blscan.c

@@ -116,6 +116,7 @@ blgetbitmap(IndexScanDesc scan, TIDBitmap *tbm)
 	bas = GetAccessStrategy(BAS_BULKREAD);
 	npages = RelationGetNumberOfBlocks(scan->indexRelation);
 	pgstat_count_index_scan(scan->indexRelation);
+	scan->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 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.037 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
+----------------------------------------------------------------------------------------------------------------------------------
+ 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

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

src/backend/access/gin/ginscan.c

@@ -437,6 +437,7 @@ ginNewScanKey(IndexScanDesc scan)
 	MemoryContextSwitchTo(oldCtx);
 
 	pgstat_count_index_scan(scan->indexRelation);
+	scan->nsearches++;
 }
 
 void

src/backend/access/gist/gistget.c

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

src/backend/access/hash/hashsearch.c

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

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->nsearches = 0;
 
 	scan->xs_itup = NULL;
 	scan->xs_itupdesc = NULL;

src/backend/access/nbtree/nbtree.c

@@ -70,6 +70,7 @@ typedef struct BTParallelScanDescData
 	BTPS_State	btps_pageStatus;	/* indicates whether next page is
 									 * available for scan. see above for
 									 * possible states of parallel scan. */
+	uint64		btps_nsearches; /* tracked for IndexScanDescData.nsearches */
 	slock_t		btps_mutex;		/* protects above variables, btps_arrElems */
 	ConditionVariable btps_cv;	/* used to synchronize parallel scan */
 
@@ -557,6 +558,7 @@ btinitparallelscan(void *target)
 	bt_target->btps_nextScanPage = InvalidBlockNumber;
 	bt_target->btps_lastCurrPage = InvalidBlockNumber;
 	bt_target->btps_pageStatus = BTPARALLEL_NOT_INITIALIZED;
+	bt_target->btps_nsearches = 0;
 	ConditionVariableInit(&bt_target->btps_cv);
 }
 
@@ -583,6 +585,7 @@ btparallelrescan(IndexScanDesc scan)
 	btscan->btps_nextScanPage = InvalidBlockNumber;
 	btscan->btps_lastCurrPage = InvalidBlockNumber;
 	btscan->btps_pageStatus = BTPARALLEL_NOT_INITIALIZED;
+	/* deliberately don't reset btps_nsearches (matches index_rescan) */
 	SpinLockRelease(&btscan->btps_mutex);
 }
 
@@ -676,6 +679,7 @@ _bt_parallel_seize(IndexScanDesc scan, BlockNumber *next_scan_page,
 			{
 				/* Can start scheduled primitive scan right away, so do so */
 				btscan->btps_pageStatus = BTPARALLEL_ADVANCING;
+				btscan->btps_nsearches++;
 				for (int i = 0; i < so->numArrayKeys; i++)
 				{
 					BTArrayKeyInfo *array = &so->arrayKeys[i];
@@ -712,6 +716,11 @@ _bt_parallel_seize(IndexScanDesc scan, BlockNumber *next_scan_page,
 			 */
 			btscan->btps_pageStatus = BTPARALLEL_ADVANCING;
 			Assert(btscan->btps_nextScanPage != P_NONE);
+			if (btscan->btps_nextScanPage == InvalidBlockNumber)
+			{
+				Assert(first);
+				btscan->btps_nsearches++;
+			}
 			*next_scan_page = btscan->btps_nextScanPage;
 			*last_curr_page = btscan->btps_lastCurrPage;
 			exit_loop = true;
@@ -810,6 +819,12 @@ _bt_parallel_done(IndexScanDesc scan)
 		btscan->btps_pageStatus = BTPARALLEL_DONE;
 		status_changed = true;
 	}
+
+	/*
+	 * Don't use local nsearches counter -- overwrite it with the nsearches
+	 * counter that we've been maintaining in shared memory
+	 */
+	scan->nsearches = btscan->btps_nsearches;
 	SpinLockRelease(&btscan->btps_mutex);
 
 	/* wake up all the workers associated with this parallel scan */

src/backend/access/nbtree/nbtsearch.c

@@ -950,6 +950,7 @@ _bt_first(IndexScanDesc scan, ScanDirection dir)
 	 * _bt_search/_bt_endpoint below
 	 */
 	pgstat_count_index_scan(rel);
+	scan->nsearches++;
 
 	/*----------
 	 * Examine the scan keys to discover where we need to start the scan.

src/backend/access/spgist/spgscan.c

@@ -421,6 +421,7 @@ spgrescan(IndexScanDesc scan, ScanKey scankey, int nscankeys,
 
 	/* count an indexscan for stats */
 	pgstat_count_index_scan(scan->indexRelation);
+	scan->nsearches++;
 }
 
 void