Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commit5ead85f

Browse files
Show index search count in EXPLAIN ANALYZE.
Expose the count of index searches/index descents in EXPLAIN ANALYZE'soutput for index scan nodes. This information is particularly usefulwith scans that use ScalarArrayOp quals, where the number of index scansisn't predictable in advance (at least not with optimizations like theone added to nbtree by Postgres 17 commit5bf748b). It will also beuseful when EXPLAIN ANALYZE shows details of an nbtree index scan thatuses skip scan optimizations set to be introduced by an upcoming patch.The instrumentation works by teaching index AMs to increment a newnsearches counter whenever a new index search begins. The counter isincremented at exactly the same point that index AMs must alreadyincrement the index's pg_stat_*_indexes.idx_scan counter (we're countingthe 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 indexscan specific costs (e.g., "Rows Removed by Filter:"). It is similar tothe approach used in other cases where we must track costs that are onlyreadily accessible inside an access method, and not from the executor(e.g., "Heap Blocks:" output for a Bitmap Heap Scan). It is inherentlynecessary to maintain a counter that can be incremented multiple timesduring a single amgettuple call (or amgetbitmap call), and directlyexposing 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.comDiscussion:https://postgr.es/m/CAH2-WzkRqvaqR2CTNqTZP0z6FuL4-3ED6eQB0yx38XBNj1v-4Q@mail.gmail.com
1 parent635f580 commit5ead85f

File tree

22 files changed

+310
-49
lines changed

22 files changed

+310
-49
lines changed

‎contrib/bloom/blscan.c

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -116,6 +116,7 @@ blgetbitmap(IndexScanDesc scan, TIDBitmap *tbm)
116116
bas=GetAccessStrategy(BAS_BULKREAD);
117117
npages=RelationGetNumberOfBlocks(scan->indexRelation);
118118
pgstat_count_index_scan(scan->indexRelation);
119+
scan->nsearches++;
119120

120121
for (blkno=BLOOM_HEAD_BLKNO;blkno<npages;blkno++)
121122
{

‎doc/src/sgml/bloom.sgml

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -173,10 +173,11 @@ CREATE INDEX
173173
Buffers: shared hit=21864
174174
-&gt; 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)
175175
Index Cond: ((i2 = 898732) AND (i5 = 123451))
176+
Index Searches: 1
176177
Buffers: shared hit=19608
177178
Planning Time: 0.099 ms
178179
Execution Time: 22.632 ms
179-
(10 rows)
180+
(11 rows)
180181
</programlisting>
181182
</para>
182183

@@ -208,13 +209,15 @@ CREATE INDEX
208209
Buffers: shared hit=6
209210
-&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)
210211
Index Cond: (i5 = 123451)
212+
Index Searches: 1
211213
Buffers: shared hit=3
212214
-&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)
213215
Index Cond: (i2 = 898732)
216+
Index Searches: 1
214217
Buffers: shared hit=3
215218
Planning Time: 0.264 ms
216219
Execution Time: 0.047 ms
217-
(13 rows)
220+
(15 rows)
218221
</programlisting>
219222
Although this query runs much faster than with either of the single
220223
indexes, we pay a penalty in index size. Each of the single-column

‎doc/src/sgml/monitoring.sgml

Lines changed: 22 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -4234,16 +4234,32 @@ description | Waiting for a newly initialized WAL file to reach durable storage
42344234

42354235
<note>
42364236
<para>
4237-
Queries that use certain <acronym>SQL</acronym> constructs to search for
4238-
rows matching any value out of a list or array of multiple scalar values
4239-
(see <xref linkend="functions-comparisons"/>) perform multiple
4240-
<quote>primitive</quote> index scans (up to one primitive scan per scalar
4241-
value) during query execution. Each internal primitive index scan
4242-
increments <structname>pg_stat_all_indexes</structname>.<structfield>idx_scan</structfield>,
4237+
Index scans may sometimes perform multiple index searches per execution.
4238+
Each index search increments <structname>pg_stat_all_indexes</structname>.<structfield>idx_scan</structfield>,
42434239
so it's possible for the count of index scans to significantly exceed the
42444240
total number of index scan executor node executions.
42454241
</para>
4242+
<para>
4243+
This can happen with queries that use certain <acronym>SQL</acronym>
4244+
constructs to search for rows matching any value out of a list or array of
4245+
multiple scalar values (see <xref linkend="functions-comparisons"/>). It
4246+
can also happen to queries with a
4247+
<literal><replaceable>column_name</replaceable> =
4248+
<replaceable>value1</replaceable> OR
4249+
<replaceable>column_name</replaceable> =
4250+
<replaceable>value2</replaceable> ...</literal> construct, though only
4251+
when the optimizer transforms the construct into an equivalent
4252+
multi-valued array representation.
4253+
</para>
42464254
</note>
4255+
<tip>
4256+
<para>
4257+
<command>EXPLAIN ANALYZE</command> outputs the total number of index
4258+
searches performed by each index scan node. See
4259+
<xref linkend="using-explain-analyze"/> for an example demonstrating how
4260+
this works.
4261+
</para>
4262+
</tip>
42474263

42484264
</sect2>
42494265

‎doc/src/sgml/perform.sgml

Lines changed: 60 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -729,9 +729,11 @@ WHERE t1.unique1 &lt; 10 AND t1.unique2 = t2.unique2;
729729
Buffers: shared hit=3 read=5 written=4
730730
-&gt; 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)
731731
Index Cond: (unique1 &lt; 10)
732+
Index Searches: 1
732733
Buffers: shared hit=2
733734
-&gt; 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)
734735
Index Cond: (unique2 = t1.unique2)
736+
Index Searches: 10
735737
Buffers: shared hit=24 read=6
736738
Planning:
737739
Buffers: shared hit=15 dirtied=9
@@ -790,6 +792,7 @@ WHERE t1.unique1 &lt; 100 AND t1.unique2 = t2.unique2 ORDER BY t1.fivethous;
790792
Buffers: shared hit=92
791793
-&gt; 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)
792794
Index Cond: (unique1 &lt; 100)
795+
Index Searches: 1
793796
Buffers: shared hit=2
794797
Planning:
795798
Buffers: shared hit=12
@@ -805,6 +808,58 @@ WHERE t1.unique1 &lt; 100 AND t1.unique2 = t2.unique2 ORDER BY t1.fivethous;
805808
shown.)
806809
</para>
807810

811+
<para>
812+
Index Scan nodes (as well as Bitmap Index Scan and Index-Only Scan nodes)
813+
show an <quote>Index Searches</quote> line that reports the total number
814+
of searches across <emphasis>all</emphasis> node
815+
executions/<literal>loops</literal>:
816+
817+
<screen>
818+
EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE thousand IN (1, 500, 700, 999);
819+
QUERY PLAN
820+
-------------------------------------------------------------------&zwsp;---------------------------------------------------------
821+
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)
822+
Recheck Cond: (thousand = ANY ('{1,500,700,999}'::integer[]))
823+
Heap Blocks: exact=39
824+
Buffers: shared hit=47
825+
-> 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)
826+
Index Cond: (thousand = ANY ('{1,500,700,999}'::integer[]))
827+
Index Searches: 4
828+
Buffers: shared hit=8
829+
Planning Time: 0.037 ms
830+
Execution Time: 0.034 ms
831+
</screen>
832+
833+
Here we see a Bitmap Index Scan node that needed 4 separate index
834+
searches. The scan had to search the index from the
835+
<structname>tenk1_thous_tenthous</structname> index root page once per
836+
<type>integer</type> value from the predicate's <literal>IN</literal>
837+
construct. However, the number of index searches often won't have such a
838+
simple correspondence to the query predicate:
839+
840+
<screen>
841+
EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE thousand IN (1, 2, 3, 4);
842+
QUERY PLAN
843+
----------------------------------------------------------------------------------------------------------------------------------
844+
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)
845+
Recheck Cond: (thousand = ANY ('{1,2,3,4}'::integer[]))
846+
Heap Blocks: exact=38
847+
Buffers: shared hit=40
848+
-> 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)
849+
Index Cond: (thousand = ANY ('{1,2,3,4}'::integer[]))
850+
Index Searches: 1
851+
Buffers: shared hit=2
852+
Planning Time: 0.029 ms
853+
Execution Time: 0.026 ms
854+
</screen>
855+
856+
This variant of our <literal>IN</literal> query performed only 1 index
857+
search. It spent less time traversing the index (compared to the original
858+
query) because its <literal>IN</literal> construct uses values matching
859+
index tuples stored next to each other, on the same
860+
<structname>tenk1_thous_tenthous</structname> index leaf page.
861+
</para>
862+
808863
<para>
809864
Another type of extra information is the number of rows removed by a
810865
filter condition:
@@ -861,6 +916,7 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @&gt; polygon '(0.5,2.0)';
861916
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)
862917
Index Cond: (f1 @&gt; '((0.5,2))'::polygon)
863918
Rows Removed by Index Recheck: 1
919+
Index Searches: 1
864920
Buffers: shared hit=1
865921
Planning Time: 0.039 ms
866922
Execution Time: 0.098 ms
@@ -894,8 +950,10 @@ EXPLAIN (ANALYZE, BUFFERS OFF) SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND un
894950
-&gt; BitmapAnd (cost=25.07..25.07 rows=10 width=0) (actual time=0.100..0.101 rows=0.00 loops=1)
895951
-&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)
896952
Index Cond: (unique1 &lt; 100)
953+
Index Searches: 1
897954
-&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)
898955
Index Cond: (unique2 &gt; 9000)
956+
Index Searches: 1
899957
Planning Time: 0.162 ms
900958
Execution Time: 0.143 ms
901959
</screen>
@@ -923,6 +981,7 @@ EXPLAIN ANALYZE UPDATE tenk1 SET hundred = hundred + 1 WHERE unique1 &lt; 100;
923981
Buffers: shared hit=4 read=2
924982
-&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)
925983
Index Cond: (unique1 &lt; 100)
984+
Index Searches: 1
926985
Buffers: shared read=2
927986
Planning Time: 0.151 ms
928987
Execution Time: 1.856 ms
@@ -1061,6 +1120,7 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique2 &gt; 9000
10611120
Index Cond: (unique2 &gt; 9000)
10621121
Filter: (unique1 &lt; 100)
10631122
Rows Removed by Filter: 287
1123+
Index Searches: 1
10641124
Buffers: shared hit=16
10651125
Planning Time: 0.077 ms
10661126
Execution Time: 0.086 ms

