[PG13] Planning (time + buffers) data structure in explain plan (format text)
Hi all,
As far as I understand, in the upcoming version 13, information about
buffers used during planning is now available in the explain plan.
[…]
Planning Time: 0.203 ms
Buffers: shared hit=14
[…]
In the JSON format, the data structure is a bit different:
[…]
"Planning": {
"Planning Time": 0.533,
"Shared Hit Blocks": 14,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
},
[…]
For a matter of consistency, I wonder if it would be possible to format
it like the following:
[…]
Planning:
Planning Time: 0.203 ms
Buffers: shared hit=14
[…]
Note: a similar way to format information is already used for JIT.
[…]
JIT:
Functions: 3
Options: Inlining false, Optimization false, Expressions true,
Deforming true
Timing: Generation 0.340 ms, Inlining 0.000 ms, Optimization 0.168
ms, Emission 1.907 ms, Total 2.414 ms
[…]
Regards,
Pierre
Hi,
On Fri, Aug 7, 2020 at 2:30 PM Pierre Giraud <pierre.giraud@dalibo.com> wrote:
Hi all,
As far as I understand, in the upcoming version 13, information about
buffers used during planning is now available in the explain plan.
Indeed.
[…]
Planning Time: 0.203 ms
Buffers: shared hit=14
[…]In the JSON format, the data structure is a bit different:
[…]
"Planning": {
"Planning Time": 0.533,
"Shared Hit Blocks": 14,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
},
[…]For a matter of consistency, I wonder if it would be possible to format
it like the following:[…]
Planning:
Planning Time: 0.203 ms
Buffers: shared hit=14
[…]
I agree that this output looks more consistent with other output,
including JIT as you mentioned. I'll send a patch for that if there's
no objection.
Out of curiosity, is the current text output actually harder to parse
than the one you're suggesting?
Le 07/08/2020 à 14:52, Julien Rouhaud a écrit :
Hi,
On Fri, Aug 7, 2020 at 2:30 PM Pierre Giraud <pierre.giraud@dalibo.com> wrote:
Hi all,
As far as I understand, in the upcoming version 13, information about
buffers used during planning is now available in the explain plan.Indeed.
[…]
Planning Time: 0.203 ms
Buffers: shared hit=14
[…]In the JSON format, the data structure is a bit different:
[…]
"Planning": {
"Planning Time": 0.533,
"Shared Hit Blocks": 14,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
},
[…]For a matter of consistency, I wonder if it would be possible to format
it like the following:[…]
Planning:
Planning Time: 0.203 ms
Buffers: shared hit=14
[…]I agree that this output looks more consistent with other output,
including JIT as you mentioned. I'll send a patch for that if there's
no objection.
Thanks a lot!
Out of curiosity, is the current text output actually harder to parse
than the one you're suggesting?
I don't want to speak in the name of developers of others parsing tools
but this should not require a lot of work to parse the output I'm proposing.
It would be nice to have their opinion though, especially Hubert depesz
Lubaczewski's since he already integrated the change:
https://gitlab.com/depesz/Pg--Explain/-/commit/4a760136ee69ee4929625d4e4022f79ac60b763f
However, as far as I know, he's not doing anything with the buffers
information with the "Planning" section yet.
To answer your question, I think that the new output would make the
parser a little bit easier to write because it would make things a bit
clearer (ie. more separated) so less prone to errors.
On Fri, Aug 7, 2020 at 3:51 PM Pierre Giraud <pierre.giraud@dalibo.com> wrote:
Le 07/08/2020 à 14:52, Julien Rouhaud a écrit :
Hi,
On Fri, Aug 7, 2020 at 2:30 PM Pierre Giraud <pierre.giraud@dalibo.com> wrote:
Hi all,
As far as I understand, in the upcoming version 13, information about
buffers used during planning is now available in the explain plan.Indeed.
[…]
Planning Time: 0.203 ms
Buffers: shared hit=14
[…]In the JSON format, the data structure is a bit different:
[…]
"Planning": {
"Planning Time": 0.533,
"Shared Hit Blocks": 14,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0
},
[…]For a matter of consistency, I wonder if it would be possible to format
it like the following:[…]
Planning:
Planning Time: 0.203 ms
Buffers: shared hit=14
[…]I agree that this output looks more consistent with other output,
including JIT as you mentioned. I'll send a patch for that if there's
no objection.Thanks a lot!
Out of curiosity, is the current text output actually harder to parse
than the one you're suggesting?I don't want to speak in the name of developers of others parsing tools
but this should not require a lot of work to parse the output I'm proposing.
It would be nice to have their opinion though, especially Hubert depesz
Lubaczewski's since he already integrated the change:
https://gitlab.com/depesz/Pg--Explain/-/commit/4a760136ee69ee4929625d4e4022f79ac60b763fHowever, as far as I know, he's not doing anything with the buffers
information with the "Planning" section yet.To answer your question, I think that the new output would make the
parser a little bit easier to write because it would make things a bit
clearer (ie. more separated) so less prone to errors.
Adding depesz.
On Fri, Aug 07, 2020 at 02:30:01PM +0200, Pierre Giraud wrote:
Hi all,
As far as I understand, in the upcoming version 13, information about
buffers used during planning is now available in the explain plan.[…]
Planning Time: 0.203 ms
Buffers: shared hit=14
[…]For a matter of consistency, I wonder if it would be possible to format
it like the following:[…]
Planning:
Planning Time: 0.203 ms
Buffers: shared hit=14
Thanks for reporting. I added this here.
https://wiki.postgresql.org/wiki/PostgreSQL_13_Open_Items
--
Justin
On Tue, Aug 18, 2020 at 10:27:06PM -0500, Justin Pryzby wrote:
On Fri, Aug 07, 2020 at 02:30:01PM +0200, Pierre Giraud wrote:
Hi all,
As far as I understand, in the upcoming version 13, information about
buffers used during planning is now available in the explain plan.[…]
Planning Time: 0.203 ms
Buffers: shared hit=14
[…]For a matter of consistency, I wonder if it would be possible to format
it like the following:[…]
Planning:
Planning Time: 0.203 ms
Buffers: shared hit=14Thanks for reporting. I added this here.
https://wiki.postgresql.org/wiki/PostgreSQL_13_Open_Items
Thanks Justin!
Hearing no objection, here's a patch to change the output as suggested by
Pierre:
=# explain (analyze, buffers) select * from pg_class;
QUERY PLAN >
------------------------------------------------------------------------------------------------------->
Seq Scan on pg_class (cost=0.00..16.86 rows=386 width=265) (actual time=0.020..0.561 rows=386 loops=1)
Buffers: shared hit=9 read=4
Planning:
Planning Time: 4.345 ms
Buffers: shared hit=103 read=12
Execution Time: 1.447 ms
(6 rows)
=# explain (analyze, buffers, format json) select * from pg_class;
QUERY PLAN
-------------------------------------
[ +
{ +
"Plan": { +
"Node Type": "Seq Scan", +
"Parallel Aware": false, +
[...]
"Temp Written Blocks": 0 +
}, +
"Planning": { +
"Planning Time": 4.494, +
"Shared Hit Blocks": 103, +
"Shared Read Blocks": 12, +
"Shared Dirtied Blocks": 0, +
"Shared Written Blocks": 0, +
"Local Hit Blocks": 0, +
"Local Read Blocks": 0, +
"Local Dirtied Blocks": 0, +
"Local Written Blocks": 0, +
"Temp Read Blocks": 0, +
"Temp Written Blocks": 0 +
}, +
"Triggers": [ +
], +
"Execution Time": 1.824 +
} +
]
(1 row)
Attachments:
fix_explain_planning-v1.difftext/plain; charset=us-asciiDownload
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 30e0a7ee7f..375431acee 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -587,7 +587,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
ExplainPrintPlan(es, queryDesc);
if (es->summary && (planduration || bufusage))
+ {
ExplainOpenGroup("Planning", "Planning", true, es);
+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ {
+ ExplainIndentText(es);
+ appendStringInfoString(es->str, "Planning:\n");
+ es->indent++;
+ }
+ }
if (es->summary && planduration)
{
@@ -598,16 +606,14 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *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))
+ {
+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ es->indent--;
ExplainCloseGroup("Planning", "Planning", true, es);
+ }
/* Print info about runtime of triggers */
if (es->analyze)
On Wed, 19 Aug 2020 at 19:22, Julien Rouhaud <rjuju123@gmail.com> wrote:
Hearing no objection, here's a patch to change the output as suggested by
Pierre:=# explain (analyze, buffers) select * from pg_class;
QUERY PLAN >
------------------------------------------------------------------------------------------------------->
Seq Scan on pg_class (cost=0.00..16.86 rows=386 width=265) (actual time=0.020..0.561 rows=386 loops=1)
Buffers: shared hit=9 read=4
Planning:
Planning Time: 4.345 ms
Buffers: shared hit=103 read=12
Execution Time: 1.447 ms
(6 rows)
I don't really have anything to say about the change in format, but on
looking at the feature, I do find it strange that I need to specify
ANALYZE to get EXPLAIN to output the buffer information for the
planner.
I'd expect that EXPLAIN (BUFFERS) would work just fine, but I get:
ERROR: EXPLAIN option BUFFERS requires ANALYZE
Ths docs [1]https://www.postgresql.org/docs/devel/sql-explain.html also mention this is disallowed per:
"This parameter may only be used when ANALYZE is also enabled."
I just don't agree that it should be. What if I want to get an
indication of why the planner is slow but I don't want to wait for the
query to execute? or don't want to execute it at all, say it's a
DELETE!
It looks like we'd need to make BUFFERS imply SUMMARY, perhaps
something along the lines of what we do now with ANALYZE with:
/* if the summary was not set explicitly, set default value */
es->summary = (summary_set) ? es->summary : es->analyze;
However, I'm not quite sure how we should handle if someone does:
EXPLAIN (BUFFERS on, SUMMARY off). Without the summary, there's no
place to print the buffers, which seems bad as they asked for buffers.
David
On Wed, Aug 19, 2020 at 08:49:48PM +1200, David Rowley wrote:
On Wed, 19 Aug 2020 at 19:22, Julien Rouhaud <rjuju123@gmail.com> wrote:
Hearing no objection, here's a patch to change the output as suggested by
Pierre:=# explain (analyze, buffers) select * from pg_class;
QUERY PLAN >
------------------------------------------------------------------------------------------------------->
Seq Scan on pg_class (cost=0.00..16.86 rows=386 width=265) (actual time=0.020..0.561 rows=386 loops=1)
Buffers: shared hit=9 read=4
Planning:
Planning Time: 4.345 ms
Buffers: shared hit=103 read=12
Execution Time: 1.447 ms
(6 rows)I don't really have anything to say about the change in format, but on
looking at the feature, I do find it strange that I need to specify
ANALYZE to get EXPLAIN to output the buffer information for the
planner.I'd expect that EXPLAIN (BUFFERS) would work just fine, but I get:
ERROR: EXPLAIN option BUFFERS requires ANALYZE
Ths docs [1] also mention this is disallowed per:
"This parameter may only be used when ANALYZE is also enabled."
I just don't agree that it should be. What if I want to get an
indication of why the planner is slow but I don't want to wait for the
query to execute? or don't want to execute it at all, say it's a
DELETE!
I quite agree, this restriction is unhelpful since we have planning buffer
information.
It looks like we'd need to make BUFFERS imply SUMMARY
+1
However, I'm not quite sure how we should handle if someone does:
EXPLAIN (BUFFERS on, SUMMARY off). Without the summary, there's no
place to print the buffers, which seems bad as they asked for buffers.
But this won't be as much a problem if ANALYZE is asked, and having different
behaviors isn't appealing. So maybe it's better to let people get what they
asked for even if that's contradictory?
On Wed, 19 Aug 2020 at 21:05, Julien Rouhaud <rjuju123@gmail.com> wrote:
On Wed, Aug 19, 2020 at 08:49:48PM +1200, David Rowley wrote:
However, I'm not quite sure how we should handle if someone does:
EXPLAIN (BUFFERS on, SUMMARY off). Without the summary, there's no
place to print the buffers, which seems bad as they asked for buffers.But this won't be as much a problem if ANALYZE is asked, and having different
behaviors isn't appealing. So maybe it's better to let people get what they
asked for even if that's contradictory?
I'd say BUFFERS on, BUFFERS off is contradictory. I don't think
BUFFERS, SUMMARY OFF is. It's just that we show the buffer details for
the planner in the summary. Since "summary" is not exactly a word
that describes what you're asking EXPLAIN to do, I wouldn't blame
users if they got confused as to why their BUFFERS on request was not
displayed.
We do use errors for weird combinations already, e.g:
postgres=# explain (timing on) select * from t1 where a > 4000000;
ERROR: EXPLAIN option TIMING requires ANALYZE
so, maybe we can just error if analyze == off AND buffers == on AND
summary == off. We likely should pay attention to analyze there as it
seems perfectly fine to EXPLAIN (ANALYZE, BUFFERS, SUMMARY off). We
quite often do SUMMARY off for the regression tests... I think that
might have been why it was added in the first place.
David
On Wed, 19 Aug 2020 at 22:39, David Rowley <dgrowleyml@gmail.com> wrote:
so, maybe we can just error if analyze == off AND buffers == on AND
summary == off. We likely should pay attention to analyze there as it
seems perfectly fine to EXPLAIN (ANALYZE, BUFFERS, SUMMARY off). We
quite often do SUMMARY off for the regression tests... I think that
might have been why it was added in the first place.
I had something like the attached in mind.
postgres=# explain (buffers) select * from t1 where a > 4000000;
QUERY PLAN
--------------------------------------------------------------------------
Index Only Scan using t1_pkey on t1 (cost=0.42..10.18 rows=100 width=4)
Index Cond: (a > 4000000)
Planning Time: 13.341 ms
Buffers: shared hit=2735
(4 rows)
It does look a bit weirder if the planner didn't do any buffer work:
postgres=# explain (buffers) select * from pg_class;
QUERY PLAN
--------------------------------------------------------------
Seq Scan on pg_class (cost=0.00..443.08 rows=408 width=768)
Planning Time: 0.136 ms
(2 rows)
but that's not a combination that people were able to use before, so I
think it's ok to show the planning time there.
David
Attachments:
explain_buffers_without_analyze.patchapplication/octet-stream; name=explain_buffers_without_analyze.patchDownload
diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index 1c19e254dc..906b2ccd50 100644
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -187,8 +187,7 @@ ROLLBACK;
query processing.
The number of blocks shown for an
upper-level node includes those used by all its child nodes. In text
- format, only non-zero values are printed. This parameter may only be
- used when <literal>ANALYZE</literal> is also enabled. It defaults to
+ format, only non-zero values are printed. It defaults to
<literal>FALSE</literal>.
</para>
</listitem>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 4cb3215728..7289054209 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -223,10 +223,13 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
parser_errposition(pstate, opt->location)));
}
- if (es->buffers && !es->analyze)
+ /* if the summary was not set explicitly, enable it if buffers are */
+ es->summary = (summary_set) ? es->summary : es->buffers;
+
+ if (es->buffers && !es->analyze && !es->summary)
ereport(ERROR,
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
- errmsg("EXPLAIN option BUFFERS requires ANALYZE")));
+ errmsg("EXPLAIN option BUFFERS requires ANALYZE or SUMMARY")));
if (es->wal && !es->analyze)
ereport(ERROR,
@@ -242,8 +245,8 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
errmsg("EXPLAIN option TIMING requires ANALYZE")));
- /* if the summary was not set explicitly, set default value */
- es->summary = (summary_set) ? es->summary : es->analyze;
+ /* if the summary was not set explicitly, enable it if analyze is on. */
+ es->summary |= (summary_set) ? es->summary : es->analyze;
/*
* Parse analysis was done already, but we still have to run the rule
On 2020/08/19 19:39, David Rowley wrote:
On Wed, 19 Aug 2020 at 21:05, Julien Rouhaud <rjuju123@gmail.com> wrote:
On Wed, Aug 19, 2020 at 08:49:48PM +1200, David Rowley wrote:
However, I'm not quite sure how we should handle if someone does:
EXPLAIN (BUFFERS on, SUMMARY off). Without the summary, there's no
place to print the buffers, which seems bad as they asked for buffers.But this won't be as much a problem if ANALYZE is asked, and having different
behaviors isn't appealing. So maybe it's better to let people get what they
asked for even if that's contradictory?I'd say BUFFERS on, BUFFERS off is contradictory. I don't think
BUFFERS, SUMMARY OFF is. It's just that we show the buffer details for
the planner in the summary. Since "summary" is not exactly a word
that describes what you're asking EXPLAIN to do, I wouldn't blame
users if they got confused as to why their BUFFERS on request was not
displayed.
Displaying the planner's buffer usage under summary is the root cause of
the confusion? If so, what about displaying that outside summary?
Attached is the POC patch that I'm just thinking.
With the patch, for example, whatever "summary" settng is, "buffers on"
displays the planner's buffer usage if it happens.
=# explain (buffers on, summary off) select * from t;
QUERY PLAN
-----------------------------------------------------
Seq Scan on t (cost=0.00..32.60 rows=2260 width=8)
Planning:
Buffers: shared hit=16 read=6
(3 rows)
If "summary" is enabled, the planning time is also displayed.
=# explain (buffers on, summary on) select * from t;
QUERY PLAN
-----------------------------------------------------
Seq Scan on t (cost=0.00..32.60 rows=2260 width=8)
Planning:
Buffers: shared hit=16 read=6
Planning Time: 0.904 ms
(4 rows)
If the planner's buffer usage doesn't happen, it's not displayed
(in text format).
=# explain (buffers on, summary on) select * from t;
QUERY PLAN
-----------------------------------------------------
Seq Scan on t (cost=0.00..32.60 rows=2260 width=8)
Planning Time: 0.064 ms
(2 rows)
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
Attachments:
explain_exclude_planning_buffers_from_summary.patchtext/plain; charset=UTF-8; name=explain_exclude_planning_buffers_from_summary.patch; x-mac-creator=0; x-mac-type=0Download
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 30e0a7ee7f..c98c9b5547 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -116,7 +116,8 @@ static void show_instrumentation_count(const char *qlabel, int which,
static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es);
static void show_eval_params(Bitmapset *bms_params, ExplainState *es);
static const char *explain_get_index_name(Oid indexId);
-static void show_buffer_usage(ExplainState *es, const BufferUsage *usage);
+static void show_buffer_usage(ExplainState *es, const BufferUsage *usage,
+ bool planning);
static void show_wal_usage(ExplainState *es, const WalUsage *usage);
static void ExplainIndexScanDetails(Oid indexid, ScanDirection indexorderdir,
ExplainState *es);
@@ -221,11 +222,6 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
parser_errposition(pstate, opt->location)));
}
- if (es->buffers && !es->analyze)
- ereport(ERROR,
- (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
- errmsg("EXPLAIN option BUFFERS requires ANALYZE")));
-
if (es->wal && !es->analyze)
ereport(ERROR,
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
@@ -586,8 +582,13 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
/* Create textual dump of plan tree */
ExplainPrintPlan(es, queryDesc);
- if (es->summary && (planduration || bufusage))
+ /* Show buffer usage in planning */
+ if (bufusage)
+ {
ExplainOpenGroup("Planning", "Planning", true, es);
+ show_buffer_usage(es, bufusage, true);
+ ExplainCloseGroup("Planning", "Planning", true, es);
+ }
if (es->summary && planduration)
{
@@ -596,19 +597,6 @@ 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);
@@ -1996,7 +1984,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
/* Show buffer/WAL usage */
if (es->buffers && planstate->instrument)
- show_buffer_usage(es, &planstate->instrument->bufusage);
+ show_buffer_usage(es, &planstate->instrument->bufusage, false);
if (es->wal && planstate->instrument)
show_wal_usage(es, &planstate->instrument->walusage);
@@ -2015,7 +2003,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
ExplainOpenWorker(n, es);
if (es->buffers)
- show_buffer_usage(es, &instrument->bufusage);
+ show_buffer_usage(es, &instrument->bufusage, false);
if (es->wal)
show_wal_usage(es, &instrument->walusage);
ExplainCloseWorker(n, es);
@@ -3301,7 +3289,7 @@ explain_get_index_name(Oid indexId)
* Show buffer usage details.
*/
static void
-show_buffer_usage(ExplainState *es, const BufferUsage *usage)
+show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
{
if (es->format == EXPLAIN_FORMAT_TEXT)
{
@@ -3317,6 +3305,15 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage)
usage->temp_blks_written > 0);
bool has_timing = (!INSTR_TIME_IS_ZERO(usage->blk_read_time) ||
!INSTR_TIME_IS_ZERO(usage->blk_write_time));
+ bool show_planning = (planning && (has_shared ||
+ has_local || has_temp || has_timing));
+
+ if (show_planning)
+ {
+ ExplainIndentText(es);
+ appendStringInfoString(es->str, "Planning:\n");
+ es->indent++;
+ }
/* Show only positive counter values. */
if (has_shared || has_local || has_temp)
@@ -3386,6 +3383,9 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage)
INSTR_TIME_GET_MILLISEC(usage->blk_write_time));
appendStringInfoChar(es->str, '\n');
}
+
+ if (show_planning)
+ es->indent--;
}
else
{
On Thu, 20 Aug 2020 at 03:31, Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
On 2020/08/19 19:39, David Rowley wrote:
On Wed, 19 Aug 2020 at 21:05, Julien Rouhaud <rjuju123@gmail.com> wrote:
On Wed, Aug 19, 2020 at 08:49:48PM +1200, David Rowley wrote:
However, I'm not quite sure how we should handle if someone does:
EXPLAIN (BUFFERS on, SUMMARY off). Without the summary, there's no
place to print the buffers, which seems bad as they asked for buffers.But this won't be as much a problem if ANALYZE is asked, and having different
behaviors isn't appealing. So maybe it's better to let people get what they
asked for even if that's contradictory?I'd say BUFFERS on, BUFFERS off is contradictory. I don't think
BUFFERS, SUMMARY OFF is. It's just that we show the buffer details for
the planner in the summary. Since "summary" is not exactly a word
that describes what you're asking EXPLAIN to do, I wouldn't blame
users if they got confused as to why their BUFFERS on request was not
displayed.Displaying the planner's buffer usage under summary is the root cause of
the confusion? If so, what about displaying that outside summary?
Attached is the POC patch that I'm just thinking.
I had a look at this and I like it better than what I proposed earlier.
The change to show_buffer_usage() is a bit ugly, but I'm not really
seeing a better way to do it. Perhaps that can be improved later if we
ever find that there's some other special case to add.
David
On Thu, 20 Aug 2020 at 03:31, Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
With the patch, for example, whatever "summary" settng is, "buffers on"
displays the planner's buffer usage if it happens.
I forgot to mention earlier, you'll also need to remove the part in
the docs that mentions BUFFERS requires ANALYZE.
David
On 2020/08/20 13:00, David Rowley wrote:
On Thu, 20 Aug 2020 at 03:31, Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
With the patch, for example, whatever "summary" settng is, "buffers on"
displays the planner's buffer usage if it happens.I forgot to mention earlier, you'll also need to remove the part in
the docs that mentions BUFFERS requires ANALYZE.
Thanks for the review! I removed that.
Attached is the updated version of the patch.
I also added the regression test performing "explain (buffers on)"
without "analyze" option.
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
Attachments:
explain_exclude_planning_buffers_from_summary_v2.patchtext/plain; charset=UTF-8; name=explain_exclude_planning_buffers_from_summary_v2.patch; x-mac-creator=0; x-mac-type=0Download
diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index 1c19e254dc..906b2ccd50 100644
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -187,8 +187,7 @@ ROLLBACK;
query processing.
The number of blocks shown for an
upper-level node includes those used by all its child nodes. In text
- format, only non-zero values are printed. This parameter may only be
- used when <literal>ANALYZE</literal> is also enabled. It defaults to
+ format, only non-zero values are printed. It defaults to
<literal>FALSE</literal>.
</para>
</listitem>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 30e0a7ee7f..c98c9b5547 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -116,7 +116,8 @@ static void show_instrumentation_count(const char *qlabel, int which,
static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es);
static void show_eval_params(Bitmapset *bms_params, ExplainState *es);
static const char *explain_get_index_name(Oid indexId);
-static void show_buffer_usage(ExplainState *es, const BufferUsage *usage);
+static void show_buffer_usage(ExplainState *es, const BufferUsage *usage,
+ bool planning);
static void show_wal_usage(ExplainState *es, const WalUsage *usage);
static void ExplainIndexScanDetails(Oid indexid, ScanDirection indexorderdir,
ExplainState *es);
@@ -221,11 +222,6 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
parser_errposition(pstate, opt->location)));
}
- if (es->buffers && !es->analyze)
- ereport(ERROR,
- (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
- errmsg("EXPLAIN option BUFFERS requires ANALYZE")));
-
if (es->wal && !es->analyze)
ereport(ERROR,
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
@@ -586,8 +582,13 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
/* Create textual dump of plan tree */
ExplainPrintPlan(es, queryDesc);
- if (es->summary && (planduration || bufusage))
+ /* Show buffer usage in planning */
+ if (bufusage)
+ {
ExplainOpenGroup("Planning", "Planning", true, es);
+ show_buffer_usage(es, bufusage, true);
+ ExplainCloseGroup("Planning", "Planning", true, es);
+ }
if (es->summary && planduration)
{
@@ -596,19 +597,6 @@ 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);
@@ -1996,7 +1984,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
/* Show buffer/WAL usage */
if (es->buffers && planstate->instrument)
- show_buffer_usage(es, &planstate->instrument->bufusage);
+ show_buffer_usage(es, &planstate->instrument->bufusage, false);
if (es->wal && planstate->instrument)
show_wal_usage(es, &planstate->instrument->walusage);
@@ -2015,7 +2003,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
ExplainOpenWorker(n, es);
if (es->buffers)
- show_buffer_usage(es, &instrument->bufusage);
+ show_buffer_usage(es, &instrument->bufusage, false);
if (es->wal)
show_wal_usage(es, &instrument->walusage);
ExplainCloseWorker(n, es);
@@ -3301,7 +3289,7 @@ explain_get_index_name(Oid indexId)
* Show buffer usage details.
*/
static void
-show_buffer_usage(ExplainState *es, const BufferUsage *usage)
+show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
{
if (es->format == EXPLAIN_FORMAT_TEXT)
{
@@ -3317,6 +3305,15 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage)
usage->temp_blks_written > 0);
bool has_timing = (!INSTR_TIME_IS_ZERO(usage->blk_read_time) ||
!INSTR_TIME_IS_ZERO(usage->blk_write_time));
+ bool show_planning = (planning && (has_shared ||
+ has_local || has_temp || has_timing));
+
+ if (show_planning)
+ {
+ ExplainIndentText(es);
+ appendStringInfoString(es->str, "Planning:\n");
+ es->indent++;
+ }
/* Show only positive counter values. */
if (has_shared || has_local || has_temp)
@@ -3386,6 +3383,9 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage)
INSTR_TIME_GET_MILLISEC(usage->blk_write_time));
appendStringInfoChar(es->str, '\n');
}
+
+ if (show_planning)
+ es->indent--;
}
else
{
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 96baba038c..a1ee6c6792 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -106,7 +106,6 @@ select explain_filter('explain (analyze, buffers, format json) select * from int
"Temp Written Blocks": N +
}, +
"Planning": { +
- "Planning Time": N.N, +
"Shared Hit Blocks": N, +
"Shared Read Blocks": N, +
"Shared Dirtied Blocks": N, +
@@ -118,6 +117,7 @@ select explain_filter('explain (analyze, buffers, format json) select * from int
"Temp Read Blocks": N, +
"Temp Written Blocks": N +
}, +
+ "Planning Time": N.N, +
"Triggers": [ +
], +
"Execution Time": N.N +
@@ -155,7 +155,6 @@ select explain_filter('explain (analyze, buffers, format xml) select * from int8
<Temp-Written-Blocks>N</Temp-Written-Blocks> +
</Plan> +
<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>+
@@ -167,6 +166,7 @@ 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> +
</Planning> +
+ <Planning-Time>N.N</Planning-Time> +
<Triggers> +
</Triggers> +
<Execution-Time>N.N</Execution-Time> +
@@ -201,7 +201,6 @@ select explain_filter('explain (analyze, buffers, format yaml) select * from int
Temp Read Blocks: N +
Temp Written Blocks: N +
Planning: +
- Planning Time: N.N +
Shared Hit Blocks: N +
Shared Read Blocks: N +
Shared Dirtied Blocks: N +
@@ -212,10 +211,58 @@ 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 +
Triggers: +
Execution Time: N.N
(1 row)
+select explain_filter('explain (buffers, format text) select * from int8_tbl i8');
+ explain_filter
+---------------------------------------------------------
+ Seq Scan on int8_tbl i8 (cost=N.N..N.N rows=N width=N)
+(1 row)
+
+select explain_filter('explain (buffers, format json) select * from int8_tbl i8');
+ explain_filter
+------------------------------------
+ [ +
+ { +
+ "Plan": { +
+ "Node Type": "Seq Scan", +
+ "Parallel Aware": false, +
+ "Relation Name": "int8_tbl",+
+ "Alias": "i8", +
+ "Startup Cost": N.N, +
+ "Total Cost": N.N, +
+ "Plan Rows": N, +
+ "Plan Width": 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 +
+ }, +
+ "Planning": { +
+ "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 +
+ } +
+ } +
+ ]
+(1 row)
+
-- SETTINGS option
-- We have to ignore other settings that might be imposed by the environment,
-- so printing the whole Settings field unfortunately won't do.
@@ -402,7 +449,6 @@ select jsonb_pretty(
"Shared Written Blocks": 0 +
}, +
"Planning": { +
- "Planning Time": 0.0, +
"Local Hit Blocks": 0, +
"Temp Read Blocks": 0, +
"Local Read Blocks": 0, +
@@ -416,6 +462,7 @@ select jsonb_pretty(
}, +
"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 dce2a34207..01783c607a 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -57,6 +57,8 @@ select explain_filter('explain (analyze, buffers, format text) select * from int
select explain_filter('explain (analyze, buffers, format json) select * from int8_tbl i8');
select explain_filter('explain (analyze, buffers, format xml) select * from int8_tbl i8');
select explain_filter('explain (analyze, buffers, format yaml) select * from int8_tbl i8');
+select explain_filter('explain (buffers, format text) select * from int8_tbl i8');
+select explain_filter('explain (buffers, format json) select * from int8_tbl i8');
-- SETTINGS option
-- We have to ignore other settings that might be imposed by the environment,
Can you please show what the plan would look like for?
=# explain (buffers on, summary on, format JSON) select * from t;
Le 20/08/2020 à 09:58, Fujii Masao a écrit :
Show quoted text
On 2020/08/20 13:00, David Rowley wrote:
On Thu, 20 Aug 2020 at 03:31, Fujii Masao
<masao.fujii@oss.nttdata.com> wrote:With the patch, for example, whatever "summary" settng is, "buffers on"
displays the planner's buffer usage if it happens.I forgot to mention earlier, you'll also need to remove the part in
the docs that mentions BUFFERS requires ANALYZE.Thanks for the review! I removed that.
Attached is the updated version of the patch.
I also added the regression test performing "explain (buffers on)"
without "analyze" option.Regards,
On 2020/08/20 17:03, Pierre Giraud wrote:
Can you please show what the plan would look like for?
=# explain (buffers on, summary on, format JSON) select * from t;
With my patch, the following is reported in that case.
=# explain (buffers on, summary on, format JSON) select * from pg_class;
QUERY PLAN
------------------------------------
[ +
{ +
"Plan": { +
"Node Type": "Seq Scan", +
"Parallel Aware": false, +
"Relation Name": "pg_class",+
"Alias": "pg_class", +
"Startup Cost": 0.00, +
"Total Cost": 16.87, +
"Plan Rows": 387, +
"Plan Width": 265, +
"Shared Hit Blocks": 0, +
"Shared Read Blocks": 0, +
"Shared Dirtied Blocks": 0, +
"Shared Written Blocks": 0, +
"Local Hit Blocks": 0, +
"Local Read Blocks": 0, +
"Local Dirtied Blocks": 0, +
"Local Written Blocks": 0, +
"Temp Read Blocks": 0, +
"Temp Written Blocks": 0 +
}, +
"Planning": { +
"Shared Hit Blocks": 103, +
"Shared Read Blocks": 12, +
"Shared Dirtied Blocks": 0, +
"Shared Written Blocks": 0, +
"Local Hit Blocks": 0, +
"Local Read Blocks": 0, +
"Local Dirtied Blocks": 0, +
"Local Written Blocks": 0, +
"Temp Read Blocks": 0, +
"Temp Written Blocks": 0 +
}, +
"Planning Time": 8.132 +
} +
]
(1 row)
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
On Thu, 20 Aug 2020 at 19:58, Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
On 2020/08/20 13:00, David Rowley wrote:
I forgot to mention earlier, you'll also need to remove the part in
the docs that mentions BUFFERS requires ANALYZE.Thanks for the review! I removed that.
Attached is the updated version of the patch.
I also added the regression test performing "explain (buffers on)"
without "analyze" option.
Looks good to me.
David
On Thu, Aug 20, 2020 at 12:29 PM David Rowley <dgrowleyml@gmail.com> wrote:
On Thu, 20 Aug 2020 at 19:58, Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
On 2020/08/20 13:00, David Rowley wrote:
I forgot to mention earlier, you'll also need to remove the part in
the docs that mentions BUFFERS requires ANALYZE.Thanks for the review! I removed that.
Attached is the updated version of the patch.
I also added the regression test performing "explain (buffers on)"
without "analyze" option.Looks good to me.
Looks good to me too.
On 2020/08/20 22:34, Julien Rouhaud wrote:
On Thu, Aug 20, 2020 at 12:29 PM David Rowley <dgrowleyml@gmail.com> wrote:
On Thu, 20 Aug 2020 at 19:58, Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
On 2020/08/20 13:00, David Rowley wrote:
I forgot to mention earlier, you'll also need to remove the part in
the docs that mentions BUFFERS requires ANALYZE.Thanks for the review! I removed that.
Attached is the updated version of the patch.
I also added the regression test performing "explain (buffers on)"
without "analyze" option.Looks good to me.
Looks good to me too.
David and Julien, thanks for the review! I'd like to wait for
Pierre's opinion about this change before committing the patch.
Pierre,
could you share your opinion about this change?
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
Le 20/08/2020 à 17:41, Fujii Masao a écrit :
On 2020/08/20 22:34, Julien Rouhaud wrote:
On Thu, Aug 20, 2020 at 12:29 PM David Rowley <dgrowleyml@gmail.com>
wrote:On Thu, 20 Aug 2020 at 19:58, Fujii Masao
<masao.fujii@oss.nttdata.com> wrote:On 2020/08/20 13:00, David Rowley wrote:
I forgot to mention earlier, you'll also need to remove the part in
the docs that mentions BUFFERS requires ANALYZE.Thanks for the review! I removed that.
Attached is the updated version of the patch.
I also added the regression test performing "explain (buffers on)"
without "analyze" option.Looks good to me.
Looks good to me too.
David and Julien, thanks for the review! I'd like to wait for
Pierre's opinion about this change before committing the patch.Pierre,
could you share your opinion about this change?
It looks good to me too. Thanks a lot!
Let's not forget to notify Hubert (depesz) once integrated.
Show quoted text
Regards,
On 2020/08/21 14:54, Pierre Giraud wrote:
Le 20/08/2020 à 17:41, Fujii Masao a écrit :
On 2020/08/20 22:34, Julien Rouhaud wrote:
On Thu, Aug 20, 2020 at 12:29 PM David Rowley <dgrowleyml@gmail.com>
wrote:On Thu, 20 Aug 2020 at 19:58, Fujii Masao
<masao.fujii@oss.nttdata.com> wrote:On 2020/08/20 13:00, David Rowley wrote:
I forgot to mention earlier, you'll also need to remove the part in
the docs that mentions BUFFERS requires ANALYZE.Thanks for the review! I removed that.
Attached is the updated version of the patch.
I also added the regression test performing "explain (buffers on)"
without "analyze" option.Looks good to me.
Looks good to me too.
David and Julien, thanks for the review! I'd like to wait for
Pierre's opinion about this change before committing the patch.Pierre,
could you share your opinion about this change?It looks good to me too. Thanks a lot!
Pushed. Thanks!
Let's not forget to notify Hubert (depesz) once integrated.
You're going to do that?
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
Fujii Masao <masao.fujii@oss.nttdata.com> writes:
Pushed. Thanks!
Buildfarm shows this patch has got problems under
-DRELCACHE_FORCE_RELEASE and/or -DCATCACHE_FORCE_RELEASE:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&dt=2020-08-21%2011%3A54%3A12
regards, tom lane
On 2020/08/21 23:53, Tom Lane wrote:
Fujii Masao <masao.fujii@oss.nttdata.com> writes:
Pushed. Thanks!
Buildfarm shows this patch has got problems under
-DRELCACHE_FORCE_RELEASE and/or -DCATCACHE_FORCE_RELEASE:https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&dt=2020-08-21%2011%3A54%3A12
Thanks for the report!
This happens because, in text format, whether "Planning:" line is output
varies depending on the system state. So explain_filter() should ignore
"Planning:" line. Patch attached. I'm now checking whether the patched
version works fine.
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
Attachments:
bugfix.patchtext/plain; charset=UTF-8; name=bugfix.patch; x-mac-creator=0; x-mac-type=0Download
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index a1ee6c6792..dc7ab2ce8b 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -23,6 +23,9 @@ begin
-- Ignore text-mode buffers output because it varies depending
-- on the system state
CONTINUE WHEN (ln ~ ' +Buffers: .*');
+ -- Ignore text-mode "Planning:" line because whether it's output
+ -- varies depending on the system state
+ CONTINUE WHEN (ln = 'Planning:');
return next ln;
end loop;
end;
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index 01783c607a..c79116c927 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -25,6 +25,9 @@ begin
-- Ignore text-mode buffers output because it varies depending
-- on the system state
CONTINUE WHEN (ln ~ ' +Buffers: .*');
+ -- Ignore text-mode "Planning:" line because whether it's output
+ -- varies depending on the system state
+ CONTINUE WHEN (ln = 'Planning:');
return next ln;
end loop;
end;
On 2020/08/22 1:04, Fujii Masao wrote:
On 2020/08/21 23:53, Tom Lane wrote:
Fujii Masao <masao.fujii@oss.nttdata.com> writes:
Pushed. Thanks!
Buildfarm shows this patch has got problems under
-DRELCACHE_FORCE_RELEASE and/or -DCATCACHE_FORCE_RELEASE:https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&dt=2020-08-21%2011%3A54%3A12
Thanks for the report!
This happens because, in text format, whether "Planning:" line is output
varies depending on the system state. So explain_filter() should ignore
"Planning:" line. Patch attached. I'm now checking whether the patched
version works fine.
I pushed the patch.
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
On Fri, Aug 21, 2020 at 07:54:13AM +0200, Pierre Giraud wrote:
It looks good to me too. Thanks a lot!
Let's not forget to notify Hubert (depesz) once integrated.
Thanks a lot, and sorry for not responding earlier - vacation.
Best regards,
depesz