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

Commit89fa551

Browse files
committed
EXPLAIN ANALYZE feature to measure and show actual runtimes and tuple
counts alongside the planner's estimates. By Martijn van Oosterhout,with some further work by Tom Lane.
1 parent27d2890 commit89fa551

File tree

18 files changed

+413
-87
lines changed

18 files changed

+413
-87
lines changed

‎doc/src/sgml/perform.sgml‎

Lines changed: 63 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
<!--
2-
$Header: /cvsroot/pgsql/doc/src/sgml/perform.sgml,v 1.9 2001/09/13 15:55:23 petere Exp $
2+
$Header: /cvsroot/pgsql/doc/src/sgml/perform.sgml,v 1.10 2001/09/18 01:59:05 tgl Exp $
33
-->
44

55
<chapter id="performance-tips">
@@ -122,7 +122,7 @@ select * from pg_class where relname = 'tenk1';
122122
regression=# explain select * from tenk1 where unique1 &lt; 1000;
123123
NOTICE: QUERY PLAN:
124124

125-
Seq Scan on tenk1 (cost=0.00..358.00 rows=1003 width=148)
125+
Seq Scan on tenk1 (cost=0.00..358.00 rows=1007 width=148)
126126
</programlisting>
127127

128128
The estimate of output rows has gone down because of the WHERE clause.
@@ -147,7 +147,7 @@ Seq Scan on tenk1 (cost=0.00..358.00 rows=1003 width=148)
147147
regression=# explain select * from tenk1 where unique1 &lt; 50;
148148
NOTICE: QUERY PLAN:
149149

150-
Index Scan using tenk1_unique1 on tenk1 (cost=0.00..173.32 rows=47 width=148)
150+
Index Scan using tenk1_unique1 on tenk1 (cost=0.00..181.09 rows=49 width=148)
151151
</programlisting>
152152

153153
and you will see that if we make the WHERE condition selective
@@ -166,7 +166,7 @@ regression=# explain select * from tenk1 where unique1 &lt; 50 and
166166
regression-# stringu1 = 'xxx';
167167
NOTICE: QUERY PLAN:
168168

169-
Index Scan using tenk1_unique1 on tenk1 (cost=0.00..173.44 rows=1 width=148)
169+
Index Scan using tenk1_unique1 on tenk1 (cost=0.00..181.22 rows=1 width=148)
170170
</programlisting>
171171

172172
The added clause <literal>stringu1 = 'xxx'</literal> reduces the output-rows estimate,
@@ -181,11 +181,11 @@ regression=# explain select * from tenk1 t1, tenk2 t2 where t1.unique1 &lt; 50
181181
regression-# and t1.unique2 = t2.unique2;
182182
NOTICE: QUERY PLAN:
183183

184-
Nested Loop (cost=0.00..269.11 rows=47 width=296)
184+
Nested Loop (cost=0.00..330.41 rows=49 width=296)
185185
-&gt; Index Scan using tenk1_unique1 on tenk1 t1
186-
(cost=0.00..173.32 rows=47 width=148)
186+
(cost=0.00..181.09 rows=49 width=148)
187187
-&gt; Index Scan using tenk2_unique2 on tenk2 t2
188-
(cost=0.00..2.01 rows=1 width=148)
188+
(cost=0.00..3.01 rows=1 width=148)
189189
</programlisting>
190190
</para>
191191

@@ -202,7 +202,7 @@ Nested Loop (cost=0.00..269.11 rows=47 width=296)
202202
same inner-scan plan and costs that we'd get from, say, <literal>explain select
203203
* from tenk2 where unique2 = 42</literal>. The costs of the loop node are then set
204204
on the basis of the cost of the outer scan, plus one repetition of the
205-
inner scan for each outer tuple (47 *2.01, here), plus a little CPU
205+
inner scan for each outer tuple (49 *3.01, here), plus a little CPU
206206
time for join processing.
207207
</para>
208208

@@ -229,12 +229,12 @@ regression=# explain select * from tenk1 t1, tenk2 t2 where t1.unique1 &lt; 50
229229
regression-# and t1.unique2 = t2.unique2;
230230
NOTICE: QUERY PLAN:
231231

232-
Hash Join (cost=173.44..557.03 rows=47 width=296)
232+
Hash Join (cost=181.22..564.83 rows=49 width=296)
233233
-&gt; Seq Scan on tenk2 t2
234234
(cost=0.00..333.00 rows=10000 width=148)
235-
-&gt; Hash (cost=173.32..173.32 rows=47 width=148)
235+
-&gt; Hash (cost=181.09..181.09 rows=49 width=148)
236236
-&gt; Index Scan using tenk1_unique1 on tenk1 t1
237-
(cost=0.00..173.32 rows=47 width=148)
237+
(cost=0.00..181.09 rows=49 width=148)
238238
</programlisting>
239239

