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.

4 files changed, 114 insertions, 90 deletions

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 @@
 <!--
-$Header: /cvsroot/pgsql/doc/src/sgml/perform.sgml,v 1.18 2002/03/22 19:20:17 petere Exp $
+$Header: /cvsroot/pgsql/doc/src/sgml/perform.sgml,v 1.19 2002/03/24 04:31:05 tgl Exp $
 -->
 
  <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
 
      <listitem>
       <para>
-       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).
       </para>
      </listitem>
 
@@ -92,13 +92,13 @@ $Header: /cvsroot/pgsql/doc/src/sgml/perform.sgml,v 1.18 2002/03/22 19:20:17 pet
 
    <para>
     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):
 
     <programlisting>
 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)
     </programlisting>
    </para>
 
@@ -120,9 +120,10 @@ SELECT * FROM pg_class WHERE relname = 'tenk1';
 
     <programlisting>
 regression=# EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 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 &lt; 1000)
     </programlisting>
 
     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)
 
     <programlisting>
 regression=# EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 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 &lt; 50)
     </programlisting>
 
     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)
     <programlisting>
 regression=# EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 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 &lt; 50)
+   Filter: (stringu1 = 'xxx'::name)
     </programlisting>
 
-    The added clause <literal>stringu1 = 'xxx'</literal> reduces the output-rows estimate,
-    but not the cost because we still have to visit the same set of tuples.
+    The added clause <literal>stringu1 = 'xxx'</literal> reduces the
+    output-rows estimate, but not the cost because we still have to visit the
+    same set of tuples.  Notice that the <literal>stringu1</> clause
+    cannot be applied as an index condition (since this index is only on
+    the <literal>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.
    </para>
 
    <para>
@@ -179,13 +188,15 @@ Index Scan using tenk1_unique1 on tenk1  (cost=0.00..181.22 rows=1 width=148)
     <programlisting>
 regression=# EXPLAIN SELECT * FROM tenk1 t1, tenk2 t2 WHERE t1.unique1 &lt; 50
 regression-# AND t1.unique2 = t2.unique2;
-INFO:  QUERY PLAN:
-
-Nested Loop  (cost=0.00..330.41 rows=49 width=296)
-  -&gt;  Index Scan using tenk1_unique1 on tenk1 t1
-               (cost=0.00..181.09 rows=49 width=148)
-  -&gt;  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)
+   -&gt;  Index Scan using tenk1_unique1 on tenk1 t1
+                                      (cost=0.00..179.33 rows=49 width=148)
+         Index Filter: (unique1 &lt; 50)
+   -&gt;  Index Scan using tenk2_unique2 on tenk2 t2
+                                      (cost=0.00..3.01 rows=1 width=148)
+         Index Filter: ("outer".unique2 = t2.unique2)
     </programlisting>
    </para>
 
@@ -227,14 +238,15 @@ regression=# set enable_nestloop = off;
 SET VARIABLE
 regression=# EXPLAIN SELECT * FROM tenk1 t1, tenk2 t2 WHERE t1.unique1 &lt; 50
 regression-# AND t1.unique2 = t2.unique2;
-INFO:  QUERY PLAN:
-
-Hash Join  (cost=181.22..564.83 rows=49 width=296)
-  -&gt;  Seq Scan on tenk2 t2
-               (cost=0.00..333.00 rows=10000 width=148)
-  -&gt;  Hash  (cost=181.09..181.09 rows=49 width=148)
-        -&gt;  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)
+   -&gt;  Seq Scan on tenk2 t2  (cost=0.00..333.00 rows=10000 width=148)
+   -&gt;  Hash  (cost=179.33..179.33 rows=49 width=148)
+         -&gt;  Index Scan using tenk1_unique1 on tenk1 t1
+                                    (cost=0.00..179.33 rows=49 width=148)
+               Index Filter: (unique1 &lt; 50)
     </programlisting>
 
     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)
     cost for the hash join, since we won't get any tuples out until we can
     start reading <classname>tenk2</classname>.  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.
    </para>
 
@@ -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 &lt; 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)
-  -&gt;  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)
-  -&gt;  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)
+   -&gt;  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 &lt; 50)
+   -&gt;  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
 </screen>
 
     Note that the <quote>actual time</quote> 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.
    </para>
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 @@
 <!--
-$Header: /cvsroot/pgsql/doc/src/sgml/ref/explain.sgml,v 1.16 2002/03/22 19:20:40 petere Exp $
+$Header: /cvsroot/pgsql/doc/src/sgml/ref/explain.sgml,v 1.17 2002/03/24 04:31:07 tgl Exp $
 PostgreSQL documentation
 -->
 
@@ -49,7 +49,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="PARAMETER">query</replaceabl
       <term>VERBOSE</term>
       <listitem>
        <para>
-	Flag to show detailed query plan.
+	Flag to show detailed query plan dump.
        </para>
       </listitem>
      </varlistentry>
@@ -76,28 +76,24 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="PARAMETER">query</replaceabl
 
     <variablelist>
      <varlistentry>
