8000 Print planning time only in EXPLAIN ANALYZE, not plain EXPLAIN. · postgres/postgres@90063a7 · GitHub
[go: up one dir, main page]
Skip to content

Commit 90063a7

Browse files
tglsfdctglsfdc
committed
Print planning time only in EXPLAIN ANALYZE, not plain EXPLAIN.
We've gotten enough push-back on that change to make it clear that it wasn't an especially good idea to do it like that. Revert plain EXPLAIN to its previous behavior, but keep the extra output in EXPLAIN ANALYZE. Per discussion. Internally, I set this up as a separate flag ExplainState.summary that controls printing of planning time and execution time. For now it's just copied from the ANALYZE option, but we could consider exposing it to users.
1 parent 076d29a commit 90063a7

File tree

5 files changed

+24
-36
lines changed

5 files changed

+24
-36
lines changed

‎contrib/auto_explain/auto_explain.c

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -301,6 +301,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
301301
es.verbose = auto_explain_log_verbose;
302302
es.buffers = (es.analyze && auto_explain_log_buffers);
303303
es.timing = (es.analyze && auto_explain_log_timing);
304+
es.summary = es.analyze;
304305
es.format = auto_explain_log_format;
305306

306307
ExplainBeginOutput(&es);

‎doc/src/sgml/perform.sgml

Lines changed: 6 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -89,7 +89,6 @@ EXPLAIN SELECT * FROM tenk1;
8989
QUERY PLAN
9090
-------------------------------------------------------------
9191
Seq Scan on tenk1 (cost=0.00..458.00 rows=10000 width=244)
92-
Planning time: 0.113 ms
9392
</screen>
9493
</para>
9594

@@ -162,12 +161,6 @@ EXPLAIN SELECT * FROM tenk1;
162161
actually returned, updated, or deleted by the query.
163162
</para>
164163

165-
<para>
166-
The <literal>Planning time</literal> shown is the time it took to generate
167-
the query plan from the parsed query and optimize it. It does not include
168-
rewriting and parsing.
169-
</para>
170-
171164
<para>
172165
Returning to our example:
173166

@@ -177,7 +170,6 @@ EXPLAIN SELECT * FROM tenk1;
177170
QUERY PLAN
178171
-------------------------------------------------------------
179172
Seq Scan on tenk1 (cost=0.00..458.00 rows=10000 width=244)
180-
Planning time: 0.113 ms
181173
</screen>
182174
</para>
183175

@@ -206,7 +198,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 7000;
206198
------------------------------------------------------------
207199
Seq Scan on tenk1 (cost=0.00..483.00 rows=7001 width=244)
208200
Filter: (unique1 &lt; 7000)
209-
Planning time: 0.104 ms
210201
</screen>
211202

212203
Notice that the <command>EXPLAIN</> output shows the <literal>WHERE</>
@@ -243,7 +234,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 100;
243234
Recheck Cond: (unique1 &lt; 100)
244235
-&gt; Bitmap Index Scan on tenk1_unique1 (cost=0.00..5.04 rows=101 width=0)
245236
Index Cond: (unique1 &lt; 100)
246-
Planning time: 0.093 ms
247237
</screen>
248238

249239
Here the planner has decided to use a two-step plan: the child plan
@@ -272,7 +262,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND stringu1 = 'xxx';
272262
Filter: (stringu1 = 'xxx'::name)
273263
-&gt; Bitmap Index Scan on tenk1_unique1 (cost=0.00..5.04 rows=101 width=0)
274264
Index Cond: (unique1 &lt; 100)
275-
Planning time: 0.089 ms
276265
</screen>
277266

278267
The added condition <literal>stringu1 = 'xxx'</literal> reduces the
@@ -294,7 +283,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 = 42;
294283
-----------------------------------------------------------------------------
295284
Index Scan using tenk1_unique1 on tenk1 (cost=0.29..8.30 rows=1 width=244)
296285
Index Cond: (unique1 = 42)
297-
Planning time: 0.076 ms
298286
</screen>
299287

300288
In this type of plan the table rows are fetched in index order, which
@@ -323,7 +311,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique2 &gt; 9000;
323311
Index Cond: (unique1 &lt; 100)
324312
-&gt; Bitmap Index Scan on tenk1_unique2 (cost=0.00..19.78 rows=999 width=0)
325313
Index Cond: (unique2 &gt; 9000)
326-
Planning time: 0.094 ms
327314
</screen>
328315

