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

Commit10d3995

Browse files
committed
EXPLAIN output now comes out as a query result, not a NOTICE message.
Also, fix debug logging of parse/plan trees so that the messages actuallygo through elog(), not directly to stdout.
1 parenta25b94c commit10d3995

File tree

14 files changed

+410
-211
lines changed

14 files changed

+410
-211
lines changed

‎doc/src/sgml/perform.sgml

Lines changed: 60 additions & 43 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.18 2002/03/22 19:20:17 petere Exp $
2+
$Header: /cvsroot/pgsql/doc/src/sgml/perform.sgml,v 1.19 2002/03/24 04:31:05 tgl Exp $
33
-->
44

55
<chapter id="performance-tips">
@@ -47,8 +47,8 @@ $Header: /cvsroot/pgsql/doc/src/sgml/perform.sgml,v 1.18 2002/03/22 19:20:17 pet
4747

4848
<listitem>
4949
<para>
50-
Estimated number of rows output by this plan node (again,without
51-
regard for any LIMIT).
50+
Estimated number of rows output by this plan node (again,only if
51+
executed to completion).
5252
</para>
5353
</listitem>
5454

@@ -92,13 +92,13 @@ $Header: /cvsroot/pgsql/doc/src/sgml/perform.sgml,v 1.18 2002/03/22 19:20:17 pet
9292

9393
<para>
9494
Here are some examples (using the regress test database after a
95-
vacuum analyze, and 7.2 development sources):
95+
vacuum analyze, and 7.3 development sources):
9696

9797
<programlisting>
9898
regression=# EXPLAIN SELECT * FROM tenk1;
99-
INFO:QUERY PLAN:
100-
101-
Seq Scan on tenk1 (cost=0.00..333.00 rows=10000 width=148)
99+
QUERY PLAN
100+
-------------------------------------------------------------
101+
Seq Scan on tenk1 (cost=0.00..333.00 rows=10000 width=148)
102102
</programlisting>
103103
</para>
104104

@@ -120,9 +120,10 @@ SELECT * FROM pg_class WHERE relname = 'tenk1';
120120

121121
<programlisting>
122122
regression=# EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 1000;
123-
INFO: QUERY PLAN:
124-
125-
Seq Scan on tenk1 (cost=0.00..358.00 rows=1007 width=148)
123+
QUERY PLAN
124+
------------------------------------------------------------
125+
Seq Scan on tenk1 (cost=0.00..358.00 rows=1033 width=148)
126+
Filter: (unique1 &lt; 1000)
126127
</programlisting>
127128

128129
The estimate of output rows has gone down because of the WHERE clause.
@@ -145,9 +146,10 @@ Seq Scan on tenk1 (cost=0.00..358.00 rows=1007 width=148)
145146

146147
<programlisting>
147148
regression=# EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 50;
148-
INFO: QUERY PLAN:
149-
150-
Index Scan using tenk1_unique1 on tenk1 (cost=0.00..181.09 rows=49 width=148)
149+
QUERY PLAN
150+
-------------------------------------------------------------------------------
151+
Index Scan using tenk1_unique1 on tenk1 (cost=0.00..179.33 rows=49 width=148)
152+
Index Filter: (unique1 &lt; 50)
151153
</programlisting>
152154

153155
and you will see that if we make the WHERE condition selective
@@ -164,13 +166,20 @@ Index Scan using tenk1_unique1 on tenk1 (cost=0.00..181.09 rows=49 width=148)
164166
<programlisting>
165167
regression=# EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 50 AND
166168
regression-# stringu1 = 'xxx';
167-
INFO: QUERY PLAN:
168-
169-
Index Scan using tenk1_unique1 on tenk1 (cost=0.00..181.22 rows=1 width=148)
169+
QUERY PLAN
170+
-------------------------------------------------------------------------------
171+
Index Scan using tenk1_unique1 on tenk1 (cost=0.00..179.45 rows=1 width=148)
172+
Index Filter: (unique1 &lt; 50)
173+
Filter: (stringu1 = 'xxx'::name)
170174
</programlisting>
171175

172-
The added clause <literal>stringu1 = 'xxx'</literal> reduces the output-rows estimate,
173-
but not the cost because we still have to visit the same set of tuples.
176+
The added clause <literal>stringu1 = 'xxx'</literal> reduces the
177+
output-rows estimate, but not the cost because we still have to visit the
178+
same set of tuples. Notice that the <literal>stringu1</> clause
179+
cannot be applied as an index condition (since this index is only on
180+
the <literal>unique1</> column). Instead it is applied as a filter on
181+
the rows retrieved by the index. Thus the cost has actually gone up
182+
a little bit to reflect this extra checking.
174183
</para>
175184

