]> granicus.if.org Git - postgresql/commitdiff
Print planning time only in EXPLAIN ANALYZE, not plain EXPLAIN.
authorTom Lane <tgl@sss.pgh.pa.us>
Wed, 15 Oct 2014 22:50:13 +0000 (18:50 -0400)
committerTom Lane <tgl@sss.pgh.pa.us>
Wed, 15 Oct 2014 22:50:13 +0000 (18:50 -0400)
We've gotten enough push-back on that change to make it clear that it
wasn't an especially good idea to do it like that.  Revert plain EXPLAIN
to its previous behavior, but keep the extra output in EXPLAIN ANALYZE.
Per discussion.

Internally, I set this up as a separate flag ExplainState.summary that
controls printing of planning time and execution time.  For now it's
just copied from the ANALYZE option, but we could consider exposing it
to users.

contrib/auto_explain/auto_explain.c
doc/src/sgml/perform.sgml
doc/src/sgml/ref/explain.sgml
src/backend/commands/explain.c
src/include/commands/explain.h

index b33b2211ca09f2fd67d2e793e95db3897c3196bd..d5fa6ac2d3136e788523cda8e45846f236a37e79 100644 (file)
@@ -301,6 +301,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
                        es.verbose = auto_explain_log_verbose;
                        es.buffers = (es.analyze && auto_explain_log_buffers);
                        es.timing = (es.analyze && auto_explain_log_timing);
+                       es.summary = es.analyze;
                        es.format = auto_explain_log_format;
 
                        ExplainBeginOutput(&es);
index 94c11adaa4900bf466a3f3cba3c7ab12c03c65aa..5a087fbe6a098f8bfb2ac55c99cf1e767a486409 100644 (file)
@@ -89,7 +89,6 @@ EXPLAIN SELECT * FROM tenk1;
                          QUERY PLAN
 -------------------------------------------------------------
  Seq Scan on tenk1  (cost=0.00..458.00 rows=10000 width=244)
- Planning time: 0.113 ms
 </screen>
    </para>
 
@@ -162,12 +161,6 @@ EXPLAIN SELECT * FROM tenk1;
     actually returned, updated, or deleted by the query.
    </para>
 
-   <para>
-    The <literal>Planning time</literal> shown is the time it took to generate
-    the query plan from the parsed query and optimize it. It does not include
-    rewriting and parsing.
-   </para>
-
    <para>
     Returning to our example:
 
@@ -177,7 +170,6 @@ EXPLAIN SELECT * FROM tenk1;
                          QUERY PLAN
 -------------------------------------------------------------
  Seq Scan on tenk1  (cost=0.00..458.00 rows=10000 width=244)
- Planning time: 0.113 ms
 </screen>
    </para>
 
@@ -206,7 +198,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 7000;
 ------------------------------------------------------------
  Seq Scan on tenk1  (cost=0.00..483.00 rows=7001 width=244)
    Filter: (unique1 &lt; 7000)
- Planning time: 0.104 ms
 </screen>
 
     Notice that the <command>EXPLAIN</> output shows the <literal>WHERE</>
@@ -243,7 +234,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 100;
    Recheck Cond: (unique1 &lt; 100)
    -&gt;  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=101 width=0)
          Index Cond: (unique1 &lt; 100)
- Planning time: 0.093 ms
 </screen>
 
     Here the planner has decided to use a two-step plan: the child plan
@@ -272,7 +262,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND stringu1 = 'xxx';
    Filter: (stringu1 = 'xxx'::name)
    -&gt;  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=101 width=0)
          Index Cond: (unique1 &lt; 100)
- Planning time: 0.089 ms
 </screen>
 
     The added condition <literal>stringu1 = 'xxx'</literal> reduces the
@@ -294,7 +283,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 = 42;
 -----------------------------------------------------------------------------
  Index Scan using tenk1_unique1 on tenk1  (cost=0.29..8.30 rows=1 width=244)
    Index Cond: (unique1 = 42)
- Planning time: 0.076 ms
 </screen>
 
     In this type of plan the table rows are fetched in index order, which
@@ -323,7 +311,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique2 &gt; 9000;
                Index Cond: (unique1 &lt; 100)
          -&gt;  Bitmap Index Scan on tenk1_unique2  (cost=0.00..19.78 rows=999 width=0)
                Index Cond: (unique2 &gt; 9000)