329316
But this requires visiting both indexes, so it's not necessarily a win
@@ -344,7 +331,6 @@ EXPLAIN SELECT * FROM tenk1 WHERE unique1 &lt; 100 AND unique2 &gt; 9000 LIMIT 2
344331
-&gt; Index Scan using tenk1_unique2 on tenk1 (cost=0.29..71.27 rows=10 width=244)
345332
Index Cond: (unique2 &gt; 9000)
346333
Filter: (unique1 &lt; 100)
347-
Planning time: 0.087 ms
348334
</screen>
349335
</para>
350336

@@ -378,7 +364,6 @@ WHERE t1.unique1 &lt; 10 AND t1.unique2 = t2.unique2;
378364
Index Cond: (unique1 &lt; 10)
379365
-&gt; Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..7.91 rows=1 width=244)
380366
Index Cond: (unique2 = t1.unique2)
381-
Planning time: 0.117 ms
382367
</screen>
383368
</para>
384369

@@ -430,7 +415,6 @@ WHERE t1.unique1 &lt; 10 AND t2.unique2 &lt; 10 AND t1.hundred &lt; t2.hundred;
430415
-&gt; Materialize (cost=0.29..8.51 rows=10 width=244)
431416
-&gt; Index Scan using tenk2_unique2 on tenk2 t2 (cost=0.29..8.46 rows=10 width=244)
432417
Index Cond: (unique2 &lt; 10)
433-
Planning time: 0.119 ms
434418
</screen>
435419

436420
The condition <literal>t1.hundred &lt; t2.hundred</literal> can't be
@@ -478,7 +462,6 @@ WHERE t1.unique1 &lt; 100 AND t1.unique2 = t2.unique2;
478462
Recheck Cond: (unique1 &lt; 100)
479463
-&gt; Bitmap Index Scan on tenk1_unique1 (cost=0.00..5.04 rows=101 width=0)
480464
Index Cond: (unique1 &lt; 100)
481-
Planning time: 0.182 ms
482465
</screen>
483466
</para>
484467

@@ -509,7 +492,6 @@ WHERE t1.unique1 &lt; 100 AND t1.unique2 = t2.unique2;
509492
-&gt; Sort (cost=197.83..200.33 rows=1000 width=244)
510493
Sort Key: t2.unique2
511494
-&gt; Seq Scan on onek t2 (cost=0.00..148.00 rows=1000 width=244)
512-
Planning time: 0.195 ms
513495
</screen>
514496
</para>
515497

@@ -546,7 +528,6 @@ WHERE t1.unique1 &lt; 100 AND t1.unique2 = t2.unique2;
546528
-&gt; Index Scan using tenk1_unique2 on tenk1 t1 (cost=0.29..656.28 rows=101 width=244)
547529
Filter: (unique1 &lt; 100)
548530
-&gt; Index Scan using onek_unique2 on onek t2 (cost=0.28..224.79 rows=1000 width=244)
549-
Planning time: 0.176 ms
550531
</screen>
551532

552533
which shows that the planner thinks that sorting <literal>onek</> by
@@ -780,6 +761,12 @@ ROLLBACK;
780761
decisions.
781762
</para>
782763

764+
<para>
765+
The <literal>Planning time</literal> shown by <command>EXPLAIN
766+
ANALYZE</command> is the time it took to generate the query plan from the
767+
parsed query and optimize it. It does not include parsing or rewriting.
768+
</para>
769+
783770
<para>
784771
The <literal>Execution time</literal> shown by <command>EXPLAIN
785772
ANALYZE</command> includes executor start-up and shut-down time, as well

‎doc/src/sgml/ref/explain.sgml

Lines changed: 7 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -145,8 +145,8 @@ ROLLBACK;
145145
<para>
146146
Include information on the estimated startup and total cost of each
147147
plan node, as well as the estimated number of rows and the estimated
148-
width of each row. Also, include the time spent planning the query,
149-
if available. This parameter defaults to <literal>TRUE</literal>.
148+
width of each row.
149+
This parameter defaults to <literal>TRUE</literal>.
150150
</para>
151151
</listitem>
152152
</varlistentry>
@@ -291,8 +291,7 @@ EXPLAIN SELECT * FROM foo;
291291
QUERY PLAN
292292
---------------------------------------------------------
293293
Seq Scan on foo (cost=0.00..155.00 rows=10000 width=4)
294-
Planning time: 0.114 ms
295-
(2 rows)
294+
(1 row)
296295
</programlisting>
297296
</para>
298297

@@ -312,8 +311,7 @@ EXPLAIN (FORMAT JSON) SELECT * FROM foo;
312311
"Total Cost": 155.00, +
313312
"Plan Rows": 10000, +
314313
"Plan Width": 4 +
315-
}. +
316-
"Planning Time": 0.114 +
314+
} +
317315
} +
318316
]
319317
(1 row)
@@ -332,8 +330,7 @@ EXPLAIN SELECT * FROM foo WHERE i = 4;
332330
--------------------------------------------------------------
333331
Index Scan using fi on foo (cost=0.00..5.98 rows=1 width=4)
334332
Index Cond: (i = 4)
335-
Planning time: 0.073 ms
336-
(3 rows)
333+
(2 rows)
337334
</programlisting>
338335
</para>
339336

@@ -353,8 +350,7 @@ EXPLAIN (FORMAT YAML) SELECT * FROM foo WHERE i='4';
353350
Total Cost: 5.98 +
354351
Plan Rows: 1 +
355352
Plan Width: 4 +
356-
Index Cond: "(i = 4)" +
357-
Planning Time: 0.073
353+
Index Cond: "(i = 4)"
358354
(1 row)
359355
</programlisting>
360356

@@ -386,7 +382,6 @@ EXPLAIN SELECT sum(i) FROM foo WHERE i &lt; 10;
386382
Aggregate (cost=23.93..23.93 rows=1 width=4)
387383
-&gt; Index Scan using fi on foo (cost=0.00..23.92 rows=6 width=4)
388384
Index Cond: (i &lt; 10)
389-
Planning time: 0.088 ms
390385
(3 rows)
391386
</programlisting>
392387
</para>
@@ -410,7 +405,7 @@ EXPLAIN ANALYZE EXECUTE query(100, 200);
410405
Index Cond: ((id &gt; $1) AND (id &lt; $2))
411406
Planning time: 0.197 ms
412407
Execution time: 0.225 ms
413-
(5 rows)
408+
(6 rows)
414409
</programlisting>
415410
</para>
416411

‎src/backend/commands/explain.c

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -191,6 +191,9 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
191191
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
192192
errmsg("EXPLAIN option TIMING requires ANALYZE")));
193193

194+
/* currently, summary option is not ex F42D posed to users; just set it */
195+
es.summary = es.analyze;
196+
194197
/*
195198
* Parse analysis was done already, but we still have to run the rule
196199
* rewriter. We do not do AcquireRewriteLocks: we assume the query either
@@ -431,7 +434,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
431434

432435
/*
433436
* We always collect timing for the entire statement, even when node-level
434-
* timing is off, so we don't look at es->timing here.
437+
* timing is off, so we don't look at es->timing here. (We could skip
438+
* this if !es->summary, but it's hardly worth the complication.)
435439
*/
436440
INSTR_TIME_SET_CURRENT(starttime);
437441

@@ -493,7 +497,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
493497
/* Create textual dump of plan tree */
494498
ExplainPrintPlan(es, queryDesc);
495499

496-
if (es->costs && planduration)
500+
if (es->summary && planduration)
497501
{
498502
double plantime = INSTR_TIME_GET_DOUBLE(*planduration);
499503

@@ -526,7 +530,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
526530

527531
totaltime += elapsed_time(&starttime);
528532

529-
if (es->analyze)
533+
if (es->summary)
530534
{
531535
if (es->format == EXPLAIN_FORMAT_TEXT)
532536
appendStringInfo(es->str, "Execution time: %.3f ms\n",

‎src/include/commands/explain.h

Lines changed: 3 additions & 2 deletions
5121
Original file line numberDiff line numberDiff line change
@@ -30,9 +30,10 @@ typedef struct ExplainState
3030
/* options */
3131
bool verbose; /* be verbose */
3232
bool analyze; /* print actual times */
33-
bool costs; /* print costs */
33+
bool costs; /* print estimated costs */
3434
bool buffers; /* print buffer usage */
35-
bool timing; /* print timing */
35+
bool timing; /* print detailed node timing */
36+
bool summary; /* print total planning and execution timing */
3637
ExplainFormat format; /* output format */
3738
/* other states */
3839
PlannedStmt *pstmt; /* top of plan */

0 commit comments

Comments
 (0)
0