-      <term><computeroutput>
-INFO:  QUERY PLAN:
-<replaceable>plan</replaceable>
-      </computeroutput></term>
+      <term>Query plan</term>
       <listitem>
        <para>
-	Explicit query plan from the <productname>PostgreSQL</productname> backend.
-       </para>
-      </listitem>
-     </varlistentry>
-     <varlistentry>
-      <term><computeroutput>
-EXPLAIN
-       </computeroutput></term>
-      <listitem>
-       <para>
-	Flag sent after query plan is shown.
+	Explicit query plan from the <productname>PostgreSQL</productname>
+	planner.
        </para>
       </listitem>
      </varlistentry>
     </variablelist>
    </para>
+
+   <note>
+    <para>
+     Prior to <application>PostgreSQL</application> 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).
+    </para>
+   </note>
   </refsect2>
  </refsynopsisdiv>
 
@@ -141,13 +137,6 @@ EXPLAIN
    are close to reality.
   </para>
 
-  <para>
-   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
-   <application>PostgreSQL</application>. 
-  </para>
-
   <caution>
    <para>
     Keep in mind that the query is actually executed when ANALYZE is used.
@@ -165,6 +154,15 @@ ROLLBACK;
    </para>
   </caution>
 
+  <para>
+   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
+   <application>PostgreSQL</application>.   The VERBOSE dump is either
+   pretty-printed or not, depending on the setting of the
+   <option>EXPLAIN_PRETTY_PRINT</option> configuration parameter.
+  </para>
+
   <refsect2 id="R2-SQL-EXPLAIN-3">
    <refsect2info>
     <date>1998-04-15</date>
@@ -188,50 +186,48 @@ ROLLBACK;
 
   <para>
    To show a query plan for a simple query on a table with a single
-   <type>int4</type> column and 128 rows:
+   <type>int4</type> column and 10000 rows:
 
    <programlisting>
 EXPLAIN SELECT * FROM foo;
     <computeroutput>
-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)
     </computeroutput>
    </programlisting>
   </para>
 
   <para>
-   For the same table with an index to support an
-   <firstterm>equijoin</firstterm> condition on the query,
+   If there is an index and we use a query with an indexable WHERE condition,
    <command>EXPLAIN</command> will show a different plan:
 
    <programlisting>
 EXPLAIN SELECT * FROM foo WHERE i = 4;
     <computeroutput>
-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)
     </computeroutput>
    </programlisting>
   </para>
 
   <para>
-   And finally, for the same table with an index to support an
-   <firstterm>equijoin</firstterm> condition on the query,
-   <command>EXPLAIN</command> will show the following for a query
+   And here is an example of a query plan for a query
    using an aggregate function:
 
    <programlisting>
-EXPLAIN SELECT sum(i) FROM foo WHERE i = 4;
+EXPLAIN SELECT sum(i) FROM foo WHERE i < 4;
     <computeroutput>
-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)
     </computeroutput>
    </programlisting>
   </para>
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 @@
 <!--
-$Header: /cvsroot/pgsql/doc/src/sgml/release.sgml,v 1.125 2002/03/22 19:20:22 petere Exp $
+$Header: /cvsroot/pgsql/doc/src/sgml/release.sgml,v 1.126 2002/03/24 04:31:05 tgl Exp $
 -->
 
 <appendix id="release">
@@ -24,6 +24,7 @@ CDATA means the content is "SGML-free", so you can write without
 worries about funny characters.
 -->
 <literallayout><![CDATA[
+EXPLAIN output comes out as a query result, not a NOTICE message
 DOMAINs (types that are constrained versions of base types)
 Access privileges on functions
 Access privileges on procedural languages
diff --git a/doc/src/sgml/runtime.sgml b/doc/src/sgml/runtime.sgml
index ddeac7ce1da..9c118d2be25 100644
--- a/doc/src/sgml/runtime.sgml
+++ b/doc/src/sgml/runtime.sgml
@@ -1,5 +1,5 @@
 <!--
-$Header: /cvsroot/pgsql/doc/src/sgml/runtime.sgml,v 1.109 2002/03/22 19:20:28 petere Exp $
+$Header: /cvsroot/pgsql/doc/src/sgml/runtime.sgml,v 1.110 2002/03/24 04:31:06 tgl Exp $
 -->
 
 <Chapter Id="runtime">
@@ -871,6 +871,16 @@ env PGOPTIONS='-c geqo=off' psql
      </varlistentry>
 
      <varlistentry>
+      <term><varname>EXPLAIN_PRETTY_PRINT</varname> (<type>boolean</type>)</term>
+      <listitem>
+       <para>
+        Determines whether <command>EXPLAIN VERBOSE</> uses the indented
+	or non-indented format for displaying detailed querytree dumps.
+       </para>
+      </listitem>
+     </varlistentry>
+
+     <varlistentry>
       <term><varname>HOSTNAME_LOOKUP</varname> (<type>boolean</type>)</term>
       <listitem>
        <para>