diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index b33b2211ca..d5fa6ac2d3 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -301,6 +301,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc) es.verbose = auto_explain_log_verbose; es.buffers = (es.analyze && auto_explain_log_buffers); es.timing = (es.analyze && auto_explain_log_timing); + es.summary = es.analyze; es.format = auto_explain_log_format; ExplainBeginOutput(&es); diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml index 94c11adaa4..5a087fbe6a 100644 --- a/doc/src/sgml/perform.sgml +++ b/doc/src/sgml/perform.sgml @@ -89,7 +89,6 @@ EXPLAIN SELECT * FROM tenk1; QUERY PLAN ------------------------------------------------------------- Seq Scan on tenk1 (cost=0.00..458.00 rows=10000 width=244) - Planning time: 0.113 ms @@ -162,12 +161,6 @@ 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: @@ -177,7 +170,6 @@ EXPLAIN SELECT * FROM tenk1; QUERY PLAN ------------------------------------------------------------- Seq Scan on tenk1 (cost=0.00..458.00 rows=10000 width=244) - Planning time: 0.113 ms @@ -206,7 +198,6 @@ 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 @@ -243,7 +234,6 @@ 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 @@ -272,7 +262,6 @@ 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 @@ -294,7 +283,6 @@ 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 @@ -323,7 +311,6 @@ 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 @@ -344,7 +331,6 @@ 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 @@ -378,7 +364,6 @@ 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 @@ -430,7 +415,6 @@ 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 @@ -478,7 +462,6 @@ 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 @@ -509,7 +492,6 @@ 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 @@ -546,7 +528,6 @@ 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 @@ -780,6 +761,12 @@ ROLLBACK; decisions. + + The Planning time shown by EXPLAIN + ANALYZE is the time it took to generate the query plan from the + parsed query and optimize it. It does not include parsing or rewriting. + + The Execution time shown by EXPLAIN ANALYZE includes executor start-up and shut-down time, as well diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index 72776a0fde..f14a58dfc6 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -145,8 +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. Also, include the time spent planning the query, - if available. This parameter defaults to TRUE. + width of each row. + This parameter defaults to TRUE. @@ -291,8 +291,7 @@ EXPLAIN SELECT * FROM foo; QUERY PLAN --------------------------------------------------------- Seq Scan on foo (cost=0.00..155.00 rows=10000 width=4) - Planning time: 0.114 ms -(2 rows) +(1 row) @@ -312,8 +311,7 @@ EXPLAIN (FORMAT JSON) SELECT * FROM foo; "Total Cost": 155.00, + "Plan Rows": 10000, + "Plan Width": 4 + - }. + - "Planning Time": 0.114 + + } + } + ] (1 row) @@ -332,8 +330,7 @@ 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) - Planning time: 0.073 ms -(3 rows) +(2 rows) @@ -353,8 +350,7 @@ EXPLAIN (FORMAT YAML) SELECT * FROM foo WHERE i='4'; Total Cost: 5.98 + Plan Rows: 1 + Plan Width: 4 + - Index Cond: "(i = 4)" + - Planning Time: 0.073 + Index Cond: "(i = 4)" (1 row) @@ -386,7 +382,6 @@ 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) @@ -410,7 +405,7 @@ EXPLAIN ANALYZE EXECUTE query(100, 200); Index Cond: ((id > $1) AND (id < $2)) Planning time: 0.197 ms Execution time: 0.225 ms -(5 rows) +(6 rows) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 387d263e87..3fcc1ddc69 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -191,6 +191,9 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString, (errcode(ERRCODE_INVALID_PARAMETER_VALUE), errmsg("EXPLAIN option TIMING requires ANALYZE"))); + /* currently, summary option is not exposed to users; just set it */ + es.summary = es.analyze; + /* * Parse analysis was done already, but we still have to run the rule * rewriter. We do not do AcquireRewriteLocks: we assume the query either @@ -431,7 +434,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, /* * We always collect timing for the entire statement, even when node-level - * timing is off, so we don't look at es->timing here. + * timing is off, so we don't look at es->timing here. (We could skip + * this if !es->summary, but it's hardly worth the complication.) */ INSTR_TIME_SET_CURRENT(starttime); @@ -493,7 +497,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, /* Create textual dump of plan tree */ ExplainPrintPlan(es, queryDesc); - if (es->costs && planduration) + if (es->summary && planduration) { double plantime = INSTR_TIME_GET_DOUBLE(*planduration); @@ -526,7 +530,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, totaltime += elapsed_time(&starttime); - if (es->analyze) + if (es->summary) { if (es->format == EXPLAIN_FORMAT_TEXT) appendStringInfo(es->str, "Execution time: %.3f ms\n", diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 3488be39c3..d56beaac15 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -30,9 +30,10 @@ typedef struct ExplainState /* options */ bool verbose; /* be verbose */ bool analyze; /* print actual times */ - bool costs; /* print costs */ + bool costs; /* print estimated costs */ bool buffers; /* print buffer usage */ - bool timing; /* print timing */ + bool timing; /* print detailed node timing */ + bool summary; /* print total planning and execution timing */ ExplainFormat format; /* output format */ /* other states */ PlannedStmt *pstmt; /* top of plan */