Include planning time in EXPLAIN ANALYZE output.

This doesn't work for prepared queries, but it's not too easy to get
the information in that case and there's some debate as to exactly
what the right thing to measure is, so just do this for now.

Andreas Karlsson, with slight doc changes by me.

diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml
index 2af1738576a41373bdf4440257fb353acc379129..482490ba78c3ee91471d2c839c2a8774df61b8a2 100644 (file)
--- a/doc/src/sgml/perform.sgml
+++ b/doc/src/sgml/perform.sgml
@@ -89,6 +89,7 @@ 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>
 
@@ -161,6 +162,12 @@ 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:
 
@@ -170,6 +177,7 @@ 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>
 
@@ -198,6 +206,7 @@ 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</>
@@ -234,6 +243,7 @@ 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
@@ -262,6 +272,7 @@ 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
@@ -283,6 +294,7 @@ 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
@@ -311,6 +323,7 @@ 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
@@ -331,6 +344,7 @@ 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>
 
@@ -364,6 +378,7 @@ 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>
 
@@ -415,6 +430,7 @@ 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
@@ -462,6 +478,7 @@ 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>
 
@@ -492,6 +509,7 @@ 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>
 
@@ -528,6 +546,7 @@ 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
@@ -564,6 +583,7 @@ 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) (actual time=0.021..0.022 rows=1 loops=10)
          Index Cond: (unique2 = t1.unique2)
+ Planning time: 0.181 ms
  Total runtime: 0.501 ms
 </screen>
 
@@ -612,6 +632,7 @@ WHERE t1.unique1 &lt; 100 AND t1.unique2 = t2.unique2 ORDER BY t1.fivethous;
                      Recheck Cond: (unique1 &lt; 100)
                      -&gt;  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=101 width=0) (actual time=0.049..0.049 rows=100 loops=1)
                            Index Cond: (unique1 &lt; 100)
+ Planning time: 0.194 ms
  Total runtime: 8.008 ms
 </screen>
 
@@ -635,6 +656,7 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE ten &lt; 7;
  Seq Scan on tenk1  (cost=0.00..483.00 rows=7000 width=244) (actual time=0.016..5.107 rows=7000 loops=1)
    Filter: (ten &lt; 7)
    Rows Removed by Filter: 3000
+ Planning time: 0.083 ms
  Total runtime: 5.905 ms
 </screen>
 
@@ -657,6 +679,7 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @&gt; polygon '(0.5,2.0)';
  Seq Scan on polygon_tbl  (cost=0.00..1.05 rows=1 width=32) (actual time=0.044..0.044 rows=0 loops=1)
    Filter: (f1 @&gt; '((0.5,2))'::polygon)
    Rows Removed by Filter: 4
+ Planning time: 0.040 ms
  Total runtime: 0.083 ms
 </screen>
 
@@ -675,6 +698,7 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @&gt; polygon '(0.5,2.0)';
  Index Scan using gpolygonind on polygon_tbl  (cost=0.13..8.15 rows=1 width=32) (actual time=0.062..0.062 rows=0 loops=1)
    Index Cond: (f1 @&gt; '((0.5,2))'::polygon)
    Rows Removed by Index Recheck: 1
+ Planning time: 0.034 ms
  Total runtime: 0.144 ms
 </screen>
 
@@ -705,6 +729,7 @@ EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique
          -&gt;  Bitmap Index Scan on tenk1_unique2  (cost=0.00..19.78 rows=999 width=0) (actual time=0.227..0.227 rows=999 loops=1)
                Index Cond: (unique2 &gt; 9000)
                Buffers: shared hit=5
+ Planning time: 0.088 ms
  Total runtime: 0.423 ms
 </screen>
 
@@ -732,6 +757,7 @@ EXPLAIN ANALYZE UPDATE tenk1 SET hundred = hundred + 1 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) (actual time=0.043..0.043 rows=100 loops=1)
                Index Cond: (unique1 &lt; 100)
+ Planning time: 0.079 ms
  Total runtime: 14.727 ms
 
 ROLLBACK;
@@ -817,6 +843,7 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique2 &gt; 9000
          Index Cond: (unique2 &gt; 9000)
          Filter: (unique1 &lt; 100)
          Rows Removed by Filter: 287
+ Planning time: 0.096 ms
  Total runtime: 0.336 ms
 </screen>
 

diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index 35264dcc72cf44023a315e0d4b4d500d0bea1320..0f579fb161fe6336aecb1fd50fd9d2aef38a7c2f 100644 (file)
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -145,7 +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.  This parameter defaults to <literal>TRUE</literal>.
+      width of each row.  Also, include the time spent planning the query,
+      if available.  This parameter defaults to <literal>TRUE</literal>.
      </para>
     </listitem>
    </varlistentry>
@@ -289,7 +290,8 @@ EXPLAIN SELECT * FROM foo;
                        QUERY PLAN
 ---------------------------------------------------------
  Seq Scan on foo  (cost=0.00..155.00 rows=10000 width=4)
