From 1e8795751f0ad0131d644adf02f0a3e7029712d7 Mon Sep 17 00:00:00 2001 From: Ashutosh Bapat Date: Wed, 8 Mar 2017 10:44:40 +0530 Subject: [PATCH 2/2] Print planning time in EXPLAIN EXECUTE. When a PREPAREd statement is EXPLAINed using EXPLAIN EXECUTE, it involves fetching a cached plan or replanning the statement if cached plan is not available or is invalid. There is no way to display time taken for this activity in EXPLAIN EXECUTE. Add support to display this time as planning time in EXPLAIN EXECUTE output. Include time spent in evaluating parameters in planning time, since the planner may create a customized plan for each different parameter set. --- doc/src/sgml/ref/explain.sgml | 5 ++++- src/backend/commands/prepare.c | 9 ++++++++- 2 files changed, 12 insertions(+), 2 deletions(-) diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index 4d83359..c63728d 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -202,7 +202,10 @@ ROLLBACK; Include planning time and execution time. Execution time is included - when ANALYZE is enabled. + when ANALYZE is enabled. Planning time in + EXPLAIN EXECUTE includes the time required to fetch + the plan from the cache and the time required for re-planning, if + necessary. It defaults to TRUE when ANALYZE is enabled. Otherwise it defaults to FALSE. diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c index 116ed67..1cf0d2b 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -638,6 +638,10 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, ListCell *p; ParamListInfo paramLI = NULL; EState *estate = NULL; + instr_time planstart; + instr_time planduration; + + INSTR_TIME_SET_CURRENT(planstart); /* Look it up in the hash table */ entry = FetchPreparedStatement(execstmt->name, true); @@ -666,6 +670,9 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, /* 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 */ @@ -674,7 +681,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, PlannedStmt *pstmt = castNode(PlannedStmt, lfirst(p)); if (pstmt->commandType != CMD_UTILITY) - ExplainOnePlan(pstmt, into, es, query_string, paramLI, NULL); + ExplainOnePlan(pstmt, into, es, query_string, paramLI, &planduration); else ExplainOneUtility(pstmt->utilityStmt, into, es, query_string, paramLI); -- 1.7.9.5