Skip to content

Commit ce77abe

Browse files
MasaoFujiiMasaoFujii
committed
Include information on buffer usage during planning phase, in EXPLAIN output, take two.
When BUFFERS option is enabled, EXPLAIN command includes the information on buffer usage during each plan node, in its output. In addition to that, this commit makes EXPLAIN command include also the information on buffer usage during planning phase, in its output. This feature makes it easier to discern the cases where lots of buffer access happen during planning. This commit revives the original commit ed7a509 that was reverted by commit 19db23b. The original commit had to be reverted because it caused the regression test failure on the buildfarm members prion and dory. But since commit c0885c4 got rid of the caues of the test failure, the original commit can be safely introduced again. Author: Julien Rouhaud, slightly revised by Fujii Masao Reviewed-by: Justin Pryzby Discussion: https://postgr.es/m/16109-26a1a88651e90608@postgresql.org
1 parent e41955f commit ce77abe

File tree

4 files changed

+95
-8
lines changed

4 files changed

+95
-8
lines changed

‎src/backend/commands/explain.c‎

Lines changed: 30 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -372,7 +372,11 @@ ExplainOneQuery(Query *query, int cursorOptions,
372372
PlannedStmt *plan;
373373
instr_time planstart,
374374
planduration;
375+
BufferUsage bufusage_start,
376+
bufusage;
375377

378+
if (es->buffers)
379+
bufusage_start = pgBufferUsage;
376380
INSTR_TIME_SET_CURRENT(planstart);
377381

378382
/* plan the query */
@@ -381,9 +385,16 @@ ExplainOneQuery(Query *query, int cursorOptions,
381385
INSTR_TIME_SET_CURRENT(planduration);
382386
INSTR_TIME_SUBTRACT(planduration, planstart);
383387

388+
/* calc differences of buffer counters. */
389+
if (es->buffers)
390+
{
391+
memset(&bufusage, 0, sizeof(BufferUsage));
392+
BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);
393+
}
394+
384395
/* run it (if needed) and produce output */
385396
ExplainOnePlan(plan, into, es, queryString, params, queryEnv,
386-
&planduration);
397+
&planduration, (es->buffers ? &bufusage : NULL));
387398
}
388399
}
389400

@@ -476,7 +487,8 @@ ExplainOneUtility(Node *utilityStmt, IntoClause *into, ExplainState *es,
476487
void
477488
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
478489
const char *queryString, ParamListInfo params,
479-
QueryEnvironment *queryEnv, const instr_time *planduration)
490+
QueryEnvironment *queryEnv, const instr_time *planduration,
491+
const BufferUsage *bufusage)
480492
{
481493
DestReceiver *dest;
482494
QueryDesc *queryDesc;
@@ -560,13 +572,29 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
560572
/* Create textual dump of plan tree */
561573
ExplainPrintPlan(es, queryDesc);
562574

575+
if (es->summary && (planduration || bufusage))
576+
ExplainOpenGroup("Planning", "Planning", true, es);
577+
563578
if (es->summary && planduration)
564579
{
565580
double plantime = INSTR_TIME_GET_DOUBLE(*planduration);
566581

567582
ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es);
568583
}
569584

585+
/* Show buffer usage */
586+
if (es->summary && bufusage)
587+
{
588+
if (es->format == EXPLAIN_FORMAT_TEXT)
589+
es->indent++;
590+
show_buffer_usage(es, bufusage);
591+
if (es->format == EXPLAIN_FORMAT_TEXT)
592+
es->indent--;
593+
}
594+
595+
if (es->summary && (planduration || bufusage))
596+
ExplainCloseGroup("Planning", "Planning", true, es);
597+
570598
/* Print info about runtime of triggers */
571599
if (es->analyze)
572600
ExplainPrintTriggers(es, queryDesc);

‎src/backend/commands/prepare.c‎

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -616,7 +616,11 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
616616
EState *estate = NULL;
617617
instr_time planstart;
618618
instr_time planduration;
619+
BufferUsage bufusage_start,
620+
bufusage;
619621

622+
if (es->buffers)
623+
bufusage_start = pgBufferUsage;
620624
INSTR_TIME_SET_CURRENT(planstart);
621625

622626
/* Look it up in the hash table */
@@ -654,6 +658,13 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
654658
INSTR_TIME_SET_CURRENT(planduration);
655659
INSTR_TIME_SUBTRACT(planduration, planstart);
656660

661+
/* calc differences of buffer counters. */
662+
if (es->buffers)
663+
{
664+
memset(&bufusage, 0, sizeof(BufferUsage));
665+
BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);
666+
}
667+
657668
plan_list = cplan->stmt_list;
658669

659670
/* Explain each query */
@@ -663,7 +674,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
663674

664675
if (pstmt->commandType != CMD_UTILITY)
665676
ExplainOnePlan(pstmt, into, es, query_string, paramLI, queryEnv,
666-
&planduration);
677+
&planduration, (es->buffers ? &bufusage : NULL));
667678
else
668679
ExplainOneUtility(pstmt->utilityStmt, into, es, query_string,
669680
paramLI, queryEnv);

‎src/include/commands/explain.h‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -89,7 +89,8 @@ extern void ExplainOneUtility(Node *utilityStmt, IntoClause *into,
8989
extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
9090
ExplainState *es, const char *queryString,
9191
ParamListInfo params, QueryEnvironment *queryEnv,
92-
const instr_time *planduration);
92+
const instr_time *planduration,
93+
const BufferUsage *bufusage);
9394

9495
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
9596
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);

‎src/test/regress/expected/explain.out‎

Lines changed: 51 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -105,7 +105,19 @@ select explain_filter('explain (analyze, buffers, format json) select * from int
105105
"Temp Read Blocks": N, +
106106
"Temp Written Blocks": N +
107107
}, +
108-
"Planning Time": N.N, +
108+
"Planning": { +
109+
"Planning Time": N.N, +
110+
"Shared Hit Blocks": N, +
111+
"Shared Read Blocks": N, +
112+
"Shared Dirtied Blocks": N, +
113+
"Shared Written Blocks": N, +
114+
"Local Hit Blocks": N, +
115+
"Local Read Blocks": N, +
116+
"Local Dirtied Blocks": N, +
117+
"Local Written Blocks": N, +
118+
"Temp Read Blocks": N, +
119+
"Temp Written Blocks": N +
120+
}, +
109121
"Triggers": [ +
110122
], +
111123
"Execution Time": N.N +
@@ -142,7 +154,19 @@ select explain_filter('explain (analyze, buffers, format xml) select * from int8
142154
<Temp-Read-Blocks>N</Temp-Read-Blocks> +
143155
<Temp-Written-Blocks>N</Temp-Written-Blocks> +
144156
</Plan> +
145-
<Planning-Time>N.N</Planning-Time> +
157+
<Planning> +
158+
<Planning-Time>N.N</Planning-Time> +
159+
<Shared-Hit-Blocks>N</Shared-Hit-Blocks> +
160+
<Shared-Read-Blocks>N</Shared-Read-Blocks> +
161+
<Shared-Dirtied-Blocks>N</Shared-Dirtied-Blocks>+
162+
<Shared-Written-Blocks>N</Shared-Written-Blocks>+
163+
<Local-Hit-Blocks>N</Local-Hit-Blocks> +
164+
<Local-Read-Blocks>N</Local-Read-Blocks> +
165+
<Local-Dirtied-Blocks>N</Local-Dirtied-Blocks> +
166+
<Local-Written-Blocks>N</Local-Written-Blocks> +
167+
<Temp-Read-Blocks>N</Temp-Read-Blocks> +
168+
<Temp-Written-Blocks>N</Temp-Written-Blocks> +
169+
</Planning> +
146170
<Triggers> +
147171
</Triggers> +
148172
<Execution-Time>N.N</Execution-Time> +
@@ -176,7 +200,18 @@ select explain_filter('explain (analyze, buffers, format yaml) select * from int
176200
Local Written Blocks: N +
177201
Temp Read Blocks: N +
178202
Temp Written Blocks: N +
179-
Planning Time: N.N +
203+
Planning: +
204+
Planning Time: N.N +
205+
Shared Hit Blocks: N +
206+
Shared Read Blocks: N +
207+
Shared Dirtied Blocks: N +
208+
Shared Written Blocks: N +
209+
Local Hit Blocks: N +
210+
Local Read Blocks: N +
211+
Local Dirtied Blocks: N +
212+
Local Written Blocks: N +
213+
Temp Read Blocks: N +
214+
Temp Written Blocks: N +
180215
Triggers: +
181216
Execution Time: N.N
182217
(1 row)
@@ -366,9 +401,21 @@ select jsonb_pretty(
366401
"Shared Dirtied Blocks": 0, +
367402
"Shared Written Blocks": 0 +
368403
}, +
404+
"Planning": { +
405+
"Planning Time": 0.0, +
406+
"Local Hit Blocks": 0, +
407+
"Temp Read Blocks": 0, +
408+
"Local Read Blocks": 0, +
409+
"Shared Hit Blocks": 0, +
410+
"Shared Read Blocks": 0, +
411+
"Temp Written Blocks": 0, +
412+
"Local Dirtied Blocks": 0, +
413+
"Local Written Blocks": 0, +
414+
"Shared Dirtied Blocks": 0, +
415+
"Shared Written Blocks": 0 +
416+
}, +
369417
"Triggers": [ +
370418
], +
371-
"Planning Time": 0.0, +
372419
"Execution Time": 0.0 +
373420
} +
374421
]

0 commit comments

Comments
 (0)