-(1 row)
+ Planning time: 0.114 ms
+(2 rows)
 </programlisting>
   </para>
 
@@ -309,7 +311,8 @@ EXPLAIN (FORMAT JSON) SELECT * FROM foo;
        "Total Cost": 155.00,   +
        "Plan Rows": 10000,     +
        "Plan Width": 4         +
-     }                         +
+     }.                        +
+     "Planning Time": 0.114    +
    }                           +
  ]
 (1 row)
@@ -328,7 +331,8 @@ 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)
-(2 rows)
+ Planning time: 0.073 ms
+(3 rows)
 </programlisting>
   </para>
 
@@ -348,7 +352,8 @@ EXPLAIN (FORMAT YAML) SELECT * FROM foo WHERE i='4';
      Total Cost: 5.98         +
      Plan Rows: 1             +
      Plan Width: 4            +
-     Index Cond: "(i = 4)"
+     Index Cond: "(i = 4)"    +
+   Planning Time: 0.073
 (1 row)
 </programlisting>
 
@@ -380,6 +385,7 @@ 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>
@@ -401,6 +407,7 @@ EXPLAIN ANALYZE EXECUTE query(100, 200);
    Group Key: foo
    -&gt;  Index Scan using test_pkey on test  (cost=0.29..9.29 rows=50 width=8) (actual time=0.039..0.091 rows=99 loops=1)
          Index Cond: ((id &gt; $1) AND (id &lt; $2))
+ Planning time: 0.197 ms
  Total runtime: 0.225 ms
 (5 rows)
 </programlisting>

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 0dba9283f1ce2689439b49feec5d722590243908..08f3167f10d638a8b616504ee4030b32e1ab66d2 100644 (file)
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -320,13 +320,19 @@ ExplainOneQuery(Query *query, IntoClause *into, ExplainState *es,
        (*ExplainOneQuery_hook) (query, into, es, queryString, params);
    else
    {
-       PlannedStmt *plan;
+       PlannedStmt *plan;
+       instr_time  planstart, planduration;
+
+       INSTR_TIME_SET_CURRENT(planstart);
 
        /* plan the query */
        plan = pg_plan_query(query, 0, params);
 
+       INSTR_TIME_SET_CURRENT(planduration);
+       INSTR_TIME_SUBTRACT(planduration, planstart);
+
        /* run it (if needed) and produce output */
-       ExplainOnePlan(plan, into, es, queryString, params);
+       ExplainOnePlan(plan, into, es, queryString, params, &planduration);
    }
 }
 
@@ -403,7 +409,8 @@ ExplainOneUtility(Node *utilityStmt, IntoClause *into, ExplainState *es,
  */
 void
 ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
-              const char *queryString, ParamListInfo params)
+              const char *queryString, ParamListInfo params,
+              const instr_time *planduration)
 {
    DestReceiver *dest;
    QueryDesc  *queryDesc;
@@ -484,6 +491,17 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
    /* Create textual dump of plan tree */
    ExplainPrintPlan(es, queryDesc);
 
+   if (es->costs && planduration)
+   {
+       double plantime = INSTR_TIME_GET_DOUBLE(*planduration);
+
+       if (es->format == EXPLAIN_FORMAT_TEXT)
+           appendStringInfo(es->str, "Planning time: %.3f ms\n",
+                            1000.0 * plantime);
+       else
+           ExplainPropertyFloat("Planning Time", 1000.0 * plantime, 3, es);
+   }
+
    /* Print info about runtime of triggers */
    if (es->analyze)
        ExplainPrintTriggers(es, queryDesc);

diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c
index 49c40935eb921d048e1906fb58bddcdb9831be86..65431b713d0c7c4aef034dbebaa8c4eb4037ab38 100644 (file)
--- a/src/backend/commands/prepare.c
+++ b/src/backend/commands/prepare.c
@@ -665,7 +665,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
        PlannedStmt *pstmt = (PlannedStmt *) lfirst(p);
 
        if (IsA(pstmt, PlannedStmt))
-           ExplainOnePlan(pstmt, into, es, query_string, paramLI);
+           ExplainOnePlan(pstmt, into, es, query_string, paramLI, NULL);
        else
            ExplainOneUtility((Node *) pstmt, into, es, query_string, paramLI);
 

diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index e097710ddddae958bc5f040e968cfeced7c5d2b2..3488be39c38a819621909f156c4c92606eb9f0c2 100644 (file)
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -67,8 +67,8 @@ extern void ExplainOneUtility(Node *utilityStmt, IntoClause *into,
                  const char *queryString, ParamListInfo params);
 
 extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
-              ExplainState *es,
-              const char *queryString, ParamListInfo params);
+              ExplainState *es, const char *queryString,
+              ParamListInfo params, const instr_time *planduration);
 
 extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
 extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);