Re: BUG #16109: Postgres planning time is high across version (Expose buffer usage during planning in EXPLAIN)

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(dot)fujii(at)oss(dot)nttdata(dot)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