File 00008-planner_timing.patch of Package postgresql10
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 59b95f6f4b..18bfa86cf7 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -16,6 +16,7 @@
#include "commands/explain.h"
#include "executor/instrument.h"
+#include "optimizer/planner.h"
#include "utils/guc.h"
PG_MODULE_MAGIC;
@@ -321,6 +322,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
if (msec >= auto_explain_log_min_duration)
{
ExplainState *es = NewExplainState();
+ instr_time planduration = queryDesc->plannedstmt->planDuration;
es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
es->verbose = auto_explain_log_verbose;
@@ -354,8 +356,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
* often result in duplication.
*/
ereport(LOG,
- (errmsg("duration: %.3f ms plan:\n%s",
- msec, es->str->data),
+ (errmsg("duration: %.3f ms planning: %.3f ms plan:\n%s",
+ msec, 1000 * INSTR_TIME_GET_DOUBLE(planduration),
+ es->str->data),
errhidestmt(true)));
pfree(es->str->data);
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 953e74d73c..1bfcbc1e45 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -358,20 +358,13 @@ ExplainOneQuery(Query *query, int cursorOptions,
else
{
PlannedStmt *plan;
- instr_time planstart,
- planduration;
-
- INSTR_TIME_SET_CURRENT(planstart);
/* plan the query */
plan = pg_plan_query(query, cursorOptions, params);
- INSTR_TIME_SET_CURRENT(planduration);
- INSTR_TIME_SUBTRACT(planduration, planstart);
-
/* run it (if needed) and produce output */
ExplainOnePlan(plan, into, es, queryString, params, queryEnv,
- &planduration);
+ &plan->planDuration);
}
}
diff --git a/src/backend/optimizer/plan/planner.c b/src/backend/optimizer/plan/planner.c
index a8a025cb85..baa9678dc6 100644
--- a/src/backend/optimizer/plan/planner.c
+++ b/src/backend/optimizer/plan/planner.c
@@ -202,11 +202,22 @@ PlannedStmt *
planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
{
PlannedStmt *result;
+ instr_time planstart,
+ planduration;
+
+ INSTR_TIME_SET_CURRENT(planstart);
if (planner_hook)
result = (*planner_hook) (parse, cursorOptions, boundParams);
else
result = standard_planner(parse, cursorOptions, boundParams);
+
+ INSTR_TIME_SET_CURRENT(planduration);
+ INSTR_TIME_SUBTRACT(planduration, planstart);
+
+ /* Record time spent on hooks and standard_planner() */
+ result->planDuration = planduration;
+
return result;
}
diff --git a/src/include/nodes/plannodes.h b/src/include/nodes/plannodes.h
index a382331f41..9dac43a41b 100644
--- a/src/include/nodes/plannodes.h
+++ b/src/include/nodes/plannodes.h
@@ -19,6 +19,7 @@
#include "nodes/bitmapset.h"
#include "nodes/lockoptions.h"
#include "nodes/primnodes.h"
+#include "portability/instr_time.h"
/* ----------------------------------------------------------------
@@ -93,6 +94,8 @@ typedef struct PlannedStmt
Node *utilityStmt; /* non-null if this is utility stmt */
+ instr_time planDuration; /* time spent on planning */
+
/* statement location in source string (copied from Query) */
int stmt_location; /* start location, or -1 if unknown */
int stmt_len; /* length in bytes; 0 means "rest of string" */