diff --git a/contrib/auto_explain/auto_explain.c contrib/auto_explain/auto_explain.c index a47e7f0c295..b00e1a0ec5d 100644 --- a/contrib/auto_explain/auto_explain.c +++ contrib/auto_explain/auto_explain.c @@ -18,6 +18,7 @@ #include "commands/explain.h" #include "executor/instrument.h" #include "jit/jit.h" +#include "optimizer/planner.h" #include "utils/guc.h" PG_MODULE_MAGIC; @@ -335,6 +336,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; @@ -370,8 +372,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 src/backend/commands/explain.c index 799a22e9d55..670c2d6ceb7 100644 --- a/src/backend/commands/explain.c +++ src/backend/commands/explain.c @@ -356,20 +356,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 src/backend/optimizer/plan/planner.c index 6a3f4667e89..caac90bfac0 100644 --- a/src/backend/optimizer/plan/planner.c +++ src/backend/optimizer/plan/planner.c @@ -256,11 +256,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 src/include/nodes/plannodes.h index fae16500fe2..ca2bedc89d2 100644 --- a/src/include/nodes/plannodes.h +++ src/include/nodes/plannodes.h @@ -20,6 +20,7 @@ #include "nodes/bitmapset.h" #include "nodes/lockoptions.h" #include "nodes/primnodes.h" +#include "portability/instr_time.h" /* ---------------------------------------------------------------- @@ -96,6 +97,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" */