On 2020/04/02 3:47, Julien Rouhaud wrote:
On Wed, Apr 1, 2020 at 7:51 PM Fujii Masao <masao.fu...@oss.nttdata.com> wrote:
On 2020/03/31 10:31, Justin Pryzby wrote:
On Wed, Jan 29, 2020 at 12:15:59PM +0100, Julien Rouhaud wrote:
Rebase due to conflict with 3ec20c7091e97.
This is failing to apply probably since
4a539a25ebfc48329fd656a95f3c1eb2cda38af3.
Could you rebase? (Also, not sure if this can be set as RFC?)
I updated the patch. Attached.
Thanks a lot! I'm sorry I missed Justin's ping, and it I just
realized that my cron job that used to warn me about cfbot failure was
broken :(
+/* Compute the difference between two BufferUsage */
+BufferUsage
+ComputeBufferCounters(BufferUsage *start, BufferUsage *stop)
Since BufferUsageAccumDiff() was exported, ComputeBufferCounters() is
no longer necessary. In the patched version, BufferUsageAccumDiff() is
used to calculate the difference of buffer usage.
Indeed, exposing BufferUsageAccumDiff wa definitely a good thing!
+ if (es->summary && (planduration || es->buffers))
+ ExplainOpenGroup("Planning", "Planning", true, es);
Isn't it more appropriate to check "bufusage" instead of "es->buffers" here?
The patch changes the code so that "bufusage" is checked.
AFAICS not unless ExplainOneQuery is also changed to pass a NULL
pointer if the BUFFER option wasn't provided (and maybe also
optionally skip the planning buffer computation). With this version
you now get:
=# explain (analyze, buffers off) update t1 set id = id;
QUERY PLAN
-------------------------------------------------------------------------------------------------------
Update on t1 (cost=0.00..22.70 rows=1270 width=42) (actual
time=0.170..0.170 rows=0 loops=1)
-> Seq Scan on t1 (cost=0.00..22.70 rows=1270 width=42) (actual
time=0.050..0.054 rows=1 loops=1)
Planning Time: 1.461 ms
Buffers: shared hit=25
Execution Time: 1.071 ms
(5 rows)
which seems wrong to me.
I reused the es->buffers to avoid having needing something like:
Yes, you're right! So I updated the patch as you suggested.
Attached is the updated version of the patch.
Thanks for the review!
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index ee0e638f33..81a18abbeb 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -372,7 +372,11 @@ ExplainOneQuery(Query *query, int cursorOptions,
PlannedStmt *plan;
instr_time planstart,
planduration;
+ BufferUsage bufusage_start,
+ bufusage;
+ if (es->buffers)
+ bufusage_start = pgBufferUsage;
INSTR_TIME_SET_CURRENT(planstart);
/* plan the query */
@@ -381,9 +385,16 @@ ExplainOneQuery(Query *query, int cursorOptions,
INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);
+ /* calc differences of buffer counters. */
+ if (es->buffers)
+ {
+ memset(&bufusage, 0, sizeof(BufferUsage));
+ BufferUsageAccumDiff(&bufusage, &pgBufferUsage,
&bufusage_start);
+ }
+
/* run it (if needed) and produce output */
ExplainOnePlan(plan, into, es, queryString, params, queryEnv,
- &planduration);
+ &planduration, (es->buffers ?
&bufusage : NULL));
}
}
@@ -476,7 +487,8 @@ ExplainOneUtility(Node *utilityStmt, IntoClause *into,
ExplainState *es,
void
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
const char *queryString, ParamListInfo params,
- QueryEnvironment *queryEnv, const instr_time
*planduration)
+ QueryEnvironment *queryEnv, const instr_time
*planduration,
+ const BufferUsage *bufusage)
{
DestReceiver *dest;
QueryDesc *queryDesc;
@@ -560,6 +572,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
ExplainState *es,
/* Create textual dump of plan tree */
ExplainPrintPlan(es, queryDesc);
+ if (es->summary && (planduration || bufusage))
+ ExplainOpenGroup("Planning", "Planning", true, es);
+
if (es->summary && planduration)
{
double plantime = INSTR_TIME_GET_DOUBLE(*planduration);
@@ -567,6 +582,19 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
ExplainState *es,
ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime,
3, es);
}
+ /* Show buffer usage */
+ if (es->summary && bufusage)
+ {
+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ es->indent++;
+ show_buffer_usage(es, bufusage);
+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ es->indent--;
+ }
+
+ if (es->summary && (planduration || bufusage))
+ ExplainCloseGroup("Planning", "Planning", true, 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 284a5bfbec..80d6df8ac1 100644
--- a/src/backend/commands/prepare.c
+++ b/src/backend/commands/prepare.c
@@ -616,7 +616,11 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause
*into, ExplainState *es,
EState *estate = NULL;
instr_time planstart;
instr_time planduration;
+ BufferUsage bufusage_start,
+ bufusage;
+ if (es->buffers)
+ bufusage_start = pgBufferUsage;
INSTR_TIME_SET_CURRENT(planstart);
/* Look it up in the hash table */
@@ -654,6 +658,13 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause
*into, ExplainState *es,
INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);
+ /* calc differences of buffer counters. */
+ if (es->buffers)
+ {
+ memset(&bufusage, 0, sizeof(BufferUsage));
+ BufferUsageAccumDiff(&bufusage, &pgBufferUsage,
&bufusage_start);
+ }
+
plan_list = cplan->stmt_list;
/* Explain each query */
@@ -663,7 +674,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause
*into, ExplainState *es,
if (pstmt->commandType != CMD_UTILITY)
ExplainOnePlan(pstmt, into, es, query_string, paramLI,
queryEnv,
- &planduration);
+ &planduration, (es->buffers
? &bufusage : NULL));
else
ExplainOneUtility(pstmt->utilityStmt, into, es,
query_string,
paramLI, queryEnv);
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 54f6240e5e..739c1d0b42 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -89,7 +89,8 @@ extern void ExplainOneUtility(Node *utilityStmt, IntoClause
*into,
extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
ExplainState *es, const char
*queryString,
ParamListInfo params,
QueryEnvironment *queryEnv,
- const instr_time
*planduration);
+ const instr_time
*planduration,
+ const BufferUsage *bufusage);
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
diff --git a/src/test/regress/expected/explain.out
b/src/test/regress/expected/explain.out
index 8f31c308c6..191ea5de7f 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -105,7 +105,19 @@ select explain_filter('explain (analyze, buffers, format
json) select * from int
"Temp Read Blocks": N, +
"Temp Written Blocks": N +
}, +
- "Planning Time": N.N, +
+ "Planning": { +
+ "Planning Time": N.N, +
+ "Shared Hit Blocks": N, +
+ "Shared Read Blocks": N, +
+ "Shared Dirtied Blocks": N, +
+ "Shared Written Blocks": N, +
+ "Local Hit Blocks": N, +
+ "Local Read Blocks": N, +
+ "Local Dirtied Blocks": N, +
+ "Local Written Blocks": N, +
+ "Temp Read Blocks": N, +
+ "Temp Written Blocks": N +
+ }, +
"Triggers": [ +
], +
"Execution Time": N.N +
@@ -142,7 +154,19 @@ select explain_filter('explain (analyze, buffers, format
xml) select * from int8
<Temp-Read-Blocks>N</Temp-Read-Blocks> +
<Temp-Written-Blocks>N</Temp-Written-Blocks> +
</Plan> +
- <Planning-Time>N.N</Planning-Time> +
+ <Planning> +
+ <Planning-Time>N.N</Planning-Time> +
+ <Shared-Hit-Blocks>N</Shared-Hit-Blocks> +
+ <Shared-Read-Blocks>N</Shared-Read-Blocks> +
+ <Shared-Dirtied-Blocks>N</Shared-Dirtied-Blocks>+
+ <Shared-Written-Blocks>N</Shared-Written-Blocks>+
+ <Local-Hit-Blocks>N</Local-Hit-Blocks> +
+ <Local-Read-Blocks>N</Local-Read-Blocks> +
+ <Local-Dirtied-Blocks>N</Local-Dirtied-Blocks> +
+ <Local-Written-Blocks>N</Local-Written-Blocks> +
+ <Temp-Read-Blocks>N</Temp-Read-Blocks> +
+ <Temp-Written-Blocks>N</Temp-Written-Blocks> +
+ </Planning> +
<Triggers> +
</Triggers> +
<Execution-Time>N.N</Execution-Time> +
@@ -176,7 +200,18 @@ select explain_filter('explain (analyze, buffers, format
yaml) select * from int
Local Written Blocks: N +
Temp Read Blocks: N +
Temp Written Blocks: N +
- Planning Time: N.N +
+ Planning: +
+ Planning Time: N.N +
+ Shared Hit Blocks: N +
+ Shared Read Blocks: N +
+ Shared Dirtied Blocks: N +
+ Shared Written Blocks: N +
+ Local Hit Blocks: N +
+ Local Read Blocks: N +
+ Local Dirtied Blocks: N +
+ Local Written Blocks: N +
+ Temp Read Blocks: N +
+ Temp Written Blocks: N +
Triggers: +
Execution Time: N.N
(1 row)
@@ -366,9 +401,21 @@ select jsonb_pretty(
"Shared Dirtied Blocks": 0, +
"Shared Written Blocks": 0 +
}, +
+ "Planning": { +
+ "Planning Time": 0.0, +
+ "Local Hit Blocks": 0, +
+ "Temp Read Blocks": 0, +
+ "Local Read Blocks": 0, +
+ "Shared Hit Blocks": 0, +
+ "Shared Read Blocks": 0, +
+ "Temp Written Blocks": 0, +
+ "Local Dirtied Blocks": 0, +
+ "Local Written Blocks": 0, +
+ "Shared Dirtied Blocks": 0, +
+ "Shared Written Blocks": 0 +
+ }, +
"Triggers": [ +
], +
- "Planning Time": 0.0, +
"Execution Time": 0.0 +
} +
]