240240
This plan proposes to extract the 50 interesting rows of <classname>tenk1</classname>
@@ -245,10 +245,61 @@ Hash Join (cost=173.44..557.03 rows=47 width=296)
245245
cost for the hash join, since we won't get any tuples out until we can
246246
start reading <classname>tenk2</classname>. The total time estimate for the join also
247247
includes a hefty charge for CPU time to probe the hash table
248-
10000 times. Note, however, that we are NOT charging 10000 times173.32;
248+
10000 times. Note, however, that we are NOT charging 10000 times181.09;
249249
the hash table setup is only done once in this plan type.
250250
</para>
251251

252+
<para>
253+
It is possible to check on the accuracy of the planner's estimated costs
254+
by using EXPLAIN ANALYZE. This command actually executes the query,
255+
and then displays the true runtime accumulated within each plan node
256+
along with the same estimated costs that a plain EXPLAIN shows.
257+
For example, we might get a result like this:
258+
259+
<programlisting>
260+
regression=# explain analyze select * from tenk1 t1, tenk2 t2 where t1.unique1 &lt; 50
261+
regression-# and t1.unique2 = t2.unique2;
262+
NOTICE: QUERY PLAN:
263+
264+
Nested Loop (cost=0.00..330.41 rows=49 width=296) (actual time=1.31..28.90 rows=50 loops=1)
265+
-&gt; Index Scan using tenk1_unique1 on tenk1 t1
266+
(cost=0.00..181.09 rows=49 width=148) (actual time=0.69..8.84 rows=50 loops=1)
267+
-&gt; Index Scan using tenk2_unique2 on tenk2 t2
268+
(cost=0.00..3.01 rows=1 width=148) (actual time=0.28..0.31 rows=1 loops=50)
269+
Total runtime: 30.67 msec
270+
</programlisting>
271+
272+
Note that the <quote>actual time</quote> values are in milliseconds of
273+
real time, whereas the <quote>cost</quote> estimates are expressed in
274+
arbitrary units of disk fetches; so they are unlikely to match up.
275+
The thing to pay attention to is the ratios.
276+
</para>
277+
278+
<para>
279+
In some query plans, it is possible for a subplan node to be executed more
280+
than once. For example, the inner indexscan is executed once per outer
281+
tuple in the above nested-loop plan. In such cases, the
282+
<quote>loops</quote> value reports the
283+
total number of executions of the node, and the actual time and rows
284+
values shown are averages per-execution. This is done to make the numbers
285+
comparable with the way that the cost estimates are shown. Multiply by
286+
the <quote>loops</quote> value to get the total time actually spent in
287+
the node.
288+
</para>
289+
290+
<para>
291+
The <quote>total runtime</quote> shown by EXPLAIN ANALYZE includes
292+
executor startup and shutdown time, as well as time spent processing
293+
the result tuples. It does not include parsing, rewriting, or planning
294+
time. For a SELECT query, the total runtime will normally be just a
295+
little larger than the total time reported for the top-level plan node.
296+
For INSERT, UPDATE, and DELETE queries, the total runtime may be
297+
considerably larger, because it includes the time spent processing the
298+
output tuples. In these queries, the time for the top plan node
299+
essentially is the time spent computing the new tuples and/or locating
300+
the old ones, but it doesn't include the time spent making the changes.
301+
</para>
302+
252303
<para>
253304
It is worth noting that EXPLAIN results should not be extrapolated
254305
to situations other than the one you are actually testing; for example,

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

Lines changed: 37 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
<!--
2-
$Header: /cvsroot/pgsql/doc/src/sgml/ref/explain.sgml,v 1.12 2001/09/03 12:57:50 petere Exp $
2+
$Header: /cvsroot/pgsql/doc/src/sgml/ref/explain.sgml,v 1.13 2001/09/18 01:59:05 tgl Exp $
33
Postgres documentation
44
-->
55

@@ -24,7 +24,7 @@ Postgres documentation
2424
<date>1999-07-20</date>
2525
</refsynopsisdivinfo>
2626
<synopsis>
27-
EXPLAIN [ VERBOSE ] <replaceable class="PARAMETER">query</replaceable>
27+
EXPLAIN [ANALYZE ] [VERBOSE ] <replaceable class="PARAMETER">query</replaceable>
2828
</synopsis>
2929

3030
<refsect2 id="R2-SQL-EXPLAIN-1">
@@ -37,6 +37,14 @@ EXPLAIN [ VERBOSE ] <replaceable class="PARAMETER">query</replaceable>
3737
<para>
3838

