[CF 5183] Showing primitive index scan count in EXPLAIN ANALYZE (for skip scan and SAOP scans)

This branch was automatically generated by a robot using patches from an
email thread registered at:

https://commitfest.postgresql.org/patch/5183

The branch will be overwritten each time a new patch version is posted to
the thread, and also periodically to check for bitrot caused by changes
on the master branch.

Patch(es): https://www.postgresql.org/message-id/CAH2-Wz=zzD+752xD8NjVfdxh6c_vRdhWhwRHSw4qXOt=quk=vg@mail.gmail.com
Author(s): Peter Geoghegan

Author: Commitfest Bot

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,30 @@ 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
+    <literal><replaceable>expression</replaceable> =
+     <replaceable>value1</replaceable> OR
+     <replaceable>expression</replaceable> = <replaceable>value2</replaceable>
+     ...</literal> constructs, though only when the optimizer transforms the
+    constructs 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.
+   </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 correspondance 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