176185
<para>
@@ -179,13 +188,15 @@ Index Scan using tenk1_unique1 on tenk1 (cost=0.00..181.22 rows=1 width=148)
179188
<programlisting>
180189
regression=# EXPLAIN SELECT * FROM tenk1 t1, tenk2 t2 WHERE t1.unique1 &lt; 50
181190
regression-# AND t1.unique2 = t2.unique2;
182-
INFO: QUERY PLAN:
183-
184-
Nested Loop (cost=0.00..330.41 rows=49 width=296)
185-
-&gt; Index Scan using tenk1_unique1 on tenk1 t1
186-
(cost=0.00..181.09 rows=49 width=148)
187-
-&gt; Index Scan using tenk2_unique2 on tenk2 t2
188-
(cost=0.00..3.01 rows=1 width=148)
191+
QUERY PLAN
192+
----------------------------------------------------------------------------
193+
Nested Loop (cost=0.00..327.02 rows=49 width=296)
194+
-&gt; Index Scan using tenk1_unique1 on tenk1 t1
195+
(cost=0.00..179.33 rows=49 width=148)
196+
Index Filter: (unique1 &lt; 50)
197+
-&gt; Index Scan using tenk2_unique2 on tenk2 t2
198+
(cost=0.00..3.01 rows=1 width=148)
199+
Index Filter: ("outer".unique2 = t2.unique2)
189200
</programlisting>
190201
</para>
191202

@@ -227,14 +238,15 @@ regression=# set enable_nestloop = off;
227238
SET VARIABLE
228239
regression=# EXPLAIN SELECT * FROM tenk1 t1, tenk2 t2 WHERE t1.unique1 &lt; 50
229240
regression-# AND t1.unique2 = t2.unique2;
230-
INFO: QUERY PLAN:
231-
232-
Hash Join (cost=181.22..564.83 rows=49 width=296)
233-
-&gt; Seq Scan on tenk2 t2
234-
(cost=0.00..333.00 rows=10000 width=148)
235-
-&gt; Hash (cost=181.09..181.09 rows=49 width=148)
236-
-&gt; Index Scan using tenk1_unique1 on tenk1 t1
237-
(cost=0.00..181.09 rows=49 width=148)
241+
QUERY PLAN
242+
--------------------------------------------------------------------------
243+
Hash Join (cost=179.45..563.06 rows=49 width=296)
244+
Hash Cond: ("outer".unique2 = "inner".unique2)
245+
-&gt; Seq Scan on tenk2 t2 (cost=0.00..333.00 rows=10000 width=148)
246+
-&gt; Hash (cost=179.33..179.33 rows=49 width=148)
247+
-&gt; Index Scan using tenk1_unique1 on tenk1 t1
248+
(cost=0.00..179.33 rows=49 width=148)
249+
Index Filter: (unique1 &lt; 50)
238250
</programlisting>
239251

240252
This plan proposes to extract the 50 interesting rows of <classname>tenk1</classname>
@@ -245,7 +257,7 @@ Hash Join (cost=181.22..564.83 rows=49 width=296)
245257
cost for the hash join, since we won't get any tuples out until we can
246258
start reading <classname>tenk2</classname>. The total time estimate for the join also
247259
includes a hefty charge for CPU time to probe the hash table
248-
10000 times. Note, however, that we are NOT charging 10000 times181.09;
260+
10000 times. Note, however, that we are NOT charging 10000 times179.33;
249261
the hash table setup is only done once in this plan type.
250262
</para>
251263

@@ -260,14 +272,19 @@ Hash Join (cost=181.22..564.83 rows=49 width=296)
260272
regression=# EXPLAIN ANALYZE
261273
regression-# SELECT * FROM tenk1 t1, tenk2 t2
262274
regression-# WHERE t1.unique1 &lt; 50 AND t1.unique2 = t2.unique2;
263-
INFO: QUERY PLAN:
264-
265-
Nested Loop (cost=0.00..330.41 rows=49 width=296) (actual time=1.31..28.90 rows=50 loops=1)
266-
-&gt; Index Scan using tenk1_unique1 on tenk1 t1
267-
(cost=0.00..181.09 rows=49 width=148) (actual time=0.69..8.84 rows=50 loops=1)
268-
-&gt; Index Scan using tenk2_unique2 on tenk2 t2
269-
(cost=0.00..3.01 rows=1 width=148) (actual time=0.28..0.31 rows=1 loops=50)
270-
Total runtime: 30.67 msec
275+
QUERY PLAN
276+
-------------------------------------------------------------------------------
277+
Nested Loop (cost=0.00..327.02 rows=49 width=296)
278+
(actual time=1.18..29.82 rows=50 loops=1)
279+
-&gt; Index Scan using tenk1_unique1 on tenk1 t1
280+
(cost=0.00..179.33 rows=49 width=148)
281+
(actual time=0.63..8.91 rows=50 loops=1)
282+
Index Filter: (unique1 &lt; 50)
283+
-&gt; Index Scan using tenk2_unique2 on tenk2 t2
284+
(cost=0.00..3.01 rows=1 width=148)
285+
(actual time=0.29..0.32 rows=1 loops=50)
286+
Index Filter: ("outer".unique2 = t2.unique2)
287+
Total runtime: 31.60 msec
271288
</screen>
272289

