From 10d3995057b2ea89e56adb571c1beb2b972d1c6f Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Sun, 24 Mar 2002 04:31:09 +0000 Subject: 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 actually go through elog(), not directly to stdout. --- doc/src/sgml/perform.sgml | 103 ++++++++++++++++++++++++------------------ doc/src/sgml/ref/explain.sgml | 86 +++++++++++++++++------------------ doc/src/sgml/release.sgml | 3 +- doc/src/sgml/runtime.sgml | 12 ++++- 4 files changed, 114 insertions(+), 90 deletions(-) (limited to 'doc/src') diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml index 94f49921f7e..6b13d6ae3af 100644 --- a/doc/src/sgml/perform.sgml +++ b/doc/src/sgml/perform.sgml @@ -1,5 +1,5 @@ @@ -47,8 +47,8 @@ $Header: /cvsroot/pgsql/doc/src/sgml/perform.sgml,v 1.18 2002/03/22 19:20:17 pet - Estimated number of rows output by this plan node (again, without - regard for any LIMIT). + Estimated number of rows output by this plan node (again, only if + executed to completion). @@ -92,13 +92,13 @@ $Header: /cvsroot/pgsql/doc/src/sgml/perform.sgml,v 1.18 2002/03/22 19:20:17 pet Here are some examples (using the regress test database after a - vacuum analyze, and 7.2 development sources): + vacuum analyze, and 7.3 development sources): regression=# EXPLAIN SELECT * FROM tenk1; -INFO: QUERY PLAN: - -Seq Scan on tenk1 (cost=0.00..333.00 rows=10000 width=148) + QUERY PLAN +------------------------------------------------------------- + Seq Scan on tenk1 (cost=0.00..333.00 rows=10000 width=148) @@ -120,9 +120,10 @@ SELECT * FROM pg_class WHERE relname = 'tenk1'; regression=# EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 1000; -INFO: QUERY PLAN: - -Seq Scan on tenk1 (cost=0.00..358.00 rows=1007 width=148) + QUERY PLAN +------------------------------------------------------------ + Seq Scan on tenk1 (cost=0.00..358.00 rows=1033 width=148) + Filter: (unique1 < 1000) 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) regression=# EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 50; -INFO: QUERY PLAN: - -Index Scan using tenk1_unique1 on tenk1 (cost=0.00..181.09 rows=49 width=148) + QUERY PLAN +------------------------------------------------------------------------------- + Index Scan using tenk1_unique1 on tenk1 (cost=0.00..179.33 rows=49 width=148) + Index Filter: (unique1 < 50) 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) regression=# EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 50 AND regression-# stringu1 = 'xxx'; -INFO: QUERY PLAN: - -Index Scan using tenk1_unique1 on tenk1 (cost=0.00..181.22 rows=1 width=148) + QUERY PLAN +------------------------------------------------------------------------------- + Index Scan using tenk1_unique1 on tenk1 (cost=0.00..179.45 rows=1 width=148) + Index Filter: (unique1 < 50) + Filter: (stringu1 = 'xxx'::name) - The added clause stringu1 = 'xxx' reduces the output-rows estimate, - but not the cost because we still have to visit the same set of tuples. + The added clause stringu1 = 'xxx' reduces the + output-rows estimate, but not the cost because we still have to visit the + same set of tuples. Notice that the stringu1 clause + cannot be applied as an index condition (since this index is only on + the unique1 column). Instead it is applied as a filter on + the rows retrieved by the index. Thus the cost has actually gone up + a little bit to reflect this extra checking. @@ -179,13 +188,15 @@ Index Scan using tenk1_unique1 on tenk1 (cost=0.00..181.22 rows=1 width=148) regression=# EXPLAIN SELECT * FROM tenk1 t1, tenk2 t2 WHERE t1.unique1 < 50 regression-# AND t1.unique2 = t2.unique2; -INFO: QUERY PLAN: - -Nested Loop (cost=0.00..330.41 rows=49 width=296) - -> Index Scan using tenk1_unique1 on tenk1 t1 - (cost=0.00..181.09 rows=49 width=148) - -> Index Scan using tenk2_unique2 on tenk2 t2 - (cost=0.00..3.01 rows=1 width=148) + QUERY PLAN +---------------------------------------------------------------------------- + Nested Loop (cost=0.00..327.02 rows=49 width=296) + -> Index Scan using tenk1_unique1 on tenk1 t1 + (cost=0.00..179.33 rows=49 width=148) + Index Filter: (unique1 < 50) + -> Index Scan using tenk2_unique2 on tenk2 t2 + (cost=0.00..3.01 rows=1 width=148) + Index Filter: ("outer".unique2 = t2.unique2) @@ -227,14 +238,15 @@ regression=# set enable_nestloop = off; SET VARIABLE regression=# EXPLAIN SELECT * FROM tenk1 t1, tenk2 t2 WHERE t1.unique1 < 50 regression-# AND t1.unique2 = t2.unique2; -INFO: QUERY PLAN: - -Hash Join (cost=181.22..564.83 rows=49 width=296) - -> Seq Scan on tenk2 t2 - (cost=0.00..333.00 rows=10000 width=148) - -> Hash (cost=181.09..181.09 rows=49 width=148) - -> Index Scan using tenk1_unique1 on tenk1 t1 - (cost=0.00..181.09 rows=49 width=148) + QUERY PLAN +-------------------------------------------------------------------------- + Hash Join (cost=179.45..563.06 rows=49 width=296) + Hash Cond: ("outer".unique2 = "inner".unique2) + -> Seq Scan on tenk2 t2 (cost=0.00..333.00 rows=10000 width=148) + -> Hash (cost=179.33..179.33 rows=49 width=148) + -> Index Scan using tenk1_unique1 on tenk1 t1 + (cost=0.00..179.33 rows=49 width=148) + Index Filter: (unique1 < 50) This plan proposes to extract the 50 interesting rows of tenk1 @@ -245,7 +257,7 @@ Hash Join (cost=181.22..564.83 rows=49 width=296) cost for the hash join, since we won't get any tuples out until we can start reading tenk2. The total time estimate for the join also includes a hefty charge for CPU time to probe the hash table - 10000 times. Note, however, that we are NOT charging 10000 times 181.09; + 10000 times. Note, however, that we are NOT charging 10000 times 179.33; the hash table setup is only done once in this plan type. @@ -260,14 +272,19 @@ Hash Join (cost=181.22..564.83 rows=49 width=296) regression=# EXPLAIN ANALYZE regression-# SELECT * FROM tenk1 t1, tenk2 t2 regression-# WHERE t1.unique1 < 50 AND t1.unique2 = t2.unique2; -INFO: QUERY PLAN: - -Nested Loop (cost=0.00..330.41 rows=49 width=296) (actual time=1.31..28.90 rows=50 loops=1) - -> Index Scan using tenk1_unique1 on tenk1 t1 - (cost=0.00..181.09 rows=49 width=148) (actual time=0.69..8.84 rows=50 loops=1) - -> Index Scan using tenk2_unique2 on tenk2 t2 - (cost=0.00..3.01 rows=1 width=148) (actual time=0.28..0.31 rows=1 loops=50) -Total runtime: 30.67 msec + QUERY PLAN +------------------------------------------------------------------------------- + Nested Loop (cost=0.00..327.02 rows=49 width=296) + (actual time=1.18..29.82 rows=50 loops=1) + -> Index Scan using tenk1_unique1 on tenk1 t1 + (cost=0.00..179.33 rows=49 width=148) + (actual time=0.63..8.91 rows=50 loops=1) + Index Filter: (unique1 < 50) + -> Index Scan using tenk2_unique2 on tenk2 t2 + (cost=0.00..3.01 rows=1 width=148) + (actual time=0.29..0.32 rows=1 loops=50) + Index Filter: ("outer".unique2 = t2.unique2) + Total runtime: 31.60 msec Note that the actual time values are in milliseconds of @@ -296,7 +313,7 @@ Total runtime: 30.67 msec little larger than the total time reported for the top-level plan node. For INSERT, UPDATE, and DELETE queries, the total run time may be considerably larger, because it includes the time spent processing the - output tuples. In these queries, the time for the top plan node + result tuples. In these queries, the time for the top plan node essentially is the time spent computing the new tuples and/or locating the old ones, but it doesn't include the time spent making the changes. diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index 33c9add4531..28172aac5b7 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -1,5 +1,5 @@ @@ -49,7 +49,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] queryVERBOSE - Flag to show detailed query plan. + Flag to show detailed query plan dump. @@ -76,28 +76,24 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] query - -INFO: QUERY PLAN: -plan - + Query plan - Explicit query plan from the PostgreSQL backend. - - - - - -EXPLAIN - - - - Flag sent after query plan is shown. + Explicit query plan from the PostgreSQL + planner. + + + + Prior to PostgreSQL 7.3, the query plan + was emitted in the form of a NOTICE message. Now it appears as a + query result (formatted like a table with a single text column). + + @@ -141,13 +137,6 @@ EXPLAIN are close to reality. - - The VERBOSE option emits the full internal representation of the plan tree, - rather than just a summary (and sends it to the postmaster log file, too). - Usually this option is only useful for debugging - PostgreSQL. - - Keep in mind that the query is actually executed when ANALYZE is used. @@ -165,6 +154,15 @@ ROLLBACK; + + The VERBOSE option emits the full internal representation of the plan tree, + rather than just a summary. + Usually this option is only useful for debugging + PostgreSQL. The VERBOSE dump is either + pretty-printed or not, depending on the setting of the + configuration parameter. + + 1998-04-15 @@ -188,50 +186,48 @@ ROLLBACK; To show a query plan for a simple query on a table with a single - int4 column and 128 rows: + int4 column and 10000 rows: EXPLAIN SELECT * FROM foo; -INFO: QUERY PLAN: - -Seq Scan on foo (cost=0.00..2.28 rows=128 width=4) - -EXPLAIN + QUERY PLAN +--------------------------------------------------------- + Seq Scan on foo (cost=0.00..155.00 rows=10000 width=4) +(1 row) - For the same table with an index to support an - equijoin condition on the query, + If there is an index and we use a query with an indexable WHERE condition, EXPLAIN will show a different plan: EXPLAIN SELECT * FROM foo WHERE i = 4; -INFO: QUERY PLAN: - -Index Scan using fi on foo (cost=0.00..0.42 rows=1 width=4) - -EXPLAIN + QUERY PLAN +-------------------------------------------------------------- + Index Scan using fi on foo (cost=0.00..5.98 rows=1 width=4) + Index Filter: (i = 4) +(2 rows) - And finally, for the same table with an index to support an - equijoin condition on the query, - EXPLAIN will show the following for a query + And here is an example of a query plan for a query using an aggregate function: -EXPLAIN SELECT sum(i) FROM foo WHERE i = 4; +EXPLAIN SELECT sum(i) FROM foo WHERE i < 4; -INFO: QUERY PLAN: - -Aggregate (cost=0.42..0.42 rows=1 width=4) - -> Index Scan using fi on foo (cost=0.00..0.42 rows=1 width=4) + QUERY PLAN +--------------------------------------------------------------------- + Aggregate (cost=23.93..23.93 rows=1 width=4) + -> Index Scan using fi on foo (cost=0.00..23.92 rows=6 width=4) + Index Filter: (i < 10) +(3 rows) diff --git a/doc/src/sgml/release.sgml b/doc/src/sgml/release.sgml index 4900f1b7482..f0af67599db 100644 --- a/doc/src/sgml/release.sgml +++ b/doc/src/sgml/release.sgml @@ -1,5 +1,5 @@ @@ -24,6 +24,7 @@ CDATA means the content is "SGML-free", so you can write without worries about funny characters. --> @@ -870,6 +870,16 @@ env PGOPTIONS='-c geqo=off' psql + + EXPLAIN_PRETTY_PRINT (boolean) + + + Determines whether EXPLAIN VERBOSE uses the indented + or non-indented format for displaying detailed querytree dumps. + + + + HOSTNAME_LOOKUP (boolean) -- cgit v1.2.3