A patch with updated documentation is attached.
On 01/02/2014 04:08 AM, Robert Haas wrote:
I'm wondering whether the time should be stored inside the PlannedStmt
node instead of passing it around separately. One possible problem
with the way you've done things here is that, in the case of a
prepared statement, EXPLAIN ANALYZE will emit the time needed to call
GetCachedPlan(), even if that function didn't do any replanning. Now
you could argue that this is the correct behavior, but I think there's
a decent argument that what we ought to show there is the amount of
time that was required to create the plan that we're displaying at the
time it was created, rather than the amount of time that was required
to figure out that we didn't need to replan.
A minor side benefit of this approach is that you wouldn't need to
change the signature for ExplainOnePlan(), which would avoid breaking
extensions that may call it.
A possible argument against printing the time to create the plan is that
unless it was created when running EXPLAIN we will not know it. I do not
think we want to always measure the time it took to generate a plan due
to slow clocks on some architectures. Also I feel that such a patch
would be more invasive.
Just my reasoning for the current solution. I welcome any opinions about
how to print planning time for prepared statements since I am not a
heavy user of them.
--
Andreas Karlsson
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 7097eff..34ca209
*** a/src/backend/commands/explain.c
--- b/src/backend/commands/explain.c
*************** ExplainOneQuery(Query *query, IntoClause
*** 318,330 ****
(*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);
}
}
--- 318,336 ----
(*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);
}
}
*************** ExplainOneUtility(Node *utilityStmt, Int
*** 401,407 ****
*/
void
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
! const char *queryString, ParamListInfo params)
{
DestReceiver *dest;
QueryDesc *queryDesc;
--- 407,414 ----
*/
void
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
! const char *queryString, ParamListInfo params,
! instr_time planduration)
{
DestReceiver *dest;
QueryDesc *queryDesc;
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 482,487 ****
--- 489,505 ----
/* Create textual dump of plan tree */
ExplainPrintPlan(es, queryDesc);
+ if (es->costs)
+ {
+ 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)
{
diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c
new file mode 100644
index 49c4093..73116cb
*** 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 planstart, planduration;
/* Look it up in the hash table */
entry = FetchPreparedStatement(execstmt->name, true);
*************** ExplainExecuteQuery(ExecuteStmt *execstm
*** 654,662 ****
--- 655,668 ----
queryString, estate);
}
+ INSTR_TIME_SET_CURRENT(planstart);
+
/* Replan if needed, and acquire a transient refcount */
cplan = GetCachedPlan(entry->plansource, paramLI, true);
+ INSTR_TIME_SET_CURRENT(planduration);
+ INSTR_TIME_SUBTRACT(planduration, planstart);
+
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);
--- 671,677 ----
PlannedStmt *pstmt = (PlannedStmt *) lfirst(p);
if (IsA(pstmt, PlannedStmt))
! ExplainOnePlan(pstmt, into, es, query_string, paramLI, planduration);
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 9e71206..c64a70d
*** 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);
--- 67,74 ----
const char *queryString, ParamListInfo params);
extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
! ExplainState *es, const char *queryString,
! ParamListInfo params, instr_time planduration);
extern void ExplainPrintPlan(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