273290
Note that the <quote>actual time</quote> values are in milliseconds of
@@ -296,7 +313,7 @@ Total runtime: 30.67 msec
296313
little larger than the total time reported for the top-level plan node.
297314
For INSERT, UPDATE, and DELETE queries, the total run time may be
298315
considerably larger, because it includes the time spent processing the
299-
output tuples. In these queries, the time for the top plan node
316+
result tuples. In these queries, the time for the top plan node
300317
essentially is the time spent computing the new tuples and/or locating
301318
the old ones, but it doesn't include the time spent making the changes.
302319
</para>

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

Lines changed: 41 additions & 45 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.16 2002/03/22 19:20:40 petere Exp $
2+
$Header: /cvsroot/pgsql/doc/src/sgml/ref/explain.sgml,v 1.17 2002/03/24 04:31:07 tgl Exp $
33
PostgreSQL documentation
44
-->
55

@@ -49,7 +49,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="PARAMETER">query</replaceabl
4949
<term>VERBOSE</term>
5050
<listitem>
5151
<para>
52-
Flag to show detailed query plan.
52+
Flag to show detailed query plan dump.
5353
</para>
5454
</listitem>
5555
</varlistentry>
@@ -76,28 +76,24 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="PARAMETER">query</replaceabl
7676

7777
<variablelist>
7878
<varlistentry>
79-
<term><computeroutput>
80-
INFO: QUERY PLAN:
81-
<replaceable>plan</replaceable>
82-
</computeroutput></term>
79+
<term>Query plan</term>
8380
<listitem>
8481
<para>
85-
Explicit query plan from the <productname>PostgreSQL</productname> backend.
86-
</para>
87-
</listitem>
88-
</varlistentry>
89-
<varlistentry>
90-
<term><computeroutput>
91-
EXPLAIN
92-
</computeroutput></term>
93-
<listitem>
94-
<para>
95-
Flag sent after query plan is shown.
82+
Explicit query plan from the <productname>PostgreSQL</productname>
83+
planner.
9684
</para>
9785
</listitem>
9886
</varlistentry>
9987
</variablelist>
10088
</para>
89+
90+
<note>
91+
<para>
92+
Prior to <application>PostgreSQL</application> 7.3, the query plan
93+
was emitted in the form of a NOTICE message. Now it appears as a
94+
query result (formatted like a table with a single text column).
95+
</para>
96+
</note>
10197
</refsect2>
10298
</refsynopsisdiv>
10399

@@ -141,13 +137,6 @@ EXPLAIN
141137
are close to reality.
142138
</para>
143139

144-
<para>
145-
The VERBOSE option emits the full internal representation of the plan tree,
146-
rather than just a summary (and sends it to the postmaster log file, too).
147-
Usually this option is only useful for debugging
148-
<application>PostgreSQL</application>.
149-
</para>
150-
151140
<caution>
152141
<para>
153142
Keep in mind that the query is actually executed when ANALYZE is used.
@@ -165,6 +154,15 @@ ROLLBACK;
165154
</para>
166155
</caution>
167156

157+
<para>
158+
The VERBOSE option emits the full internal representation of the plan tree,
159+
rather than just a summary.
160+
Usually this option is only useful for debugging
161+
<application>PostgreSQL</application>. The VERBOSE dump is either
162+
pretty-printed or not, depending on the setting of the
163+
<option>EXPLAIN_PRETTY_PRINT</option> configuration parameter.
164+
</para>
165+
168166
<refsect2 id="R2-SQL-EXPLAIN-3">
169167
<refsect2info>
170168
<date>1998-04-15</date>
@@ -188,50 +186,48 @@ ROLLBACK;
188186

189187
<para>
190188
To show a query plan for a simple query on a table with a single
191-
<type>int4</type> column and128 rows:
189+
<type>int4</type> column and10000 rows:
192190

193191
<programlisting>
194192
EXPLAIN SELECT * FROM foo;
195193
<computeroutput>
196-
INFO: QUERY PLAN:
197-
198-
Seq Scan on foo (cost=0.00..2.28 rows=128 width=4)
199-
200-
EXPLAIN
194+
QUERY PLAN
195+
---------------------------------------------------------
196+
Seq Scan on foo (cost=0.00..155.00 rows=10000 width=4)
197+
(1 row)
201198
</computeroutput>
202199
</programlisting>
203200
</para>
204201

205202
<para>
206-
For the same table with an index to support an
207-
<firstterm>equijoin</firstterm> condition on the query,
203+
If there is an index and we use a query with an indexable WHERE condition,
208204
<command>EXPLAIN</command> will show a different plan:
209205

210206
<programlisting>
211207
EXPLAIN SELECT * FROM foo WHERE i = 4;
212208
<computeroutput>
213-
INFO:QUERY PLAN:
214-
215-
Index Scan using fi on foo (cost=0.00..0.42 rows=1 width=4)
216-
217-
EXPLAIN
209+
QUERY PLAN
210+
--------------------------------------------------------------
211+
Index Scan using fi on foo (cost=0.00..5.98 rows=1 width=4)
212+
Index Filter: (i = 4)
213+
(2 rows)
218214
</computeroutput>
219215
</programlisting>
220216
</para>
221217

222218
<para>
223-
And finally, for the same table with an index to support an
224-
<firstterm>equijoin</firstterm> condition on the query,
225-
<command>EXPLAIN</command> will show the following for a query
219+
And here is an example of a query plan for a query
226220
using an aggregate function:
227221

228222
<programlisting>
229-
EXPLAIN SELECT sum(i) FROM foo WHERE i= 4;
223+
EXPLAIN SELECT sum(i) FROM foo WHERE i< 4;
230224
<computeroutput>
231-
INFO: QUERY PLAN:
232-
233-
Aggregate (cost=0.42..0.42 rows=1 width=4)
234-
-> Index Scan using fi on foo (cost=0.00..0.42 rows=1 width=4)
225+
QUERY PLAN
226+
---------------------------------------------------------------------
227+
Aggregate (cost=23.93..23.93 rows=1 width=4)
228+
-> Index Scan using fi on foo (cost=0.00..23.92 rows=6 width=4)
229+
Index Filter: (i < 10)
230+
(3 rows)
235231
</computeroutput>
236232
</programlisting>
237233
</para>

‎doc/src/sgml/release.sgml

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
<!--
2-
$Header: /cvsroot/pgsql/doc/src/sgml/release.sgml,v 1.125 2002/03/22 19:20:22 petere Exp $
2+
$Header: /cvsroot/pgsql/doc/src/sgml/release.sgml,v 1.126 2002/03/24 04:31:05 tgl Exp $
33
-->
44

55
<appendix id="release">
@@ -24,6 +24,7 @@ CDATA means the content is "SGML-free", so you can write without
2424
worries about funny characters.
2525
-->
2626
<literallayout><![CDATA[
27+
EXPLAIN output comes out as a query result, not a NOTICE message
2728
DOMAINs (types that are constrained versions of base types)
2829
Access privileges on functions
2930
Access privileges on procedural languages

‎doc/src/sgml/runtime.sgml

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
<!--
2-
$Header: /cvsroot/pgsql/doc/src/sgml/runtime.sgml,v 1.109 2002/03/22 19:20:28 petere Exp $
2+
$Header: /cvsroot/pgsql/doc/src/sgml/runtime.sgml,v 1.110 2002/03/24 04:31:06 tgl Exp $
33
-->
44

55
<Chapter Id="runtime">
@@ -870,6 +870,16 @@ env PGOPTIONS='-c geqo=off' psql
870870
</listitem>
871871
</varlistentry>
872872

873+
<varlistentry>
874+
<term><varname>EXPLAIN_PRETTY_PRINT</varname> (<type>boolean</type>)</term>
875+
<listitem>
876+
<para>
877+
Determines whether <command>EXPLAIN VERBOSE</> uses the indented
878+
or non-indented format for displaying detailed querytree dumps.
879+
</para>
880+
</listitem>
881+
</varlistentry>
882+
873883
<varlistentry>
874884
<term><varname>HOSTNAME_LOOKUP</varname> (<type>boolean</type>)</term>
875885
<listitem>

0 commit comments

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