- Planning time: 0.094 ms
 </screen>
 
     But this requires visiting both indexes, so it's not necessarily a win
@@ -344,7 +331,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique2 &gt; 9000 LIMIT 2
    -&gt;  Index Scan using tenk1_unique2 on tenk1  (cost=0.29..71.27 rows=10 width=244)
          Index Cond: (unique2 &gt; 9000)
          Filter: (unique1 &lt; 100)
- Planning time: 0.087 ms
 </screen>
    </para>
 
@@ -378,7 +364,6 @@ WHERE t1.unique1 &lt; 10 AND t1.unique2 = t2.unique2;
                Index Cond: (unique1 &lt; 10)
    -&gt;  Index Scan using tenk2_unique2 on tenk2 t2  (cost=0.29..7.91 rows=1 width=244)
          Index Cond: (unique2 = t1.unique2)
- Planning time: 0.117 ms
 </screen>
    </para>
 
@@ -430,7 +415,6 @@ WHERE t1.unique1 &lt; 10 AND t2.unique2 &lt; 10 AND t1.hundred &lt; t2.hundred;
    -&gt;  Materialize  (cost=0.29..8.51 rows=10 width=244)
          -&gt;  Index Scan using tenk2_unique2 on tenk2 t2  (cost=0.29..8.46 rows=10 width=244)
                Index Cond: (unique2 &lt; 10)
- Planning time: 0.119 ms
 </screen>
 
     The condition <literal>t1.hundred &lt; t2.hundred</literal> can't be
@@ -478,7 +462,6 @@ WHERE t1.unique1 &lt; 100 AND t1.unique2 = t2.unique2;
                Recheck Cond: (unique1 &lt; 100)
                -&gt;  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=101 width=0)
                      Index Cond: (unique1 &lt; 100)
- Planning time: 0.182 ms
 </screen>
    </para>
 
@@ -509,7 +492,6 @@ WHERE t1.unique1 &lt; 100 AND t1.unique2 = t2.unique2;
    -&gt;  Sort  (cost=197.83..200.33 rows=1000 width=244)
          Sort Key: t2.unique2
          -&gt;  Seq Scan on onek t2  (cost=0.00..148.00 rows=1000 width=244)
- Planning time: 0.195 ms
 </screen>
    </para>
 
@@ -546,7 +528,6 @@ WHERE t1.unique1 &lt; 100 AND t1.unique2 = t2.unique2;
    -&gt;  Index Scan using tenk1_unique2 on tenk1 t1  (cost=0.29..656.28 rows=101 width=244)
          Filter: (unique1 &lt; 100)
    -&gt;  Index Scan using onek_unique2 on onek t2  (cost=0.28..224.79 rows=1000 width=244)
- Planning time: 0.176 ms
 </screen>
 
     which shows that the planner thinks that sorting <literal>onek</> by
@@ -780,6 +761,12 @@ ROLLBACK;
     decisions.
    </para>
 
+   <para>
+    The <literal>Planning time</literal> shown by <command>EXPLAIN
+    ANALYZE</command> is the time it took to generate the query plan from the
+    parsed query and optimize it. It does not include parsing or rewriting.
+   </para>
+
    <para>
     The <literal>Execution time</literal> shown by <command>EXPLAIN
     ANALYZE</command> includes executor start-up and shut-down time, as well
index 72776a0fdef92c8318cb8353c1f96bb0d81bba56..f14a58dfc6353a55e705e9dcfccd52ba8d5ed0a0 100644 (file)
@@ -145,8 +145,8 @@ ROLLBACK;
      <para>
       Include information on the estimated startup and total cost of each
       plan node, as well as the estimated number of rows and the estimated
-      width of each row.  Also, include the time spent planning the query,
-      if available.  This parameter defaults to <literal>TRUE</literal>.
+      width of each row.
+      This parameter defaults to <literal>TRUE</literal>.
      </para>
     </listitem>
    </varlistentry>
@@ -291,8 +291,7 @@ EXPLAIN SELECT * FROM foo;
                        QUERY PLAN
 ---------------------------------------------------------
  Seq Scan on foo  (cost=0.00..155.00 rows=10000 width=4)
