Planning time in explain/explain analyze
Hi,
A user asked in -performance[1] if there is a way to measure the
planning time. Other than measuring it in the client I do not think
there is so I quickly hacked a patched which adds "Planning time" to the
outputs of EXPLAIN and EXPLAIN ANALYZE.
Is this something useful? I think it is, since plan time can become an
issue for complex queries.
A couple of questions about the path: Should the planning time be added
to both EXPLAIN and EXPLAIN ANALYZE? And is the output obvious enough?
The patch does not include any changes to documentation or tests. I will
fix that if people think this patch is useful.
$ EXPLAIN SELECT * FROM pg_stat_activity;
QUERY PLAN
--------------------------------------------------------------------------------------------------
Nested Loop (cost=1.15..2.69 rows=1 width=337)
-> Hash Join (cost=1.02..2.41 rows=1 width=273)
Hash Cond: (s.usesysid = u.oid)
-> Function Scan on pg_stat_get_activity s (cost=0.00..1.00
rows=100 width=209)
-> Hash (cost=1.01..1.01 rows=1 width=68)
-> Seq Scan on pg_authid u (cost=0.00..1.01 rows=1
width=68)
-> Index Scan using pg_database_oid_index on pg_database d
(cost=0.13..0.27 rows=1 width=68)
Index Cond: (oid = s.datid)
Planning time: 0.258 ms
(9 rows)
$ EXPLAIN ANALYZE SELECT * FROM pg_stat_activity;
QUERY
PLAN
--------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=1.15..2.69 rows=1 width=337) (actual
time=0.094..0.096 rows=1 loops=1)
-> Hash Join (cost=1.02..2.41 rows=1 width=273) (actual
time=0.078..0.079 rows=1 loops=1)
Hash Cond: (s.usesysid = u.oid)
-> Function Scan on pg_stat_get_activity s (cost=0.00..1.00
rows=100 width=209) (actual time=0.053..0.053 rows=1 loops=1)
-> Hash (cost=1.01..1.01 rows=1 width=68) (actual
time=0.014..0.014 rows=1 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
-> Seq Scan on pg_authid u (cost=0.00..1.01 rows=1
width=68) (actual time=0.007..0.009 rows=1 loops=1)
-> Index Scan using pg_database_oid_index on pg_database d
(cost=0.13..0.27 rows=1 width=68) (actual time=0.009..0.010 rows=1 loops=1)
Index Cond: (oid = s.datid)
Planning time: 0.264 ms
Total runtime: 0.158 ms
(11 rows)
Links
1.
/messages/by-id/CACfv+pKNEmbQyJPCqRGsVmc_HvRGAi3d_Ge893N8qbX+ymhodA@mail.gmail.com
--
Andreas Karlsson
Attachments:
explainplantime-v1.difftext/x-patch; name=explainplantime-v1.diffDownload
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
new file mode 100644
index 9969a25..42425fa
*** 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,412 ****
*/
void
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
! const char *queryString, ParamListInfo params)
{
DestReceiver *dest;
QueryDesc *queryDesc;
instr_time starttime;
double totaltime = 0;
int eflags;
int instrument_option = 0;
--- 407,420 ----
*/
void
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
! const char *queryString, ParamListInfo params,
! instr_time planduration)
{
DestReceiver *dest;
QueryDesc *queryDesc;
instr_time starttime;
double totaltime = 0;
+ double plantime = INSTR_TIME_GET_DOUBLE(planduration);
int eflags;
int instrument_option = 0;
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 482,487 ****
--- 490,500 ----
/* Create textual dump of plan tree */
ExplainPrintPlan(es, queryDesc);
+ 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 62208eb..48e1ea8
*** 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 ca213d7..e4fc235
*** 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);
Andreas Karlsson <andreas@proxel.se> writes:
The patch does not include any changes to documentation or tests. I will
fix that if people think this patch is useful.
I take it you've not tried the regression tests with this.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 23-12-2013 22:12, Andreas Karlsson wrote:
A user asked in -performance[1] if there is a way to measure the
planning time. Other than measuring it in the client I do not think
there is so I quickly hacked a patched which adds "Planning time" to the
outputs of EXPLAIN and EXPLAIN ANALYZE.Is this something useful? I think it is, since plan time can become an
issue for complex queries.
Yes, but a couple of years ago, this same feature was proposed as a
module [1]/messages/by-id/BANLkTi=sxKTCTcv9hsACu38eaj=fW_4OMA@mail.gmail.com[2]https://github.com/umitanuki/planinstr. I'm not sure if it is worth including as an additional
module or not. Opinions?
[1]: /messages/by-id/BANLkTi=sxKTCTcv9hsACu38eaj=fW_4OMA@mail.gmail.com
/messages/by-id/BANLkTi=sxKTCTcv9hsACu38eaj=fW_4OMA@mail.gmail.com
[2]: https://github.com/umitanuki/planinstr
--
Euler Taveira Timbira - http://www.timbira.com.br/
PostgreSQL: Consultoria, Desenvolvimento, Suporte 24x7 e Treinamento
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 12/24/2013 03:33 AM, Tom Lane wrote:
Andreas Karlsson <andreas@proxel.se> writes:
The patch does not include any changes to documentation or tests. I will
fix that if people think this patch is useful.I take it you've not tried the regression tests with this.
Yeah, forgot to mention that we need some way to disable it in the
tests. Either by not having it included in EXPLAIN or by adding an
option to turn it off. Any suggestion on which would be preferable?
--
Andreas Karlsson
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Mon, Dec 23, 2013 at 9:54 PM, Andreas Karlsson <andreas@proxel.se> wrote:
On 12/24/2013 03:33 AM, Tom Lane wrote:
Andreas Karlsson <andreas@proxel.se> writes:
The patch does not include any changes to documentation or tests. I will
fix that if people think this patch is useful.I take it you've not tried the regression tests with this.
Yeah, forgot to mention that we need some way to disable it in the tests.
Either by not having it included in EXPLAIN or by adding an option to turn
it off. Any suggestion on which would be preferable?
I would be tempted to display it only if (COSTS OFF) is not given. As
far as I can tell, the major use case for (COSTS OFF) is when you want
the output to be stable so you can include it in a regression test.
Technically speaking, planning time is not a cost, but I'm not sure I
could live with myself if we forced everyone to write (COSTS OFF,
PLANNING_TIME OFF). And I don't think much of the idea of only
including planning time when ANALYZE is used, because you don't have
to want to run the query to want to know how long it took to plan.
Also, +1 for this general concept. Great idea.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Robert Haas <robertmhaas@gmail.com> writes:
On Mon, Dec 23, 2013 at 9:54 PM, Andreas Karlsson <andreas@proxel.se> wrote:
Yeah, forgot to mention that we need some way to disable it in the tests.
Either by not having it included in EXPLAIN or by adding an option to turn
it off. Any suggestion on which would be preferable?
I would be tempted to display it only if (COSTS OFF) is not given.
Yeah. The alternatives seem to be:
1. Change a lot of regression tests. This would be a serious PITA,
not so much for the one-time cost as for every time we needed to
back-patch a regression test that includes explain output. -1.
2. Don't display the planning time by default, necessitating a new
PLANNING_TIME ON option. This has backwards compatibility to
recommend it, but not much else.
3. Let COSTS OFF suppress it.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Mon, Dec 23, 2013 at 10:47 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Robert Haas <robertmhaas@gmail.com> writes:
On Mon, Dec 23, 2013 at 9:54 PM, Andreas Karlsson <andreas@proxel.se> wrote:
Yeah, forgot to mention that we need some way to disable it in the tests.
Either by not having it included in EXPLAIN or by adding an option to turn
it off. Any suggestion on which would be preferable?I would be tempted to display it only if (COSTS OFF) is not given.
Yeah. The alternatives seem to be:
1. Change a lot of regression tests. This would be a serious PITA,
not so much for the one-time cost as for every time we needed to
back-patch a regression test that includes explain output. -1.2. Don't display the planning time by default, necessitating a new
PLANNING_TIME ON option. This has backwards compatibility to
recommend it, but not much else.3. Let COSTS OFF suppress it.
Another option would be to not display it by default, but make VERBOSE
show it. However, I think making it controlled by COSTS is a better
fit.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 12/23/13, 8:12 PM, Andreas Karlsson wrote:
A user asked in -performance[1] if there is a way to measure the
planning time.
log_planner_stats
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 12/24/2013 02:31 PM, Peter Eisentraut wrote:
On 12/23/13, 8:12 PM, Andreas Karlsson wrote:
A user asked in -performance[1] if there is a way to measure the
planning time.log_planner_stats
Thanks for the suggestion, I will use that if I need to know the plan
times. But I do not think this is as useful as having it in the EXPLAIN
output.
--
Andreas Karlsson
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 12/24/2013 05:09 AM, Robert Haas wrote:
Yeah. The alternatives seem to be:
1. Change a lot of regression tests. This would be a serious PITA,
not so much for the one-time cost as for every time we needed to
back-patch a regression test that includes explain output. -1.2. Don't display the planning time by default, necessitating a new
PLANNING_TIME ON option. This has backwards compatibility to
recommend it, but not much else.3. Let COSTS OFF suppress it.
Another option would be to not display it by default, but make VERBOSE
show it. However, I think making it controlled by COSTS is a better
fit.
After some thinking COSTS OFF really seems to be the best option. I have
changed this in the patch and will submit a patch with updated
documentation as soon as I get the time. Adding "Planning time" to all
explain outputs (only 37 of them) in the documentation should not
clutter anything too much.
--
Andreas Karlsson
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
New version of the patch with updated documentation and which does not
display the planning time when the COSTS are off.
I will add it to the next commitfest.
--
Andreas Karlsson
Attachments:
explainplantime-v2.difftext/x-patch; name=explainplantime-v2.diffDownload
diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml
new file mode 100644
index 2af1738..240a3d5
*** 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,175 ----
</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. We will not include this line in later examples in
+ this section.
+ </para>
+
+ <para>
Returning to our example:
<screen>
*************** WHERE t1.unique1 < 10 AND t1.unique2
*** 564,569 ****
--- 572,578 ----
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 ****
--- 621,627 ----
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 ****
--- 645,651 ----
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 ****
--- 668,674 ----
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 ****
--- 687,693 ----
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 ****
--- 718,724 ----
-> 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 ****
--- 746,752 ----
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 ****
--- 832,838 ----
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 9969a25..ab8b236
*** 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 62208eb..48e1ea8
*** 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 ca213d7..e4fc235
*** 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);
On Sat, Dec 28, 2013 at 11:32 PM, Andreas Karlsson <andreas@proxel.se> wrote:
New version of the patch with updated documentation and which does not
display the planning time when the COSTS are off.I will add it to the next commitfest.
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.
Also, I am inclined to think we ought to update the examples, rather
than say this:
+ rewriting and parsing. We will not include this line in later examples in
+ this section.
+ </para>--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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.
Since we support re-planning of prepared statements I would argue the
most useful thing is to print the time it took to fetch the old plan or
the create a new one as the planning time, but I am not a heavy user of
prepared statements.
Also, I am inclined to think we ought to update the examples, rather
than say this:+ rewriting and parsing. We will not include this line in later examples in + this section. + </para>
Ok, I will fix this in the next version of the patch.
--
Andreas Karlsson
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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
Attachments:
explainplantime-v3.difftext/x-patch; name=explainplantime-v3.diffDownload
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);
Andreas, Robert,
* Andreas Karlsson (andreas@proxel.se) wrote:
A patch with updated documentation is attached.
Thanks for working on this!
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.
Agreed, and really, it'd be nice to know *both*. If we're worried about
the timing cost when going through a no-op GetCachedPlan(), then perhaps
we don't add that, but if we actually *do* re-plan, it'd be handy to
know that and to know the timing it took.
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.
Agreed.
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.
This is perhaps the biggest point against- if we keep it this way...
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.
The slow-clock argument is really quite frustrating for those of us who
are looking to add more and more metrics to PG. We're nowhere near the
level that we need to be and it shows (particularly for users coming
from $OTHER-RDBMS). Perhaps we should try and come up with a solution
to address those cases (turn off metrics ala turning off stats?) while
not preventing us from gathering metrics on more reasonable systems.
Thanks,
Stephen
On Thu, Jan 9, 2014 at 1:50 PM, Stephen Frost <sfrost@snowman.net> wrote:
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.The slow-clock argument is really quite frustrating for those of us who
are looking to add more and more metrics to PG.
Especially since implementing gettimeofday quickly is a solved problem
on most architectures.
However I don't see the issue here. Two gettimeofday calls per query
plan is not really going to hurt even on systems where it's slow. The
problems we run into are explain analyze which runs getimeofday twice
for every node for every tuple processed. For cpu-bound queries that's
can become the dominant cost.
The only way two gettimeofday calls per query plan becomes an issue is
if you're executing non-cached queries repeatedly on data that's
entirely in ram. That means the query processing is entirely cpu-bound
and adding two syscalls could actually be noticeable. The mitigation
strategy would be to prepare and cache the query handle to execute it
again.
We're nowhere near the
level that we need to be and it shows (particularly for users coming
from $OTHER-RDBMS). Perhaps we should try and come up with a solution
to address those cases (turn off metrics ala turning off stats?) while
not preventing us from gathering metrics on more reasonable systems.
--
greg
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Greg Stark <stark@mit.edu> writes:
However I don't see the issue here. Two gettimeofday calls per query
plan is not really going to hurt even on systems where it's slow.
I tend to agree with this, especially if the calls only occur when the
user asks for the information (ie, does an EXPLAIN rather than just
executing the query).
The only way two gettimeofday calls per query plan becomes an issue is
if you're executing non-cached queries repeatedly on data that's
entirely in ram. That means the query processing is entirely cpu-bound
and adding two syscalls could actually be noticeable. The mitigation
strategy would be to prepare and cache the query handle to execute it
again.
This point weighs against the proposal that we time the work to fetch
a previously-prepared query plan; if we do that then the "mitigation
strategy" doesn't mitigate anything.
In short then, I think we should just add this to EXPLAIN and be done.
-1 for sticking the info into PlannedStmt or anything like that.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Jan 9, 2014 at 9:14 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
In short then, I think we should just add this to EXPLAIN and be done.
-1 for sticking the info into PlannedStmt or anything like that.
I'm confused. I thought I was arguing to support your suggestion that
the initial planning store the time in the cached plan and explain
should output the time the original planning took.
--
greg
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Greg Stark <stark@mit.edu> writes:
On Thu, Jan 9, 2014 at 9:14 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
In short then, I think we should just add this to EXPLAIN and be done.
-1 for sticking the info into PlannedStmt or anything like that.
I'm confused. I thought I was arguing to support your suggestion that
the initial planning store the time in the cached plan and explain
should output the time the original planning took.
Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
planning cycle, explain or no? I was thinking more of just putting the
timing calls into explain.c.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Jan 9, 2014 at 11:45 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Greg Stark <stark@mit.edu> writes:
On Thu, Jan 9, 2014 at 9:14 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
In short then, I think we should just add this to EXPLAIN and be done.
-1 for sticking the info into PlannedStmt or anything like that.I'm confused. I thought I was arguing to support your suggestion that
the initial planning store the time in the cached plan and explain
should output the time the original planning took.Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
planning cycle, explain or no? I was thinking more of just putting the
timing calls into explain.c.
Currently the patch includes changes to prepare.c which is what seems
odd to me. I think it'd be fine to say, hey, I can't give you the
planning time in this EXPLAIN ANALYZE because I just used a cached
plan and did not re-plan. But saying, hey, the planning time is
$TINYVALUE, when what we really mean is that looking up the
previously-cached plan took only that long, seems actively misleading
to me.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
* Robert Haas (robertmhaas@gmail.com) wrote:
Currently the patch includes changes to prepare.c which is what seems
odd to me. I think it'd be fine to say, hey, I can't give you the
planning time in this EXPLAIN ANALYZE because I just used a cached
plan and did not re-plan. But saying, hey, the planning time is
$TINYVALUE, when what we really mean is that looking up the
previously-cached plan took only that long, seems actively misleading
to me.
My thought, at least, was to always grab the planning time and then
provide it for explain and/or explain analyze, and then for re-plan
cases, indicate if a cached plan was returned, if a replan happened, and
if a replan happened, what the old plan time and the new plan time was.
I don't think it makes any sense to report on the time returned from
pulling a previously-cached plan.
I understand that it's not completely free to track the plan time for
every query but I'm in the camp that says "we need better metrics and
information for 99% of what we do" and I'd like to see us eventually
able to track average plan time (maybe on a per-query basis..), average
run-time, how many times we do a hashjoin, mergejoin, the number of
records in/out of each, memory usage, etc, etc.. I don't think we need
per-tuple timing information. I certainly wouldn't want to try and
collect all of this through shared memory or our existing stats
collector.
Thanks,
Stephen
On 01/13/2014 09:06 PM, Stephen Frost wrote:
My thought, at least, was to always grab the planning time and then
provide it for explain and/or explain analyze, and then for re-plan
cases, indicate if a cached plan was returned, if a replan happened, and
if a replan happened, what the old plan time and the new plan time was.
I like this solution due it is correctness and that all information is
included. But I also think my original path was fine in how it in its
simplicity solved the problem without adding any overhead in the
non-EXPLAIN case. Either solution would be fine by me. If the consensus
is that we want to always measure it I will look at implementing that
instead.
--
Andreas Karlsson
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Robert Haas <robertmhaas@gmail.com> writes:
On Thu, Jan 9, 2014 at 11:45 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
planning cycle, explain or no? I was thinking more of just putting the
timing calls into explain.c.
Currently the patch includes changes to prepare.c which is what seems
odd to me. I think it'd be fine to say, hey, I can't give you the
planning time in this EXPLAIN ANALYZE because I just used a cached
plan and did not re-plan. But saying, hey, the planning time is
$TINYVALUE, when what we really mean is that looking up the
previously-cached plan took only that long, seems actively misleading
to me.
Meh. Why? This would only come into play for EXPLAIN EXECUTE stmtname.
I don't think users would be surprised to see a report of minimal planning
time for that. In fact, it might be a good thing, as it would make it
easier to tell the difference between whether you were seeing a generic
plan or a custom plan for the prepared statement.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Mon, Jan 13, 2014 at 3:23 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Robert Haas <robertmhaas@gmail.com> writes:
On Thu, Jan 9, 2014 at 11:45 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
planning cycle, explain or no? I was thinking more of just putting the
timing calls into explain.c.Currently the patch includes changes to prepare.c which is what seems
odd to me. I think it'd be fine to say, hey, I can't give you the
planning time in this EXPLAIN ANALYZE because I just used a cached
plan and did not re-plan. But saying, hey, the planning time is
$TINYVALUE, when what we really mean is that looking up the
previously-cached plan took only that long, seems actively misleading
to me.Meh. Why? This would only come into play for EXPLAIN EXECUTE stmtname.
I don't think users would be surprised to see a report of minimal planning
time for that. In fact, it might be a good thing, as it would make it
easier to tell the difference between whether you were seeing a generic
plan or a custom plan for the prepared statement.
It would also make it easier to be wrong. If you want to display that
information explicitly, fine. But asking the user to use the elapsed
time to guess whether or not we really planned anything is just going
to confuse people who don't have enough experience with the system to
know what the boundary is between the largest time that could be a
cache lookup and the smallest time that could be real planning
activity. And that means virtually everyone, me included.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Robert Haas <robertmhaas@gmail.com> writes:
On Mon, Jan 13, 2014 at 3:23 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Meh. Why? This would only come into play for EXPLAIN EXECUTE stmtname.
I don't think users would be surprised to see a report of minimal planning
time for that. In fact, it might be a good thing, as it would make it
easier to tell the difference between whether you were seeing a generic
plan or a custom plan for the prepared statement.
It would also make it easier to be wrong. If you want to display that
information explicitly, fine. But asking the user to use the elapsed
time to guess whether or not we really planned anything is just going
to confuse people who don't have enough experience with the system to
know what the boundary is between the largest time that could be a
cache lookup and the smallest time that could be real planning
activity. And that means virtually everyone, me included.
If you're saying that you'd like EXPLAIN to explicitly mention whether
the plan was cached or custom, I don't have any great complaint about
that. I'm just not seeing how you arrive at the conclusion that we
mustn't report the amount of time EXPLAIN spent to get the plan.
If we do what you're proposing we'll just have a different set of confused
users, who will be wondering how EXPLAIN could have managed to spend
100 msec planning something when the EXPLAIN only took 10 msec in toto
according to psql.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Mon, Jan 13, 2014 at 3:40 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Robert Haas <robertmhaas@gmail.com> writes:
On Mon, Jan 13, 2014 at 3:23 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Meh. Why? This would only come into play for EXPLAIN EXECUTE stmtname.
I don't think users would be surprised to see a report of minimal planning
time for that. In fact, it might be a good thing, as it would make it
easier to tell the difference between whether you were seeing a generic
plan or a custom plan for the prepared statement.It would also make it easier to be wrong. If you want to display that
information explicitly, fine. But asking the user to use the elapsed
time to guess whether or not we really planned anything is just going
to confuse people who don't have enough experience with the system to
know what the boundary is between the largest time that could be a
cache lookup and the smallest time that could be real planning
activity. And that means virtually everyone, me included.If you're saying that you'd like EXPLAIN to explicitly mention whether
the plan was cached or custom, I don't have any great complaint about
that. I'm just not seeing how you arrive at the conclusion that we
mustn't report the amount of time EXPLAIN spent to get the plan.
If we do what you're proposing we'll just have a different set of confused
users, who will be wondering how EXPLAIN could have managed to spend
100 msec planning something when the EXPLAIN only took 10 msec in toto
according to psql.
What I'm saying is that if EXPLAIN reports something that's labelled
"Planning Time", it should *be* the planning time, and not anything
else. When we retrieve a plan from cache, it would be sensible not to
report the planning time at all, and IMHO it would also be sensible to
report the time it actually took to plan whenever we originally did
it. But reporting a value that is not the planning time and calling
it the planning time does not seem like a good idea to me.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 01/13/2014 09:48 PM, Robert Haas wrote:
What I'm saying is that if EXPLAIN reports something that's labelled
"Planning Time", it should *be* the planning time, and not anything
else. When we retrieve a plan from cache, it would be sensible not to
report the planning time at all, and IMHO it would also be sensible to
report the time it actually took to plan whenever we originally did
it. But reporting a value that is not the planning time and calling
it the planning time does not seem like a good idea to me.
Here is a patch which only prints when "Planning time" when a prepared
statment actually planned a query. I do not really like how I check for
if it was replanned, but I tried to avoid making changes in plancache.c.
Does this idea look ok?
--
Andreas Karlsson
Attachments:
explainplantime-v4.difftext/x-patch; name=explainplantime-v4.diffDownload
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..02809ae
*** 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, false);
}
}
*************** 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 cached)
{
DestReceiver *dest;
QueryDesc *queryDesc;
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 484,489 ****
--- 491,507 ----
/* Create textual dump of plan tree */
ExplainPrintPlan(es, queryDesc);
+ if (es->costs && !cached)
+ {
+ 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..4ddffb8
*** a/src/backend/commands/prepare.c
--- b/src/backend/commands/prepare.c
*************** ExplainExecuteQuery(ExecuteStmt *execstm
*** 624,634 ****
{
PreparedStatement *entry;
const char *query_string;
! CachedPlan *cplan;
List *plan_list;
ListCell *p;
ParamListInfo paramLI = NULL;
EState *estate = NULL;
/* Look it up in the hash table */
entry = FetchPreparedStatement(execstmt->name, true);
--- 624,635 ----
{
PreparedStatement *entry;
const char *query_string;
! CachedPlan *cplan, *lastplan;
List *plan_list;
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,675 ----
queryString, estate);
}
+ lastplan = entry->plansource->gplan;
+ if (lastplan)
+ lastplan->refcount++;
+
+ 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);
+
+ if (lastplan)
+ ReleaseCachedPlan(lastplan, false);
+
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);
--- 678,684 ----
PlannedStmt *pstmt = (PlannedStmt *) lfirst(p);
if (IsA(pstmt, PlannedStmt))
! ExplainOnePlan(pstmt, into, es, query_string, paramLI, planduration, cplan == lastplan);
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..fb67cda
*** 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,74 ----
const char *queryString, ParamListInfo params);
extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
! ExplainState *es, const char *queryString,
! ParamListInfo params, instr_time planduration, bool cached);
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
On Thu, Jan 9, 2014 at 11:45 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Greg Stark <stark@mit.edu> writes:
On Thu, Jan 9, 2014 at 9:14 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
In short then, I think we should just add this to EXPLAIN and be done.
-1 for sticking the info into PlannedStmt or anything like that.I'm confused. I thought I was arguing to support your suggestion that
the initial planning store the time in the cached plan and explain
should output the time the original planning took.Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
planning cycle, explain or no? I was thinking more of just putting the
timing calls into explain.c.
The problem is that you really can't do it that way.
ExplainOneQuery() is a good place to add the timing calls in general,
but ExplainExecuteQuery() in prepare.c never calls it; it does
GetCachedPlan(), which ultimately calls pg_plan_query() after about
four levels of indirection, and then passes the resulting plan
directly to ExplainOnePlan(). So if you only add timing calls to
explain.c, you can't handle anything that goes through
ExplainExecuteQuery(), which is confusingly in prepare.c rather than
explain.c.
One reasonably principled solution is to just give up on showing the
plan time for prepared queries altogether. If we don't want to adopt
that approach, then I think the right way to do this is to add a "bool
timing" argument to pg_plan_query(). When set, pg_plan_query()
measures the time before and after calling planner() and stores it in
the PlannedStmt. It could alternatively return it via an out
parameter, but that's not very convenient for prepare.c, which is
planning a *list* of queries and therefore presumably needs planning
time for each one.
I'm not bent on this design; I just don't see another way to do this
that has any conceptual integrity. Having the normal path measure the
time required to call pg_plan_query() and the prepared path measure
the time required to call GetCachedPlan() which may or may not
eventually call pg_plan_query() one or more times doesn't seem like a
good design, particularly if it's motivated solely by a desire to
minimize the code footprint of what's never going to be a very large
patch. The most recent version of the patch tries to finesse this
issue by determining whether GetCachedPlan() actually did anything; I
think the way it does that is likely an abstraction violation that we
don't want to countenance. But even if we're OK with that, it still
munges the planning times of multiple queries into a single number,
while the normal case separates them. It just seems like we're going
to a lot of trouble here to avoid the obvious design, and I'm not sure
why.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Robert Haas <robertmhaas@gmail.com> writes:
On Thu, Jan 9, 2014 at 11:45 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Uh, no, wasn't my suggestion. Doesn't that design imply measuring *every*
planning cycle, explain or no? I was thinking more of just putting the
timing calls into explain.c.
The problem is that you really can't do it that way.
ExplainOneQuery() is a good place to add the timing calls in general,
but ExplainExecuteQuery() in prepare.c never calls it; it does
GetCachedPlan(), which ultimately calls pg_plan_query() after about
four levels of indirection, and then passes the resulting plan
directly to ExplainOnePlan(). So if you only add timing calls to
explain.c, you can't handle anything that goes through
ExplainExecuteQuery(), which is confusingly in prepare.c rather than
explain.c.
Yeah, the factoring between explain.c and prepare.c has never been very
nice. I'm not sure what would be a cleaner design offhand, but I suspect
there is one.
One reasonably principled solution is to just give up on showing the
plan time for prepared queries altogether.
That would work for me, especially given the lack of clarity about what
ought to be measured in that case.
If we don't want to adopt
that approach, then I think the right way to do this is to add a "bool
timing" argument to pg_plan_query(). When set, pg_plan_query()
measures the time before and after calling planner() and stores it in
the PlannedStmt.
I don't find that to be exactly a "low footprint" change; it's dumping
an EXPLAIN concern all over a public API *and* a public data structure.
It might be roughly comparable in terms of number of lines in the patch,
but in terms of modularity and abstraction it's not comparable in the
least.
I'm for doing the measurement in ExplainOneQuery() and not printing
anything in code paths that don't go through there.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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
Attachments:
explainplantime-v5.difftext/x-patch; name=explainplantime-v5.diffDownload
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);
On Wed, Jan 29, 2014 at 2:21 PM, Andreas Karlsson <andreas@proxel.se> wrote:
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.
Cool. I propose adding one parameter rather than two to
ExplainOnePlan() and making it of type instr_time * rather than
passing an instr_time and a bool. If you don't want to include the
planning time, pass NULL; if you do, pass a pointer to the instr_time
you want to print. I think that would come out slightly neater than
what you have here.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 01/29/2014 09:01 PM, Robert Haas wrote:
Cool. I propose adding one parameter rather than two to
ExplainOnePlan() and making it of type instr_time * rather than
passing an instr_time and a bool. If you don't want to include the
planning time, pass NULL; if you do, pass a pointer to the instr_time
you want to print. I think that would come out slightly neater than
what you have here.
Excellent suggestion, thanks! New patch attached.
/Andreas
Attachments:
explainplantime-v6.difftext/x-patch; name=explainplantime-v6.diffDownload
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..08f3167
*** 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);
}
}
*************** 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,
! const instr_time *planduration)
{
DestReceiver *dest;
QueryDesc *queryDesc;
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 484,489 ****
--- 491,507 ----
/* 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
new file mode 100644
index 49c4093..65431b7
*** a/src/backend/commands/prepare.c
--- b/src/backend/commands/prepare.c
*************** 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);
--- 665,671 ----
PlannedStmt *pstmt = (PlannedStmt *) lfirst(p);
if (IsA(pstmt, PlannedStmt))
! 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
new file mode 100644
index e097710..3488be3
*** 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,74 ----
const char *queryString, ParamListInfo params);
extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
! 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);
On Wed, Jan 29, 2014 at 3:13 PM, Andreas Karlsson <andreas@proxel.se> wrote:
On 01/29/2014 09:01 PM, Robert Haas wrote:
Cool. I propose adding one parameter rather than two to
ExplainOnePlan() and making it of type instr_time * rather than
passing an instr_time and a bool. If you don't want to include the
planning time, pass NULL; if you do, pass a pointer to the instr_time
you want to print. I think that would come out slightly neater than
what you have here.Excellent suggestion, thanks! New patch attached.
Committed with minor doc changes.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 01/29/2014 10:10 PM, Robert Haas wrote:
Committed with minor doc changes.
Thanks!
/Andreas
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers