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.
http://www.postgresql.org/message-id/cacfv+pknembqyjpcqrgsvmc_hvrgai3d_ge893n8qbx+ymh...@mail.gmail.com
--
Andreas Karlsson
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);
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