3939
<variablelist>
40+
<varlistentry>
41+
<term>ANALYZE</term>
42+
<listitem>
43+
<para>
44+
Flag to carry out the query and show actual runtimes.
45+
</para>
46+
</listitem>
47+
</varlistentry>
4048
<varlistentry>
4149
<term>VERBOSE</term>
4250
<listitem>
@@ -124,12 +132,37 @@ EXPLAIN
124132
costs to estimate which plan is really the cheapest.
125133
</para>
126134

135+
<para>
136+
The ANALYZE option causes the query to be actually executed, not only
137+
planned. The total elapsed time expended within each plan node (in
138+
milliseconds) and total number of rows it actually returned are added to
139+
the display. This is useful for seeing whether the planner's estimates
140+
are close to reality.
141+
</para>
142+
127143
<para>
128144
The VERBOSE option emits the full internal representation of the plan tree,
129145
rather than just a summary (and sends it to the postmaster log file, too).
130146
Usually this option is only useful for debugging Postgres.
131147
</para>
132148

149+
<caution>
150+
<para>
151+
Keep in mind that the query is actually executed when ANALYZE is used.
152+
Although <command>EXPLAIN</command> will discard any output that a SELECT
153+
would return,
154+
other side-effects of the query will happen as usual.
155+
If you wish to use <command>EXPLAIN ANALYZE</command> on an INSERT,
156+
UPDATE, or DELETE query without letting the query affect your data,
157+
use this approach:
158+
<programlisting>
159+
BEGIN;
160+
EXPLAIN ANALYZE ...;
161+
ROLLBACK;
162+
</programlisting>
163+
</para>
164+
</caution>
165+
133166
<refsect2 id="R2-SQL-EXPLAIN-3">
134167
<refsect2info>
135168
<date>1998-04-15</date>
@@ -140,11 +173,8 @@ EXPLAIN
140173
<para>
141174
There is only sparse documentation on the optimizer's use of cost
142175
information in <productname>Postgres</productname>.
143-
General information on cost estimation for query optimization
144-
can be found in database textbooks.
145-
Refer to the <citetitle>Programmer's Guide</citetitle>
146-
in the chapters on indexes and the genetic query optimizer for
147-
more information.
176+
Refer to the <citetitle>User's Guide</citetitle> and
177+
<citetitle>Programmer's Guide</citetitle> for more information.
148178
</para>
149179
</refsect2>
150180
</refsect1>

‎src/backend/commands/explain.c‎

Lines changed: 63 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -5,18 +5,20 @@
55
* Portions Copyright (c) 1996-2001, PostgreSQL Global Development Group
66
* Portions Copyright (c) 1994-5, Regents of the University of California
77
*
8-
* $Header: /cvsroot/pgsql/src/backend/commands/explain.c,v 1.65 2001/03/22 03:59:22 momjian Exp $
8+
* $Header: /cvsroot/pgsql/src/backend/commands/explain.c,v 1.66 2001/09/18 01:59:06 tgl Exp $
99
*
1010
*/
1111

1212
#include"postgres.h"
1313

1414
#include"commands/explain.h"
15+
#include"executor/instrument.h"
1516
#include"lib/stringinfo.h"
1617
#include"nodes/print.h"
1718
#include"optimizer/planner.h"
1819
#include"parser/parsetree.h"
1920
#include"rewrite/rewriteHandler.h"
21+
#include"tcop/pquery.h"
2022
#include"utils/relcache.h"
2123

2224
typedefstructExplainState
@@ -28,8 +30,8 @@ typedef struct ExplainState
2830
List*rtable;/* range table */
2931
}ExplainState;
3032

31-
staticchar*Explain_PlanToString(Plan*plan,ExplainState*es);
32-
staticvoidExplainOneQuery(Query*query,boolverbose,CommandDestdest);
33+
staticStringInfoExplain_PlanToString(Plan*plan,ExplainState*es);
34+
staticvoidExplainOneQuery(Query*query,boolverbose,boolanalyze,CommandDestdest);
3335

3436
/* Convert a null string pointer into "<>" */
3537
#definestringStringInfo(s) (((s) == NULL) ? "<>" : (s))
@@ -41,7 +43,7 @@ static void ExplainOneQuery(Query *query, bool verbose, CommandDest dest);
4143
*
4244
*/
4345
void
44-
ExplainQuery(Query*query,boolverbose,CommandDestdest)
46+
ExplainQuery(Query*query,boolverbose,boolanalyze,CommandDestdest)
4547
{
4648
List*rewritten;
4749
List*l;
@@ -73,7 +75,7 @@ ExplainQuery(Query *query, bool verbose, CommandDest dest)
7375

7476
/* Explain every plan */
7577
foreach(l,rewritten)
76-
ExplainOneQuery(lfirst(l),verbose,dest);
78+
ExplainOneQuery(lfirst(l),verbose,analyze,dest);
7779
}
7880

