agora inbox for pgsql-bugs@postgresql.org
help / color / mirror / Atom feedFrom: Fujii Masao <masao.fujii@oss.nttdata.com>
To: Julien Rouhaud <rjuju123@gmail.com>
Cc: Justin Pryzby <pryzby@telsasoft.com>
Cc: Andres Freund <andres@anarazel.de>
Cc: PostgreSQL Hackers <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 13:05:56 +0900
Message-ID: <045faedf-108d-26e6-7307-ab1ac2d64624@oss.nttdata.com> (raw)
In-Reply-To: <CAOBaU_ZrKOMXLxxeqUvuFN1Xy2Kfmz7GFfT47ksCuecC8N2AOQ@mail.gmail.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>
<7bdd1e99-335f-a24a-ffbd-8a578a761970@oss.nttdata.com>
<CAOBaU_ZrKOMXLxxeqUvuFN1Xy2Kfmz7GFfT47ksCuecC8N2AOQ@mail.gmail.com>
On 2020/04/02 3:47, Julien Rouhaud wrote:
> On Wed, Apr 1, 2020 at 7:51 PM Fujii Masao <masao.fujii@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 +
} +
]
Attachments:
[text/plain] show_planning_buffers-v5.patch (8.8K, ../045faedf-108d-26e6-7307-ab1ac2d64624@oss.nttdata.com/2-show_planning_buffers-v5.patch)
download | inline diff:
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 +
} +
]
view thread (20+ messages) latest in thread
Message-ID: <045faedf-108d-26e6-7307-ab1ac2d64624@oss.nttdata.com>
Permalink: ../045faedf-108d-26e6-7307-ab1ac2d64624@oss.nttdata.com/
Also on: postgresql.org/message-id/045faedf-108d-26e6-7307-ab1ac2d64624@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, rjuju123@gmail.com, pryzby@telsasoft.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: <045faedf-108d-26e6-7307-ab1ac2d64624@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