- Planning time: 0.114 ms
-(2 rows)
+(1 row)
 </programlisting>
   </para>
 
@@ -312,8 +311,7 @@ EXPLAIN (FORMAT JSON) SELECT * FROM foo;
        "Total Cost": 155.00,   +
        "Plan Rows": 10000,     +
        "Plan Width": 4         +
-     }.                        +
-     "Planning Time": 0.114    +
+     }                         +
    }                           +
  ]
 (1 row)
@@ -332,8 +330,7 @@ EXPLAIN SELECT * FROM foo WHERE i = 4;
 --------------------------------------------------------------
  Index Scan using fi on foo  (cost=0.00..5.98 rows=1 width=4)
    Index Cond: (i = 4)
- Planning time: 0.073 ms
-(3 rows)
+(2 rows)
 </programlisting>
   </para>
 
@@ -353,8 +350,7 @@ EXPLAIN (FORMAT YAML) SELECT * FROM foo WHERE i='4';
      Total Cost: 5.98         +
      Plan Rows: 1             +
      Plan Width: 4            +
-     Index Cond: "(i = 4)"    +
-   Planning Time: 0.073
+     Index Cond: "(i = 4)"    
 (1 row)
 </programlisting>
 
@@ -386,7 +382,6 @@ EXPLAIN SELECT sum(i) FROM foo WHERE i &lt; 10;
  Aggregate  (cost=23.93..23.93 rows=1 width=4)
    -&gt;  Index Scan using fi on foo  (cost=0.00..23.92 rows=6 width=4)
          Index Cond: (i &lt; 10)
- Planning time: 0.088 ms
 (3 rows)
 </programlisting>
   </para>
@@ -410,7 +405,7 @@ EXPLAIN ANALYZE EXECUTE query(100, 200);
          Index Cond: ((id &gt; $1) AND (id &lt; $2))
  Planning time: 0.197 ms
  Execution time: 0.225 ms
-(5 rows)
+(6 rows)
 </programlisting>
   </para>
 
index 387d263e8736db1ffa179aa6057e7fa2078a84b8..3fcc1ddc69c5babb72bc77c07228762bc158a43f 100644 (file)
@@ -191,6 +191,9 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
                                (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
                                 errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
+       /* currently, summary option is not exposed to users; just set it */
+       es.summary = es.analyze;
+
        /*
         * Parse analysis was done already, but we still have to run the rule
         * rewriter.  We do not do AcquireRewriteLocks: we assume the query either
@@ -431,7 +434,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 
        /*
         * We always collect timing for the entire statement, even when node-level
-        * timing is off, so we don't look at es->timing here.
+        * timing is off, so we don't look at es->timing here.  (We could skip
+        * this if !es->summary, but it's hardly worth the complication.)
         */
        INSTR_TIME_SET_CURRENT(starttime);
 
@@ -493,7 +497,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
        /* Create textual dump of plan tree */
        ExplainPrintPlan(es, queryDesc);
 
-       if (es->costs && planduration)
+       if (es->summary && planduration)
        {
                double          plantime = INSTR_TIME_GET_DOUBLE(*planduration);
 
@@ -526,7 +530,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 
        totaltime += elapsed_time(&starttime);
 
-       if (es->analyze)
+       if (es->summary)
        {
                if (es->format == EXPLAIN_FORMAT_TEXT)
                        appendStringInfo(es->str, "Execution time: %.3f ms\n",
index 3488be39c38a819621909f156c4c92606eb9f0c2..d56beaac15989ec836dfaa88763e85aead210040 100644 (file)
@@ -30,9 +30,10 @@ typedef struct ExplainState
        /* options */
        bool            verbose;                /* be verbose */
        bool            analyze;                /* print actual times */
-       bool            costs;                  /* print costs */
+       bool            costs;                  /* print estimated costs */
        bool            buffers;                /* print buffer usage */
-       bool            timing;                 /* print timing */
+       bool            timing;                 /* print detailed node timing */
+       bool            summary;                /* print total planning and execution timing */
        ExplainFormat format;           /* output format */
        /* other states */
        PlannedStmt *pstmt;                     /* top of plan */