7981
/*
@@ -82,11 +84,11 @@ ExplainQuery(Query *query, bool verbose, CommandDest dest)
8284
*
8385
*/
8486
staticvoid
85-
ExplainOneQuery(Query*query,boolverbose,CommandDestdest)
87+
ExplainOneQuery(Query*query,boolverbose,boolanalyze,CommandDestdest)
8688
{
87-
char*s;
8889
Plan*plan;
8990
ExplainState*es;
91+
doubletotaltime=0;
9092

9193
/* planner will not cope with utility statements */
9294
if (query->commandType==CMD_UTILITY)
@@ -105,6 +107,34 @@ ExplainOneQuery(Query *query, bool verbose, CommandDest dest)
105107
if (plan==NULL)
106108
return;
107109

110+
/* Execute the plan for statistics if asked for */
111+
if (analyze)
112+
{
113+
structtimevalstarttime;
114+
structtimevalendtime;
115+
116+
/*
117+
* Set up the instrumentation for the top node.
118+
* This will cascade during plan initialisation
119+
*/
120+
plan->instrument=InstrAlloc();
121+
122+
gettimeofday(&starttime,NULL);
123+
ProcessQuery(query,plan,None);
124+
CommandCounterIncrement();
125+
gettimeofday(&endtime,NULL);
126+
127+
endtime.tv_sec-=starttime.tv_sec;
128+
endtime.tv_usec-=starttime.tv_usec;
129+
while (endtime.tv_usec<0)
130+
{
131+
endtime.tv_usec+=1000000;
132+
endtime.tv_sec--;
133+
}
134+
totaltime= (double)endtime.tv_sec+
135+
(double)endtime.tv_usec /1000000.0;
136+
}
137+
108138
es= (ExplainState*)palloc(sizeof(ExplainState));
109139
MemSet(es,0,sizeof(ExplainState));
110140

@@ -117,6 +147,8 @@ ExplainOneQuery(Query *query, bool verbose, CommandDest dest)
117147

118148
if (es->printNodes)
119149
{
150+
char*s;
151+
120152
s=nodeToString(plan);
121153
if (s)
122154
{
@@ -127,12 +159,15 @@ ExplainOneQuery(Query *query, bool verbose, CommandDest dest)
127159

128160
if (es->printCost)
129161
{
130-
s=Explain_PlanToString(plan,es);
131-
if (s)
132-
{
133-
elog(NOTICE,"QUERY PLAN:\n\n%s",s);
134-
pfree(s);
135-
}
162+
StringInfostr;
163+
164+
str=Explain_PlanToString(plan,es);
165+
if (analyze)
166+
appendStringInfo(str,"Total runtime: %.2f msec\n",
167+
1000.0*totaltime);
168+
elog(NOTICE,"QUERY PLAN:\n\n%s",str->data);
169+
pfree(str->data);
170+
pfree(str);
136171
}
137172

138173
if (es->printNodes)
@@ -292,6 +327,17 @@ explain_outNode(StringInfo str, Plan *plan, int indent, ExplainState *es)
292327
appendStringInfo(str," (cost=%.2f..%.2f rows=%.0f width=%d)",
293328
plan->startup_cost,plan->total_cost,
294329
plan->plan_rows,plan->plan_width);
330+
331+
if (plan->instrument&&plan->instrument->nloops>0 )
332+
{
333+
doublenloops=plan->instrument->nloops;
334+
335+
appendStringInfo(str," (actual time=%.2f..%.2f rows=%.0f loops=%.0f)",
336+
1000.0*plan->instrument->startup /nloops,
337+
1000.0*plan->instrument->total /nloops,
338+
plan->instrument->ntuples /nloops,
339+
plan->instrument->nloops);
340+
}
295341
}
296342
appendStringInfo(str,"\n");
297343

@@ -393,14 +439,12 @@ explain_outNode(StringInfo str, Plan *plan, int indent, ExplainState *es)
393439
}
394440
}
395441

396-
staticchar*
442+
staticStringInfo
397443
Explain_PlanToString(Plan*plan,ExplainState*es)
398444
{
399-
StringInfoDatastr;
445+
StringInfostr=makeStringInfo();
400446

401-
/* see stringinfo.h for an explanation of this maneuver */
402-
initStringInfo(&str);
403447
if (plan!=NULL)
404-
explain_outNode(&str,plan,0,es);
405-
returnstr.data;
448+
explain_outNode(str,plan,0,es);
449+
returnstr;
406450
}

0 commit comments

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