diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml index 2af1738576a..482490ba78c 100644 --- a/doc/src/sgml/perform.sgml +++ b/doc/src/sgml/perform.sgml @@ -89,6 +89,7 @@ EXPLAIN SELECT * FROM tenk1; QUERY PLAN ------------------------------------------------------------- Seq Scan on tenk1 (cost=0.00..458.00 rows=10000 width=244) + Planning time: 0.113 ms @@ -161,6 +162,12 @@ EXPLAIN SELECT * FROM tenk1; actually returned, updated, or deleted by the query. + + The Planning time 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. + + Returning to our example: @@ -170,6 +177,7 @@ EXPLAIN SELECT * FROM tenk1; QUERY PLAN ------------------------------------------------------------- Seq Scan on tenk1 (cost=0.00..458.00 rows=10000 width=244) + Planning time: 0.113 ms @@ -198,6 +206,7 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 7000; ------------------------------------------------------------ Seq Scan on tenk1 (cost=0.00..483.00 rows=7001 width=244) Filter: (unique1 < 7000) + Planning time: 0.104 ms Notice that the EXPLAIN output shows the WHERE @@ -234,6 +243,7 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 100; 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 Here the planner has decided to use a two-step plan: the child plan @@ -262,6 +272,7 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 100 AND stringu1 = 'xxx'; 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 The added condition stringu1 = 'xxx' reduces the @@ -283,6 +294,7 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 = 42; ----------------------------------------------------------------------------- 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 In this type of plan the table rows are fetched in index order, which @@ -311,6 +323,7 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 100 AND unique2 > 9000; 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 But this requires visiting both indexes, so it's not necessarily a win @@ -331,6 +344,7 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 100 AND unique2 > 9000 LIMIT 2 -> 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 @@ -364,6 +378,7 @@ WHERE t1.unique1 < 10 AND t1.unique2 = t2.unique2; 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 @@ -415,6 +430,7 @@ WHERE t1.unique1 < 10 AND t2.unique2 < 10 AND t1.hundred < t2.hundred; -> 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 The condition t1.hundred < t2.hundred can't be @@ -462,6 +478,7 @@ WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2; 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 @@ -492,6 +509,7 @@ WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2; -> 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 @@ -528,6 +546,7 @@ WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2; -> 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 which shows that the planner thinks that sorting onek by @@ -564,6 +583,7 @@ WHERE t1.unique1 < 10 AND t1.unique2 = t2.unique2; 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 @@ -612,6 +632,7 @@ WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2 ORDER BY t1.fivethous; 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 @@ -635,6 +656,7 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE ten < 7; 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 @@ -657,6 +679,7 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @> polygon '(0.5,2.0)'; 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 @@ -675,6 +698,7 @@ EXPLAIN ANALYZE SELECT * FROM polygon_tbl WHERE f1 @> polygon '(0.5,2.0)'; 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 @@ -705,6 +729,7 @@ EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM tenk1 WHERE unique1 < 100 AND unique -> 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 @@ -732,6 +757,7 @@ EXPLAIN ANALYZE UPDATE tenk1 SET hundred = hundred + 1 WHERE unique1 < 100; 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; @@ -817,6 +843,7 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE unique1 < 100 AND unique2 > 9000 Index Cond: (unique2 > 9000) Filter: (unique1 < 100) Rows Removed by Filter: 287 + Planning time: 0.096 ms Total runtime: 0.336 ms diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index 35264dcc72c..0f579fb161f 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -145,7 +145,8 @@ ROLLBACK; 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 TRUE. + width of each row. Also, include the time spent planning the query, + if available. This parameter defaults to TRUE. @@ -289,7 +290,8 @@ EXPLAIN SELECT * FROM foo; QUERY PLAN --------------------------------------------------------- Seq Scan on foo (cost=0.00..155.00 rows=10000 width=4) -(1 row) + Planning time: 0.114 ms +(2 rows) @@ -309,7 +311,8 @@ EXPLAIN (FORMAT JSON) SELECT * FROM foo; "Total Cost": 155.00, + "Plan Rows": 10000, + "Plan Width": 4 + - } + + }. + + "Planning Time": 0.114 + } + ] (1 row) @@ -328,7 +331,8 @@ EXPLAIN SELECT * FROM foo WHERE i = 4; -------------------------------------------------------------- Index Scan using fi on foo (cost=0.00..5.98 rows=1 width=4) Index Cond: (i = 4) -(2 rows) + Planning time: 0.073 ms +(3 rows) @@ -348,7 +352,8 @@ EXPLAIN (FORMAT YAML) SELECT * FROM foo WHERE i='4'; Total Cost: 5.98 + Plan Rows: 1 + Plan Width: 4 + - Index Cond: "(i = 4)" + Index Cond: "(i = 4)" + + Planning Time: 0.073 (1 row) @@ -380,6 +385,7 @@ EXPLAIN SELECT sum(i) FROM foo WHERE i < 10; 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) @@ -401,6 +407,7 @@ EXPLAIN ANALYZE EXECUTE query(100, 200); 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) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 0dba9283f1c..08f3167f10d 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -320,13 +320,19 @@ ExplainOneQuery(Query *query, IntoClause *into, ExplainState *es, (*ExplainOneQuery_hook) (query, into, es, queryString, params); else { - PlannedStmt *plan; + 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); + ExplainOnePlan(plan, into, es, queryString, params, &planduration); } } @@ -403,7 +409,8 @@ ExplainOneUtility(Node *utilityStmt, IntoClause *into, ExplainState *es, */ void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, - const char *queryString, ParamListInfo params) + const char *queryString, ParamListInfo params, + const instr_time *planduration) { DestReceiver *dest; QueryDesc *queryDesc; @@ -484,6 +491,17 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, /* 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 index 49c40935eb9..65431b713d0 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -665,7 +665,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, PlannedStmt *pstmt = (PlannedStmt *) lfirst(p); if (IsA(pstmt, PlannedStmt)) - ExplainOnePlan(pstmt, into, es, query_string, paramLI); + 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 index e097710dddd..3488be39c38 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -67,8 +67,8 @@ extern void ExplainOneUtility(Node *utilityStmt, IntoClause *into, const char *queryString, ParamListInfo params); extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, - ExplainState *es, - const char *queryString, ParamListInfo params); + 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);