Thread: pgsql: Include information on buffer usage during planning phase, in EX
Include information on buffer usage during planning phase, in EXPLAIN output. When BUFFERS option is enabled, EXPLAIN command includes the information on buffer usage during each plan node, in its output. In addition to that, this commit makes EXPLAIN command include also the information on buffer usage during planning phase, in its output. This feature makes it easier to discern the cases where lots of buffer access happen during planning. Author: Julien Rouhaud, slightly revised by Fujii Masao Reviewed-by: Justin Pryzby Discussion: https://postgr.es/m/16109-26a1a88651e90608@postgresql.org Branch ------ master Details ------- https://git.postgresql.org/pg/commitdiff/ed7a5095716ee498ecc406e1b8d5ab92c7662d10 Modified Files -------------- src/backend/commands/explain.c | 32 ++++++++++++++++++-- src/backend/commands/prepare.c | 13 ++++++++- src/include/commands/explain.h | 3 +- src/test/regress/expected/explain.out | 55 ++++++++++++++++++++++++++++++++--- 4 files changed, 95 insertions(+), 8 deletions(-)
Re: pgsql: Include information on buffer usage during planningphase, in EX
From
Michael Paquier
Date:
Hi Fujii-san, On Fri, Apr 03, 2020 at 02:28:27AM +0000, Fujii Masao wrote: > Include information on buffer usage during planning phase, in EXPLAIN output. > > When BUFFERS option is enabled, EXPLAIN command includes the information > on buffer usage during each plan node, in its output. In addition to that, > this commit makes EXPLAIN command include also the information on > buffer usage during planning phase, in its output. This feature makes it > easier to discern the cases where lots of buffer access happen during > planning. prion did not like that: https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&dt=2020-04-03%2002%3A33%3A13 Here is the diff from test explain: @@ -73,8 +73,9 @@ Seq Scan on int8_tbl i8 (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N) Buffers: shared [read] Planning Time: N.N ms + Buffers: shared [read] Execution Time: N.N ms -(4 rows) +(5 rows) Note that this animal uses -DRELCACHE_FORCE_RELEASE and -DCATCACHE_FORCE_RELEASE. -- Michael
Attachment
On 2020/04/03 11:58, Michael Paquier wrote: > Hi Fujii-san, > > On Fri, Apr 03, 2020 at 02:28:27AM +0000, Fujii Masao wrote: >> Include information on buffer usage during planning phase, in EXPLAIN output. >> >> When BUFFERS option is enabled, EXPLAIN command includes the information >> on buffer usage during each plan node, in its output. In addition to that, >> this commit makes EXPLAIN command include also the information on >> buffer usage during planning phase, in its output. This feature makes it >> easier to discern the cases where lots of buffer access happen during >> planning. > > prion did not like that: > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&dt=2020-04-03%2002%3A33%3A13 > > Here is the diff from test explain: > @@ -73,8 +73,9 @@ > Seq Scan on int8_tbl i8 (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N) > Buffers: shared [read] > Planning Time: N.N ms > + Buffers: shared [read] > Execution Time: N.N ms > -(4 rows) > +(5 rows) > > Note that this animal uses -DRELCACHE_FORCE_RELEASE and > -DCATCACHE_FORCE_RELEASE. Thanks for reporting that! Since we're now developing very heavily because of the last CF, it's not good to keep the buildfarm red for a long time. So I just reverted the commit. Then I will consider how to address the issue. Regards, -- Fujii Masao Advanced Computing Technology Center Research and Development Headquarters NTT DATA CORPORATION
Fujii Masao <masao.fujii@oss.nttdata.com> 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, 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 ... regards, tom lane
On 2020/04/03 12:30, Tom Lane wrote: > Fujii Masao <masao.fujii@oss.nttdata.com> 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? 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 Regards, -- Fujii Masao Advanced Computing Technology Center Research and Development Headquarters NTT DATA CORPORATION
Re: pgsql: Include information on buffer usage during planningphase, in EX
From
Julien Rouhaud
Date:
On Fri, Apr 03, 2020 at 03:24:41PM +0900, Fujii Masao wrote: > > > On 2020/04/03 12:30, Tom Lane wrote: > > Fujii Masao <masao.fujii@oss.nttdata.com> 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. Nitpicking, but I think that planning_time_found, or something similar, would be better here.
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 <masao.fujii@oss.nttdata.com> 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
Attachment
Re: pgsql: Include information on buffer usage during planningphase, in EX
From
Julien Rouhaud
Date:
On Fri, Apr 03, 2020 at 09:27:38PM +0900, Fujii Masao wrote: > > > 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 <masao.fujii@oss.nttdata.com> 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. Thanks Fuji-san! Just to be extra safe I locally added an extra RAISE notice '%', ln; before the continue and I confirm that this is only filtering the intended lines. Minor thinko: + -- 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. those lines begin with a leading tabulation while the rest of the sql file only contains space indentation. Other than that it all looks good to me.
Fujii Masao <masao.fujii@oss.nttdata.com> writes:
> On 2020/04/03 12:30, Tom Lane wrote:
>> 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?
I think this is a bad idea. It's overcomplicated, and more to the
point: now that we've seen the problem we should realize that we're
eventually going to have failures for *any* Buffers line in text-mode
output. We're already filtering them so hard as to be nearly useless
(see a couple lines further down). I think we should just drop them
in text mode and be content with checking for them in non-text modes.
Robert's muttered about possibly introducing some EXPLAIN option
that would make the output a bit less variable. Perhaps we should
do that. I'm not quite sure I like the idea on theoretical grounds:
testing a different behavior from what you do in production seems
like the wrong thing. But it'd allow undoing decisions like this one.
It's too late to consider such a thing for v13, though --- four days
before feature freeze is no time to be designing new features.
So for now, we have to make the output stable with the tools we have,
and text-mode Buffers output is unstable by design.
regards, tom lane
On 2020/04/03 22:35, Tom Lane wrote:
> Fujii Masao <masao.fujii@oss.nttdata.com> writes:
>> On 2020/04/03 12:30, Tom Lane wrote:
>>> 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?
>
> I think this is a bad idea. It's overcomplicated, and more to the
> point: now that we've seen the problem we should realize that we're
> eventually going to have failures for *any* Buffers line in text-mode
> output. We're already filtering them so hard as to be nearly useless
> (see a couple lines further down). I think we should just drop them
> in text mode and be content with checking for them in non-text modes.
Yeah, I'm fine with the idea. The regression test for EXPLAIN has
the following four similar tests. The first one fails in regression test
because of buffers output for the planning. Your idea seems to be
equal to removal of this first test. Because there are already
the same tests with other format. Is my understanding right?
select explain_filter('explain (analyze, buffers, format text) select * from int8_tbl i8');
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');
Or another idea is to specify "summary off" in the above first
EXPLAIN command, to suppress the summary output including
the buffers output for the planning. This seems simple and enough.
Thought?
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
Fujii Masao <masao.fujii@oss.nttdata.com> writes:
> On 2020/04/03 22:35, Tom Lane wrote:
>> I think this is a bad idea. It's overcomplicated, and more to the
>> point: now that we've seen the problem we should realize that we're
>> eventually going to have failures for *any* Buffers line in text-mode
>> output. We're already filtering them so hard as to be nearly useless
>> (see a couple lines further down). I think we should just drop them
>> in text mode and be content with checking for them in non-text modes.
> Yeah, I'm fine with the idea. The regression test for EXPLAIN has
> the following four similar tests. The first one fails in regression test
> because of buffers output for the planning. Your idea seems to be
> equal to removal of this first test. Because there are already
> the same tests with other format. Is my understanding right?
Well, there are at least three ways you could interpret my suggestion:
* don't do the test with format = text at all
* do it, but remove the buffers option
* keep test the same, make explain_filter() drop Buffers lines
But I had the last one in mind. Even if we can't *see* the output,
there is some value in making the backend run through the code ---
it'd at least catch core-dumping bugs there.
> Or another idea is to specify "summary off" in the above first
> EXPLAIN command, to suppress the summary output including
> the buffers output for the planning. This seems simple and enough.
That's still assuming that only the summary Buffers line is problematic,
which I think is wrong. Keep in mind that the explain.sql test is
barely two months old; it has never seen the field, and there is no
good reason to trust that it's rock solid stable. Now that we've
seen this failure, I'm quite afraid that the existing test case
Seq Scan on int8_tbl i8 (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
Buffers: shared [read]
Planning Time: N.N ms
can be made to fall over, eg by running with high enough shared_buffers.
regards, tom lane
On 2020/04/03 23:55, Tom Lane wrote:
> Fujii Masao <masao.fujii@oss.nttdata.com> writes:
>> On 2020/04/03 22:35, Tom Lane wrote:
>>> I think this is a bad idea. It's overcomplicated, and more to the
>>> point: now that we've seen the problem we should realize that we're
>>> eventually going to have failures for *any* Buffers line in text-mode
>>> output. We're already filtering them so hard as to be nearly useless
>>> (see a couple lines further down). I think we should just drop them
>>> in text mode and be content with checking for them in non-text modes.
>
>> Yeah, I'm fine with the idea. The regression test for EXPLAIN has
>> the following four similar tests. The first one fails in regression test
>> because of buffers output for the planning. Your idea seems to be
>> equal to removal of this first test. Because there are already
>> the same tests with other format. Is my understanding right?
>
> Well, there are at least three ways you could interpret my suggestion:
>
> * don't do the test with format = text at all
>
> * do it, but remove the buffers option
>
> * keep test the same, make explain_filter() drop Buffers lines
>
> But I had the last one in mind. Even if we can't *see* the output,
> there is some value in making the backend run through the code ---
> it'd at least catch core-dumping bugs there.
Yes, this makes sense. Thanks for clarifying that!
>> Or another idea is to specify "summary off" in the above first
>> EXPLAIN command, to suppress the summary output including
>> the buffers output for the planning. This seems simple and enough.
>
> That's still assuming that only the summary Buffers line is problematic,
> which I think is wrong. Keep in mind that the explain.sql test is
> barely two months old; it has never seen the field, and there is no
> good reason to trust that it's rock solid stable. Now that we've
> seen this failure, I'm quite afraid that the existing test case
>
> Seq Scan on int8_tbl i8 (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
> Buffers: shared [read]
> Planning Time: N.N ms
>
> can be made to fall over, eg by running with high enough shared_buffers.
Yeah, so I'm feeling that it's better to firstly make the explain test
more stable, separately from the patch for the planning buffers output.
Attached is the patch that changes explain.c as follows (i.e., removes
Buffers lines at all) to make it more stable.
ln := regexp_replace(ln, '\m\d+\M', 'N', 'g');
-- In sort output, the above won't match units-suffixed numbers
ln := regexp_replace(ln, '\m\d+kB', 'NkB', 'g');
- -- Text-mode buffers output varies depending on the system state
- ln := regexp_replace(ln, '^( +Buffers: shared)( hit=N)?( read=N)?', '\1 [read]');
+ -- Ignore text-mode buffers output because it varies depending
+ -- on the system state
+ CONTINUE WHEN (ln ~ ' +Buffers: .*');
return next ln;
end loop;
end;
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
Attachment
Fujii Masao <masao.fujii@oss.nttdata.com> writes:
> Attached is the patch that changes explain.c as follows (i.e., removes
> Buffers lines at all) to make it more stable.
> ln := regexp_replace(ln, '\m\d+\M', 'N', 'g');
> -- In sort output, the above won't match units-suffixed numbers
> ln := regexp_replace(ln, '\m\d+kB', 'NkB', 'g');
> - -- Text-mode buffers output varies depending on the system state
> - ln := regexp_replace(ln, '^( +Buffers: shared)( hit=N)?( read=N)?', '\1 [read]');
> + -- Ignore text-mode buffers output because it varies depending
> + -- on the system state
> + CONTINUE WHEN (ln ~ ' +Buffers: .*');
> return next ln;
> end loop;
> end;
Works for me.
regards, tom lane
On 2020/04/04 0:34, Tom Lane wrote: > Fujii Masao <masao.fujii@oss.nttdata.com> writes: >> Attached is the patch that changes explain.c as follows (i.e., removes >> Buffers lines at all) to make it more stable. > >> ln := regexp_replace(ln, '\m\d+\M', 'N', 'g'); >> -- In sort output, the above won't match units-suffixed numbers >> ln := regexp_replace(ln, '\m\d+kB', 'NkB', 'g'); >> - -- Text-mode buffers output varies depending on the system state >> - ln := regexp_replace(ln, '^( +Buffers: shared)( hit=N)?( read=N)?', '\1 [read]'); >> + -- Ignore text-mode buffers output because it varies depending >> + -- on the system state >> + CONTINUE WHEN (ln ~ ' +Buffers: .*'); >> return next ln; >> end loop; >> end; > > Works for me. Many thanks! Pushed. Regards, -- Fujii Masao Advanced Computing Technology Center Research and Development Headquarters NTT DATA CORPORATION
Fujii Masao <masao.fujii@oss.nttdata.com> writes:
> Many thanks! Pushed.
Looks like you didn't un-revert the main patch?
regards, tom lane
On 2020/04/04 2:46, Tom Lane wrote: > Fujii Masao <masao.fujii@oss.nttdata.com> writes: >> Many thanks! Pushed. > > Looks like you didn't un-revert the main patch? Right now, pushed! I was waiting for my test to finish without errors before commit. Anyway thanks! Regards, -- Fujii Masao Advanced Computing Technology Center Research and Development Headquarters NTT DATA CORPORATION
Re: pgsql: Include information on buffer usage during planning phase,in EX
From
Julien Rouhaud
Date:
On Fri, Apr 3, 2020 at 8:16 PM Fujii Masao <masao.fujii@oss.nttdata.com> wrote: > > On 2020/04/04 2:46, Tom Lane wrote: > > Fujii Masao <masao.fujii@oss.nttdata.com> writes: > >> Many thanks! Pushed. > > > > Looks like you didn't un-revert the main patch? > > Right now, pushed! I was waiting for my test to finish > without errors before commit. Anyway thanks! Thanks a lot!