agora inbox for pgsql-bugs@postgresql.org
help / color / mirror / Atom feedFrom: Fujii Masao <masao.fujii@oss.nttdata.com>
To: Justin Pryzby <pryzby@telsasoft.com>
To: Julien Rouhaud <rjuju123@gmail.com>
Cc: Andres Freund <andres@anarazel.de>
Cc: pgsql-hackers@lists.postgresql.org
Subject: Re: BUG #16109: Postgres planning time is high across version (Expose buffer usage during planning in EXPLAIN)
Date: Thu, 2 Apr 2020 02:51:36 +0900
Message-ID: <7bdd1e99-335f-a24a-ffbd-8a578a761970@oss.nttdata.com> (raw)
In-Reply-To: <20200331013146.GA14618@telsasoft.com>
References: <16109-26a1a88651e90608@postgresql.org>
<20191112205506.rvadbx2dnku3paaw@alap3.anarazel.de>
<CAOBaU_ZfSUrU7Cuno_ycJDFDfqJH3jC0=2ou2GkcNy-P0UPy3A@mail.gmail.com>
<20200124055534.GM13621@telsasoft.com>
<CAOBaU_ZhmG7FZBH9z28nb7++zQ--FsqX_GcTefXa7oj1yrWnRg@mail.gmail.com>
<CAOBaU_YAN6PW4perkROgXWtRmDNX8tvKwjgDpsR6wYetEUahGQ@mail.gmail.com>
<20200331013146.GA14618@telsasoft.com>
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.
+/* 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.
+ 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.
+ "Planning Time": N.N, +
+ "Shared Hit Blocks": N, +
+ "Shared Read Blocks": N, +
+ "Shared Dirtied Blocks": N,+
Doesn't this indent look strange? IMO no indent for buffer usage is
necessary when the format is either json, xml, and yaml. This looks
better at least for me. OTOH, in text format, it seems better to indent
the buffer usage for more readability. Thought?
The patch changes the code so that "es->indent" is
increment/decrement only when the format is text.
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..b1f3fe13c6 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -372,7 +372,10 @@ ExplainOneQuery(Query *query, int cursorOptions,
PlannedStmt *plan;
instr_time planstart,
planduration;
+ BufferUsage bufusage_start,
+ bufusage;
+ bufusage_start = pgBufferUsage;
INSTR_TIME_SET_CURRENT(planstart);
/* plan the query */
@@ -381,9 +384,13 @@ ExplainOneQuery(Query *query, int cursorOptions,
INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);
+ /* calc differences of buffer counters. */
+ 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, &bufusage);
}
}
@@ -476,7 +483,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 +568,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 +578,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..d54568e7b2 100644
--- a/src/backend/commands/prepare.c
+++ b/src/backend/commands/prepare.c
@@ -616,7 +616,10 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
EState *estate = NULL;
instr_time planstart;
instr_time planduration;
+ BufferUsage bufusage_start,
+ bufusage;
+ bufusage_start = pgBufferUsage;
INSTR_TIME_SET_CURRENT(planstart);
/* Look it up in the hash table */
@@ -654,6 +657,10 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);
+ /* calc differences of buffer counters. */
+ memset(&bufusage, 0, sizeof(BufferUsage));
+ BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);
+
plan_list = cplan->stmt_list;
/* Explain each query */
@@ -663,7 +670,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
if (pstmt->commandType != CMD_UTILITY)
ExplainOnePlan(pstmt, into, es, query_string, paramLI, queryEnv,
- &planduration);
+ &planduration, &bufusage);
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 +
} +
]
Attachments:
[text/plain] show_planning_buffers-v4.patch (8.7K, ../7bdd1e99-335f-a24a-ffbd-8a578a761970@oss.nttdata.com/2-show_planning_buffers-v4.patch)
download | inline diff:
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index ee0e638f33..b1f3fe13c6 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -372,7 +372,10 @@ ExplainOneQuery(Query *query, int cursorOptions,
PlannedStmt *plan;
instr_time planstart,
planduration;
+ BufferUsage bufusage_start,
+ bufusage;
+ bufusage_start = pgBufferUsage;
INSTR_TIME_SET_CURRENT(planstart);
/* plan the query */
@@ -381,9 +384,13 @@ ExplainOneQuery(Query *query, int cursorOptions,
INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);
+ /* calc differences of buffer counters. */
+ 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, &bufusage);
}
}
@@ -476,7 +483,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 +568,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 +578,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..d54568e7b2 100644
--- a/src/backend/commands/prepare.c
+++ b/src/backend/commands/prepare.c
@@ -616,7 +616,10 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
EState *estate = NULL;
instr_time planstart;
instr_time planduration;
+ BufferUsage bufusage_start,
+ bufusage;
+ bufusage_start = pgBufferUsage;
INSTR_TIME_SET_CURRENT(planstart);
/* Look it up in the hash table */
@@ -654,6 +657,10 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);
+ /* calc differences of buffer counters. */
+ memset(&bufusage, 0, sizeof(BufferUsage));
+ BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);
+
plan_list = cplan->stmt_list;
/* Explain each query */
@@ -663,7 +670,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
if (pstmt->commandType != CMD_UTILITY)
ExplainOnePlan(pstmt, into, es, query_string, paramLI, queryEnv,
- &planduration);
+ &planduration, &bufusage);
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 +
} +
]
view thread (20+ messages) latest in thread
Message-ID: <7bdd1e99-335f-a24a-ffbd-8a578a761970@oss.nttdata.com>
Permalink: ../7bdd1e99-335f-a24a-ffbd-8a578a761970@oss.nttdata.com/
Also on: postgresql.org/message-id/7bdd1e99-335f-a24a-ffbd-8a578a761970@oss.nttdata.com
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-bugs@postgresql.org
Cc: masao.fujii@oss.nttdata.com, pryzby@telsasoft.com, rjuju123@gmail.com, andres@anarazel.de, pgsql-hackers@lists.postgresql.org
Subject: Re: BUG #16109: Postgres planning time is high across version (Expose buffer usage during planning in EXPLAIN)
In-Reply-To: <7bdd1e99-335f-a24a-ffbd-8a578a761970@oss.nttdata.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox