Thread: Re: BUG #16109: Postgres planning time is high across version - 10.6vs 10.10
Re: BUG #16109: Postgres planning time is high across version - 10.6vs 10.10
From
Julien Rouhaud
Date:
(moved to -hackers)
On Tue, Nov 12, 2019 at 9:55 PM Andres Freund <andres@anarazel.de> wrote:
>
> This last point is more oriented towards other PG developers: I wonder
> if we ought to display buffer statistics for plan time, for EXPLAIN
> (BUFFERS). That'd surely make it easier to discern cases where we
> e.g. access the index and scan a lot of the index from cases where we
> hit some CPU time issue. We should easily be able to get that data, I
> think, we already maintain it, we'd just need to compute the diff
> between pgBufferUsage before / after planning.
That would be quite interesting to have. I attach as a reference a
quick POC patch to implement it:
# explain (analyze, buffers) select * from pg_stat_activity;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------
Hash Left Join (cost=2.25..3.80 rows=100 width=440) (actual
time=0.259..0.276 rows=6 loops=1)
Hash Cond: (s.usesysid = u.oid)
Buffers: shared hit=5
-> Hash Left Join (cost=1.05..2.32 rows=100 width=376) (actual
time=0.226..0.236 rows=6 loops=1)
Hash Cond: (s.datid = d.oid)
Buffers: shared hit=4
-> Function Scan on pg_stat_get_activity s (cost=0.00..1.00
rows=100 width=312) (actual time=0.148..0.151 rows=6 loop
-> Hash (cost=1.02..1.02 rows=2 width=68) (actual
time=0.034..0.034 rows=5 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 9kB
Buffers: shared hit=1
-> Seq Scan on pg_database d (cost=0.00..1.02 rows=2
width=68) (actual time=0.016..0.018 rows=5 loops=1)
Buffers: shared hit=1
-> Hash (cost=1.09..1.09 rows=9 width=68) (actual
time=0.015..0.015 rows=9 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 9kB
Buffers: shared hit=1
-> Seq Scan on pg_authid u (cost=0.00..1.09 rows=9
width=68) (actual time=0.004..0.008 rows=9 loops=1)
Buffers: shared hit=1
Planning Time: 1.902 ms
Buffers: shared hit=37 read=29
I/O Timings: read=0.506
Execution Time: 0.547 ms
(21 rows)
Note that there's a related discussion in the "Planning counters in
pg_stat_statements" thread, on whether to also compute buffers from
planning or not.
Attachment
Re: BUG #16109: Postgres planning time is high across version - 10.6vs 10.10
From
Pavel Stehule
Date:
st 13. 11. 2019 v 11:39 odesílatel Julien Rouhaud <rjuju123@gmail.com> napsal:
(moved to -hackers)
On Tue, Nov 12, 2019 at 9:55 PM Andres Freund <andres@anarazel.de> wrote:
>
> This last point is more oriented towards other PG developers: I wonder
> if we ought to display buffer statistics for plan time, for EXPLAIN
> (BUFFERS). That'd surely make it easier to discern cases where we
> e.g. access the index and scan a lot of the index from cases where we
> hit some CPU time issue. We should easily be able to get that data, I
> think, we already maintain it, we'd just need to compute the diff
> between pgBufferUsage before / after planning.
That would be quite interesting to have. I attach as a reference a
quick POC patch to implement it:
# explain (analyze, buffers) select * from pg_stat_activity;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------
Hash Left Join (cost=2.25..3.80 rows=100 width=440) (actual
time=0.259..0.276 rows=6 loops=1)
Hash Cond: (s.usesysid = u.oid)
Buffers: shared hit=5
-> Hash Left Join (cost=1.05..2.32 rows=100 width=376) (actual
time=0.226..0.236 rows=6 loops=1)
Hash Cond: (s.datid = d.oid)
Buffers: shared hit=4
-> Function Scan on pg_stat_get_activity s (cost=0.00..1.00
rows=100 width=312) (actual time=0.148..0.151 rows=6 loop
-> Hash (cost=1.02..1.02 rows=2 width=68) (actual
time=0.034..0.034 rows=5 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 9kB
Buffers: shared hit=1
-> Seq Scan on pg_database d (cost=0.00..1.02 rows=2
width=68) (actual time=0.016..0.018 rows=5 loops=1)
Buffers: shared hit=1
-> Hash (cost=1.09..1.09 rows=9 width=68) (actual
time=0.015..0.015 rows=9 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 9kB
Buffers: shared hit=1
-> Seq Scan on pg_authid u (cost=0.00..1.09 rows=9
width=68) (actual time=0.004..0.008 rows=9 loops=1)
Buffers: shared hit=1
Planning Time: 1.902 ms
Buffers: shared hit=37 read=29
I/O Timings: read=0.506
Execution Time: 0.547 ms
(21 rows)
Note that there's a related discussion in the "Planning counters in
pg_stat_statements" thread, on whether to also compute buffers from
planning or not.
+1
Pavel
Re: BUG #16109: Postgres planning time is high across version(Expose buffer usage during planning in EXPLAIN)
From
Justin Pryzby
Date:
On Wed, Nov 13, 2019 at 11:39:04AM +0100, Julien Rouhaud wrote: > (moved to -hackers) > > On Tue, Nov 12, 2019 at 9:55 PM Andres Freund <andres@anarazel.de> wrote: > > > > This last point is more oriented towards other PG developers: I wonder > > if we ought to display buffer statistics for plan time, for EXPLAIN > > (BUFFERS). That'd surely make it easier to discern cases where we > > e.g. access the index and scan a lot of the index from cases where we > > hit some CPU time issue. We should easily be able to get that data, I > > think, we already maintain it, we'd just need to compute the diff > > between pgBufferUsage before / after planning. > > That would be quite interesting to have. I attach as a reference a > quick POC patch to implement it: +1 + result.shared_blks_hit = stop->shared_blks_hit - start->shared_blks_hit; + result.shared_blks_read = stop->shared_blks_read - start->shared_blks_read; + result.shared_blks_dirtied = stop->shared_blks_dirtied - + start->shared_blks_dirtied; [...] I think it would be more readable and maintainable using a macro: #define CALC_BUFF_DIFF(x) result.##x = stop->##x - start->##x CALC_BUFF_DIFF(shared_blks_hit); CALC_BUFF_DIFF(shared_blks_read); CALC_BUFF_DIFF(shared_blks_dirtied); ... #undefine CALC_BUFF_DIFF
Re: BUG #16109: Postgres planning time is high across version (Exposebuffer usage during planning in EXPLAIN)
From
Julien Rouhaud
Date:
On Fri, Jan 24, 2020 at 6:55 AM Justin Pryzby <pryzby@telsasoft.com> wrote: > > On Wed, Nov 13, 2019 at 11:39:04AM +0100, Julien Rouhaud wrote: > > (moved to -hackers) > > > > On Tue, Nov 12, 2019 at 9:55 PM Andres Freund <andres@anarazel.de> wrote: > > > > > > This last point is more oriented towards other PG developers: I wonder > > > if we ought to display buffer statistics for plan time, for EXPLAIN > > > (BUFFERS). That'd surely make it easier to discern cases where we > > > e.g. access the index and scan a lot of the index from cases where we > > > hit some CPU time issue. We should easily be able to get that data, I > > > think, we already maintain it, we'd just need to compute the diff > > > between pgBufferUsage before / after planning. > > > > That would be quite interesting to have. I attach as a reference a > > quick POC patch to implement it: > > +1 > > + result.shared_blks_hit = stop->shared_blks_hit - start->shared_blks_hit; > + result.shared_blks_read = stop->shared_blks_read - start->shared_blks_read; > + result.shared_blks_dirtied = stop->shared_blks_dirtied - > + start->shared_blks_dirtied; > [...] > > I think it would be more readable and maintainable using a macro: > > #define CALC_BUFF_DIFF(x) result.##x = stop->##x - start->##x > CALC_BUFF_DIFF(shared_blks_hit); > CALC_BUFF_DIFF(shared_blks_read); > CALC_BUFF_DIFF(shared_blks_dirtied); > ... > #undefine CALC_BUFF_DIFF Good idea. Note that you can't use preprocessor concatenation to generate something else than a token or a number, so the ## can just be removed here.
Attachment
Re: BUG #16109: Postgres planning time is high across version (Exposebuffer usage during planning in EXPLAIN)
From
Julien Rouhaud
Date:
On Fri, Jan 24, 2020 at 10:06 PM Julien Rouhaud <rjuju123@gmail.com> wrote: > > On Fri, Jan 24, 2020 at 6:55 AM Justin Pryzby <pryzby@telsasoft.com> wrote: > > > > On Wed, Nov 13, 2019 at 11:39:04AM +0100, Julien Rouhaud wrote: > > > (moved to -hackers) > > > > > > On Tue, Nov 12, 2019 at 9:55 PM Andres Freund <andres@anarazel.de> wrote: > > > > > > > > This last point is more oriented towards other PG developers: I wonder > > > > if we ought to display buffer statistics for plan time, for EXPLAIN > > > > (BUFFERS). That'd surely make it easier to discern cases where we > > > > e.g. access the index and scan a lot of the index from cases where we > > > > hit some CPU time issue. We should easily be able to get that data, I > > > > think, we already maintain it, we'd just need to compute the diff > > > > between pgBufferUsage before / after planning. > > > > > > That would be quite interesting to have. I attach as a reference a > > > quick POC patch to implement it: > > > > +1 > > > > + result.shared_blks_hit = stop->shared_blks_hit - start->shared_blks_hit; > > + result.shared_blks_read = stop->shared_blks_read - start->shared_blks_read; > > + result.shared_blks_dirtied = stop->shared_blks_dirtied - > > + start->shared_blks_dirtied; > > [...] > > > > I think it would be more readable and maintainable using a macro: > > > > #define CALC_BUFF_DIFF(x) result.##x = stop->##x - start->##x > > CALC_BUFF_DIFF(shared_blks_hit); > > CALC_BUFF_DIFF(shared_blks_read); > > CALC_BUFF_DIFF(shared_blks_dirtied); > > ... > > #undefine CALC_BUFF_DIFF > > Good idea. Note that you can't use preprocessor concatenation to > generate something else than a token or a number, so the ## can just > be removed here. Rebase due to conflict with 3ec20c7091e97.
Attachment
Re: BUG #16109: Postgres planning time is high across version(Expose buffer usage during planning in EXPLAIN)
From
Justin Pryzby
Date:
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?) -- Justin
Re: BUG #16109: Postgres planning time is high across version (Exposebuffer usage during planning in EXPLAIN)
From
Fujii Masao
Date:
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
Attachment
Re: BUG #16109: Postgres planning time is high across version (Exposebuffer usage during planning in EXPLAIN)
From
Julien Rouhaud
Date:
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:
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index b1f3fe13c6..9dbff97a32 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -375,7 +375,9 @@ ExplainOneQuery(Query *query, int cursorOptions,
BufferUsage bufusage_start,
bufusage;
- bufusage_start = pgBufferUsage;
+ if (ex->buffers)
+ bufusage_start = pgBufferUsage;
+
INSTR_TIME_SET_CURRENT(planstart);
/* plan the query */
@@ -384,13 +386,16 @@ 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);
+ if (es->buffers)
+ {
+ /* 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, &bufusage);
+ &planduration, (es->buffers ? &bufusage : NULL));
}
which seemed like a win, but I'm not opposed to do that if you prefer.
>
> + "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.
Indeed, that's way better!
Re: BUG #16109: Postgres planning time is high across version (Exposebuffer usage during planning in EXPLAIN)
From
Fujii Masao
Date:
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
Attachment
Re: BUG #16109: Postgres planning time is high across version(Expose buffer usage during planning in EXPLAIN)
From
Julien Rouhaud
Date:
On Thu, Apr 02, 2020 at 01:05:56PM +0900, Fujii Masao wrote:
>
>
> 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!
Thanks a lot, it all looks good to me!
Re: BUG #16109: Postgres planning time is high across version (Exposebuffer usage during planning in EXPLAIN)
From
Fujii Masao
Date:
On 2020/04/02 15:01, Julien Rouhaud wrote:
> On Thu, Apr 02, 2020 at 01:05:56PM +0900, Fujii Masao wrote:
>>
>>
>> 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!
>
>
> Thanks a lot, it all looks good to me!
Thanks! Barring any objection, I will commit the latest version of the patch.
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
Re: BUG #16109: Postgres planning time is high across version (Exposebuffer usage during planning in EXPLAIN)
From
Fujii Masao
Date:
On 2020/04/02 15:52, Fujii Masao wrote:
>
>
> On 2020/04/02 15:01, Julien Rouhaud wrote:
>> On Thu, Apr 02, 2020 at 01:05:56PM +0900, Fujii Masao wrote:
>>>
>>>
>>> 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!
>>
>>
>> Thanks a lot, it all looks good to me!
>
> Thanks! Barring any objection, I will commit the latest version of the patch.
Pushed! Thanks a lot!!
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION