On 2020/04/03 16:43, Julien Rouhaud wrote:
On Fri, Apr 03, 2020 at 03:24:41PM +0900, Fujii Masao wrote:
On 2020/04/03 12:30, Tom Lane wrote:
Fujii Masao <[email protected]> writes:
On 2020/04/03 11:58, Michael Paquier wrote:
prion did not like that:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&dt=2020-04-03%2002%3A33%3A13
dory failed as well. The problem is that in text mode, a Buffers line
won't appear at all if there were zero buffer accesses. I don't think
we really want to change that,
Yes.
so probably the thing to do is adapt
the filter functions in explain.sql so that they suppress Buffers lines
altogether in text output. Kind of annoying, but ...
I'm thinking to suppress only Buffers line just after Planning Time line,
by applying something like the following changes to explain_filter().
Thought?
+1, that's a better workaround.
declare
ln text;
+ ignore_output boolean;
begin
for ln in execute $1
loop
+ IF ignore_output THEN
+ ignore_output := false;
+ CONTINUE WHEN (ln ~~ ' Buffers: %');
+ END IF;
+ ignore_output := ln ~~ 'Planning Time: %';
-- Replace any numeric word with just 'N'
ln := regexp_replace(ln, '\m\d+\M', 'N', 'g');
-- In sort output, the above won't match units-suffixed numbers
I'm not sure of what's plpgsql behavior here, but it's probably better to
initialize ignore_output to false.
Thanks for the review! Yes, that's necessary.
Nitpicking, but I think that
planning_time_found, or something similar, would be better here.
Yeah, that sounds better.
Attached is the updated version of the patch.
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..a95196b41d 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -13,9 +13,21 @@ language plpgsql as
$$
declare
ln text;
+ planning_time_found boolean := false;
begin
for ln in execute $1
loop
+ -- Filter out the buffers output for the planning to make regression
+ -- test output stable. This is necessary because whether text-mode
+ -- buffers output for the planning appears or not varies depending
+ -- on the compile option. It appears if the server is built with
+ -- -DRELCACHE_FORCE_RELEASE -DCATCACHE_FORCE_RELEASE,
+ -- but not otherwise.
+ IF planning_time_found THEN
+ planning_time_found := false;
+ CONTINUE WHEN (ln ~~ ' Buffers: %');
+ END IF;
+ planning_time_found := ln ~~ 'Planning Time: %';
-- Replace any numeric word with just 'N'
ln := regexp_replace(ln, '\m\d+\M', 'N', 'g');
-- In sort output, the above won't match units-suffixed numbers
@@ -105,7 +117,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 +166,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 +212,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 +413,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 +
} +
]
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index e09371f97b..4c608f2c84 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -15,9 +15,21 @@ language plpgsql as
$$
declare
ln text;
+ planning_time_found boolean := false;
begin
for ln in execute $1
loop
+ -- Filter out the buffers output for the planning to make regression
+ -- test output stable. This is necessary because whether text-mode
+ -- buffers output for the planning appears or not varies depending
+ -- on the compile option. It appears if the server is built with
+ -- -DRELCACHE_FORCE_RELEASE -DCATCACHE_FORCE_RELEASE,
+ -- but not otherwise.
+ IF planning_time_found THEN
+ planning_time_found := false;
+ CONTINUE WHEN (ln ~~ ' Buffers: %');
+ END IF;
+ planning_time_found := ln ~~ 'Planning Time: %';
-- Replace any numeric word with just 'N'
ln := regexp_replace(ln, '\m\d+\M', 'N', 'g');
-- In sort output, the above won't match units-suffixed numbers