‎doc/src/sgml/ref/explain.sgml

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -506,10 +506,11 @@ EXPLAIN ANALYZE EXECUTE query(100, 200);
506506
Buffers: shared hit=4
507507
-&gt; 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)
508508
Index Cond: ((id &gt; 100) AND (id &lt; 200))
509+
Index Searches: 1
509510
Buffers: shared hit=4
510511
Planning Time: 0.244 ms
511512
Execution Time: 0.073 ms
512-
(9 rows)
513+
(10 rows)
513514
</programlisting>
514515
</para>
515516

‎doc/src/sgml/rules.sgml

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1046,6 +1046,7 @@ SELECT count(*) FROM words WHERE word = 'caterpiler';
10461046
-&gt; 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)
10471047
Index Cond: (word = 'caterpiler'::text)
10481048
Heap Fetches: 0
1049+
Index Searches: 1
10491050
Planning time: 0.164 ms
10501051
Execution time: 0.117 ms
10511052
</programlisting>
@@ -1090,6 +1091,7 @@ SELECT word FROM words ORDER BY word &lt;-&gt; 'caterpiler' LIMIT 10;
10901091
Limit (cost=0.29..1.06 rows=10 width=10) (actual time=187.222..188.257 rows=10.00 loops=1)
10911092
-&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)
10921093
Order By: (word &lt;-&gt; 'caterpiler'::text)
1094+
Index Searches: 1
10931095
Planning time: 0.196 ms
10941096
Execution time: 198.640 ms
10951097
</programlisting>

‎src/backend/access/brin/brin.c

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -591,6 +591,7 @@ bringetbitmap(IndexScanDesc scan, TIDBitmap *tbm)
591591
opaque= (BrinOpaque*)scan->opaque;
592592
bdesc=opaque->bo_bdesc;
593593
pgstat_count_index_scan(idxRel);
594+
scan->nsearches++;
594595

595596
/*
596597
* We need to know the size of the table so that we know how long to

‎src/backend/access/gin/ginscan.c

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -437,6 +437,7 @@ ginNewScanKey(IndexScanDesc scan)
437437
MemoryContextSwitchTo(oldCtx);
438438

439439
pgstat_count_index_scan(scan->indexRelation);
440+
scan->nsearches++;
440441
}
441442

442443
void

‎src/backend/access/gist/gistget.c

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -625,6 +625,7 @@ gistgettuple(IndexScanDesc scan, ScanDirection dir)
625625
GISTSearchItemfakeItem;
626626

627627
pgstat_count_index_scan(scan->indexRelation);
628+
scan->nsearches++;
628629

629630
so->firstCall= false;
630631
so->curPageData=so->nPageData=0;
@@ -750,6 +751,7 @@ gistgetbitmap(IndexScanDesc scan, TIDBitmap *tbm)
750751
return0;
751752

752753
pgstat_count_index_scan(scan->indexRelation);
754+
scan->nsearches++;
753755

754756
/* Begin the scan by processing the root page */
755757
so->curPageData=so->nPageData=0;

‎src/backend/access/hash/hashsearch.c

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -298,6 +298,7 @@ _hash_first(IndexScanDesc scan, ScanDirection dir)
298298
HashScanPosItem*currItem;
299299

