On 01/28/2014 09:39 PM, Tom Lane wrote:
I'm for doing the measurement in ExplainOneQuery() and not printing
anything in code paths that don't go through there.
Reading the discussion here and realizing that my last patch was wrong I
am now in agreement with this. I have attached a patch which no longer
tries to measure planning time for prepared statements.
/Andreas
diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml
new file mode 100644
index 2af1738..482490b
*** a/doc/src/sgml/perform.sgml
--- b/doc/src/sgml/perform.sgml
*************** EXPLAIN SELECT * FROM tenk1;
*** 89,94 ****
--- 89,95 ----
QUERY PLAN
-------------------------------------------------------------
Seq Scan on tenk1 (cost=0.00..458.00 rows=10000 width=244)
+ Planning time: 0.113 ms
</screen>
</para>
*************** EXPLAIN SELECT * FROM tenk1;
*** 162,167 ****
--- 163,174 ----
</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:
<screen>
*************** EXPLAIN SELECT * FROM tenk1;
*** 170,175 ****
--- 177,183 ----
QUERY PLAN
-------------------------------------------------------------
Seq Scan on tenk1 (cost=0.00..458.00 rows=10000 width=244)
+ Planning time: 0.113 ms
</screen>
</para>
*************** EXPLAIN SELECT * FROM tenk1 WHERE unique
*** 198,203 ****
--- 206,212 ----
------------------------------------------------------------
Seq Scan on tenk1 (cost=0.00..483.00 rows=7001 width=244)
Filter: (unique1 < 7000)
+ Planning time: 0.104 ms
</screen>
Notice that the <command>EXPLAIN</> output shows the <literal>WHERE</>
*************** EXPLAIN SELECT * FROM tenk1 WHERE unique
*** 234,239 ****
--- 243,249 ----
Recheck Cond: (unique1 < 100)
-> Bitmap Index Scan on tenk1_unique1 (cost=0.00..5.04 rows=101 width=0)
Index Cond: (unique1 < 100)
+ Planning time: 0.093 ms
</screen>
Here the planner has decided to use a two-step plan: the child plan
*************** EXPLAIN SELECT * FROM tenk1 WHERE unique
*** 262,267 ****
--- 272,278 ----
Filter: (stringu1 = 'xxx'::name)
-> Bitmap Index Scan on tenk1_unique1 (cost=0.00..5.04 rows=101 width=0)
Index Cond: (unique1 < 100)
+ Planning time: 0.089 ms
</screen>
The added condition <literal>stringu1 = 'xxx'</literal> reduces the
*************** EXPLAIN SELECT * FROM tenk1 WHERE unique
*** 283,288 ****
--- 294,300 ----
-----------------------------------------------------------------------------
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
*************** EXPLAIN SELECT * FROM tenk1 WHERE unique
*** 311,316 ****
--- 323,329 ----
Index Cond: (unique1 < 100)
-> Bitmap Index Scan on tenk1_unique2 (cost=0.00..19.78 rows=999 width=0)
Index Cond: (unique2 > 9000)
+ Planning time: 0.094 ms
</screen>
But this requires visiting both indexes, so it's not necessarily a win
*************** EXPLAIN SELECT * FROM tenk1 WHERE unique
*** 331,336 ****
--- 344,350 ----
-> Index Scan using tenk1_unique2 on tenk1 (cost=0.29..71.27 rows=10 width=244)
Index Cond: (unique2 > 9000)
Filter: (unique1 < 100)
+ Planning time: 0.087 ms
</screen>
</para>
*************** WHERE t1.unique1 < 10 AND t1.unique2
*** 364,369 ****
--- 378,384 ----
Index Cond: (unique1 < 10)
-> 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>
*************** WHERE t1.unique1 < 10 AND t2.unique2
*** 415,420 ****
--- 430,436 ----
-> Materialize (cost=0.29..8.51 rows=10 width=244)
-> Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..8.46 rows=10 width=244)
Index Cond: (unique2 < 10)
+ Planning time: 0.119 ms
</screen>
The condition <literal>t1.hundred < t2.hundred</literal> can't be
*************** WHERE t1.unique1 < 100 AND t1.unique2
*** 462,467 ****
--- 478,484 ----
Recheck Cond: (unique1 < 100)
-> Bitmap Index Scan on tenk1_unique1 (cost=0.00..5.04 rows=101 width=0)
Index Cond: (unique1 < 100)
+ Planning time: 0.182 ms
</screen>
</para>
*************** WHERE t1.unique1 < 100 AND t1.unique2
*** 492,497 ****
--- 509,515 ----
-> Sort (cost=197.83..200.33 rows=1000 width=244)
Sort Key: t2.unique2
-> Seq Scan on onek t2 (cost=0.00..148.00 rows=1000 width=244)
+ Planning time: 0.195 ms
</screen>
</para>
*************** WHERE t1.unique1 < 100 AND t1.unique2
*** 528,533 ****
--- 546,552 ----
-> Index Scan using tenk1_unique2 on tenk1 t1 (cost=0.29..656.28 rows=101 width=244)
Filter: (unique1 < 100)
-> 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
*************** WHERE t1.unique1 < 10 AND t1.unique2
*** 564,569 ****
--- 583,589 ----
Index Cond: (unique1 < 10)
-> 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>
*************** WHERE t1.unique1 < 100 AND t1.unique2
*** 612,617 ****
--- 632,638 ----
Recheck Cond: (unique1 < 100)
-> 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 < 100)
+ Planning time: 0.194 ms
Total runtime: 8.008 ms
</screen>
*************** EXPLAIN ANALYZE SELECT * FROM tenk1 WHER
*** 635,640 ****
--- 656,662 ----
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 < 7)
Rows Removed by Filter: 3000
+ Planning time: 0.083 ms
Total runtime: 5.905 ms
</screen>
*************** EXPLAIN ANALYZE SELECT * FROM polygon_tb
*** 657,662 ****
--- 679,685 ----
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 @> '((0.5,2))'::polygon)
Rows Removed by Filter: 4
+ Planning time: 0.040 ms
Total runtime: 0.083 ms
</screen>
*************** EXPLAIN ANALYZE SELECT * FROM polygon_tb
*** 675,680 ****
--- 698,704 ----
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 @> '((0.5,2))'::polygon)
Rows Removed by Index Recheck: 1
+ Planning time: 0.034 ms
Total runtime: 0.144 ms
</screen>
*************** EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM
*** 705,710 ****
--- 729,735 ----
-> 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 > 9000)
Buffers: shared hit=5
+ Planning time: 0.088 ms
Total runtime: 0.423 ms
</screen>
*************** EXPLAIN ANALYZE UPDATE tenk1 SET hundred
*** 732,737 ****
--- 757,763 ----
Recheck Cond: (unique1 < 100)
-> 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 < 100)
+ Planning time: 0.079 ms
Total runtime: 14.727 ms
ROLLBACK;
*************** EXPLAIN ANALYZE SELECT * FROM tenk1 WHER
*** 817,822 ****
--- 843,849 ----
Index Cond: (unique2 > 9000)
Filter: (unique1 < 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
new file mode 100644
index 35264dc..4e3f571
*** a/doc/src/sgml/ref/explain.sgml
--- b/doc/src/sgml/ref/explain.sgml
*************** ROLLBACK;
*** 145,151 ****
<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>.
</para>
</listitem>
</varlistentry>
--- 145,152 ----
<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. Additionally it controls if the planning time is
! displayed. This parameter defaults to <literal>TRUE</literal>.
</para>
</listitem>
</varlistentry>
*************** EXPLAIN SELECT * FROM foo;
*** 289,295 ****
QUERY PLAN
---------------------------------------------------------
Seq Scan on foo (cost=0.00..155.00 rows=10000 width=4)
! (1 row)
</programlisting>
</para>
--- 290,297 ----
QUERY PLAN
---------------------------------------------------------
Seq Scan on foo (cost=0.00..155.00 rows=10000 width=4)
! Planning time: 0.114 ms
! (2 rows)
</programlisting>
</para>
*************** EXPLAIN (FORMAT JSON) SELECT * FROM foo;
*** 309,315 ****
"Total Cost": 155.00, +
"Plan Rows": 10000, +
"Plan Width": 4 +
! } +
} +
]
(1 row)
--- 311,318 ----
"Total Cost": 155.00, +
"Plan Rows": 10000, +
"Plan Width": 4 +
! }. +
! "Planning Time": 0.114 +
} +
]
(1 row)
*************** EXPLAIN SELECT * FROM foo WHERE i = 4;
*** 328,334 ****
--------------------------------------------------------------
Index Scan using fi on foo (cost=0.00..5.98 rows=1 width=4)
Index Cond: (i = 4)
! (2 rows)
</programlisting>
</para>
--- 331,338 ----
--------------------------------------------------------------
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)
</programlisting>
</para>
*************** EXPLAIN (FORMAT YAML) SELECT * FROM foo
*** 348,354 ****
Total Cost: 5.98 +
Plan Rows: 1 +
Plan Width: 4 +
! Index Cond: "(i = 4)"
(1 row)
</programlisting>
--- 352,359 ----
Total Cost: 5.98 +
Plan Rows: 1 +
Plan Width: 4 +
! Index Cond: "(i = 4)" +
! Planning Time: 0.073
(1 row)
</programlisting>
*************** EXPLAIN SELECT sum(i) FROM foo WHERE i &
*** 380,385 ****
--- 385,391 ----
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 Cond: (i < 10)
+ Planning time: 0.088 ms
(3 rows)
</programlisting>
</para>
*************** EXPLAIN ANALYZE EXECUTE query(100, 200);
*** 401,406 ****
--- 407,413 ----
Group Key: foo
-> 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 > $1) AND (id < $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
new file mode 100644
index 0dba928..62d42e0
*** a/src/backend/commands/explain.c
--- b/src/backend/commands/explain.c
*************** ExplainOneQuery(Query *query, IntoClause
*** 320,332 ****
(*ExplainOneQuery_hook) (query, into, es, queryString, params);
else
{
! PlannedStmt *plan;
/* plan the query */
plan = pg_plan_query(query, 0, params);
/* run it (if needed) and produce output */
! ExplainOnePlan(plan, into, es, queryString, params);
}
}
--- 320,338 ----
(*ExplainOneQuery_hook) (query, into, es, queryString, params);
else
{
! 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, planduration, true);
}
}
*************** ExplainOneUtility(Node *utilityStmt, Int
*** 403,409 ****
*/
void
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
! const char *queryString, ParamListInfo params)
{
DestReceiver *dest;
QueryDesc *queryDesc;
--- 409,416 ----
*/
void
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
! const char *queryString, ParamListInfo params,
! instr_time planduration, bool hasplanduration)
{
DestReceiver *dest;
QueryDesc *queryDesc;
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 484,489 ****
--- 491,507 ----
/* Create textual dump of plan tree */
ExplainPrintPlan(es, queryDesc);
+ if (es->costs && hasplanduration)
+ {
+ 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
new file mode 100644
index 49c4093..df12ff3
*** a/src/backend/commands/prepare.c
--- b/src/backend/commands/prepare.c
*************** ExplainExecuteQuery(ExecuteStmt *execstm
*** 629,634 ****
--- 629,635 ----
ListCell *p;
ParamListInfo paramLI = NULL;
EState *estate = NULL;
+ instr_time planduration;
/* Look it up in the hash table */
entry = FetchPreparedStatement(execstmt->name, true);
*************** ExplainExecuteQuery(ExecuteStmt *execstm
*** 657,662 ****
--- 658,666 ----
/* Replan if needed, and acquire a transient refcount */
cplan = GetCachedPlan(entry->plansource, paramLI, true);
+ /* We do not measure the planning time for prepared statements */
+ INSTR_TIME_SET_ZERO(planduration);
+
plan_list = cplan->stmt_list;
/* Explain each query */
*************** ExplainExecuteQuery(ExecuteStmt *execstm
*** 665,671 ****
PlannedStmt *pstmt = (PlannedStmt *) lfirst(p);
if (IsA(pstmt, PlannedStmt))
! ExplainOnePlan(pstmt, into, es, query_string, paramLI);
else
ExplainOneUtility((Node *) pstmt, into, es, query_string, paramLI);
--- 669,675 ----
PlannedStmt *pstmt = (PlannedStmt *) lfirst(p);
if (IsA(pstmt, PlannedStmt))
! ExplainOnePlan(pstmt, into, es, query_string, paramLI, planduration, false);
else
ExplainOneUtility((Node *) pstmt, into, es, query_string, paramLI);
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
new file mode 100644
index e097710..2db8c36
*** a/src/include/commands/explain.h
--- b/src/include/commands/explain.h
*************** extern void ExplainOneUtility(Node *util
*** 67,74 ****
const char *queryString, ParamListInfo params);
extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
! ExplainState *es,
! const char *queryString, ParamListInfo params);
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
--- 67,75 ----
const char *queryString, ParamListInfo params);
extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
! ExplainState *es, const char *queryString,
! ParamListInfo params,
! instr_time planduration, bool hasplanduration);
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