300300
pgstat_count_index_scan(rel);
301+
scan->nsearches++;
301302

302303
/*
303304
* We do not support hash scans with no index qualification, because we

‎src/backend/access/index/genam.c

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -119,6 +119,7 @@ RelationGetIndexScan(Relation indexRelation, int nkeys, int norderbys)
119119
scan->ignore_killed_tuples= !scan->xactStartedInRecovery;
120120

121121
scan->opaque=NULL;
122+
scan->nsearches=0;
122123

123124
scan->xs_itup=NULL;
124125
scan->xs_itupdesc=NULL;

‎src/backend/access/nbtree/nbtree.c

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -70,6 +70,7 @@ typedef struct BTParallelScanDescData
7070
BTPS_Statebtps_pageStatus;/* indicates whether next page is
7171
* available for scan. see above for
7272
* possible states of parallel scan. */
73+
uint64btps_nsearches;/* tracked for IndexScanDescData.nsearches */
7374
slock_tbtps_mutex;/* protects above variables, btps_arrElems */
7475
ConditionVariablebtps_cv;/* used to synchronize parallel scan */
7576

@@ -557,6 +558,7 @@ btinitparallelscan(void *target)
557558
bt_target->btps_nextScanPage=InvalidBlockNumber;
558559
bt_target->btps_lastCurrPage=InvalidBlockNumber;
559560
bt_target->btps_pageStatus=BTPARALLEL_NOT_INITIALIZED;
561+
bt_target->btps_nsearches=0;
560562
ConditionVariableInit(&bt_target->btps_cv);
561563
}
562564

@@ -583,6 +585,7 @@ btparallelrescan(IndexScanDesc scan)
583585
btscan->btps_nextScanPage=InvalidBlockNumber;
584586
btscan->btps_lastCurrPage=InvalidBlockNumber;
585587
btscan->btps_pageStatus=BTPARALLEL_NOT_INITIALIZED;
588+
/* deliberately don't reset btps_nsearches (matches index_rescan) */
586589
SpinLockRelease(&btscan->btps_mutex);
587590
}
588591

@@ -676,6 +679,7 @@ _bt_parallel_seize(IndexScanDesc scan, BlockNumber *next_scan_page,
676679
{
677680
/* Can start scheduled primitive scan right away, so do so */
678681
btscan->btps_pageStatus=BTPARALLEL_ADVANCING;
682+
btscan->btps_nsearches++;
679683
for (inti=0;i<so->numArrayKeys;i++)
680684
{
681685
BTArrayKeyInfo*array=&so->arrayKeys[i];
@@ -712,6 +716,11 @@ _bt_parallel_seize(IndexScanDesc scan, BlockNumber *next_scan_page,
712716
*/
713717
btscan->btps_pageStatus=BTPARALLEL_ADVANCING;
714718
Assert(btscan->btps_nextScanPage!=P_NONE);
719+
if (btscan->btps_nextScanPage==InvalidBlockNumber)
720+
{
721+
Assert(first);
722+
btscan->btps_nsearches++;
723+
}
715724
*next_scan_page=btscan->btps_nextScanPage;
716725
*last_curr_page=btscan->btps_lastCurrPage;
717726
exit_loop= true;
@@ -810,6 +819,12 @@ _bt_parallel_done(IndexScanDesc scan)
810819
btscan->btps_pageStatus=BTPARALLEL_DONE;
811820
status_changed= true;
812821
}
822+
823+
/*
824+
* Don't use local nsearches counter -- overwrite it with the nsearches
825+
* counter that we've been maintaining in shared memory
826+
*/
827+
scan->nsearches=btscan->btps_nsearches;
813828
SpinLockRelease(&btscan->btps_mutex);
814829

815830
/* wake up all the workers associated with this parallel scan */

‎src/backend/access/nbtree/nbtsearch.c

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -950,6 +950,7 @@ _bt_first(IndexScanDesc scan, ScanDirection dir)
950950
* _bt_search/_bt_endpoint below
951951
*/
952952
pgstat_count_index_scan(rel);
953+
scan->nsearches++;
953954

954955
/*----------
955956
* Examine the scan keys to discover where we need to start the scan.

‎src/backend/access/spgist/spgscan.c

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -421,6 +421,7 @@ spgrescan(IndexScanDesc scan, ScanKey scankey, int nscankeys,
421421

422422
/* count an indexscan for stats */
423423
pgstat_count_index_scan(scan->indexRelation);
424+
scan->nsearches++;
424425
}
425426

426427
void

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp