Re: Showing I/O timings spent reading/writing temp buffers in EXPLAIN

On Thu, Aug 19, 2021 at 10:52 PM Ranier Vilela <ranier(dot)vf(at)gmail(dot)com> wrote:
>
> Em qui., 19 de ago. de 2021 às 09:21, Masahiko Sawada <sawada(dot)mshk(at)gmail(dot)com> escreveu:
>>
>> Hi all ,
>>
>> It's reported on pgsql-bugs[1] that I/O timings in EXPLAIN don't show
>> the one for temp files. I think it's not a bug but could be an item
>> for PG15. As mentioned on that thread, this would be useful for users
>> in a case where temp buffers I/O used most of the time. So I've
>> written the patch for that. Please note that the patch includes only
>> to show temp buffer I/O timing to EXPLAIN but not other possibly
>> related changes such as pg_stat_statement improvements yet.
>>
>> Before (w/o patch):
>> postgres(1:14101)=# explain (analyze, buffers) select count(*) from
>> generate_series(1,100000);
>> QUERY PLAN
>> -----------------------------------------------------------------------------------------------------------------------------------
>> Aggregate (cost=1250.00..1250.01 rows=1 width=8) (actual
>> time=59.025..59.026 rows=1 loops=1)
>> Buffers: temp read=171 written=171
>> -> Function Scan on generate_series (cost=0.00..1000.00
>> rows=100000 width=0) (actual time=21.695..45.524 rows=100000 loops=1)
>> Buffers: temp read=171 written=171
>> Planning Time: 0.041 ms
>> Execution Time: 70.867 ms
>> (6 rows)
>>
>> After (w/ patch):
>> postgres(1:28754)=# explain (analyze, buffers) select count(*) from
>> generate_series(1,100000);
>> QUERY PLAN
>> -----------------------------------------------------------------------------------------------------------------------------------
>> Aggregate (cost=1250.00..1250.01 rows=1 width=8) (actual
>> time=56.189..56.190 rows=1 loops=1)
>> Buffers: temp read=171 written=171
>> I/O Timings: temp read=0.487 write=2.073
>> -> Function Scan on generate_series (cost=0.00..1000.00
>> rows=100000 width=0) (actual time=21.072..42.886 rows=100000 loops=1)
>> Buffers: temp read=171 written=171
>> I/O Timings: temp read=0.487 write=2.073
>> Planning Time: 0.041 ms
>> Execution Time: 59.928 ms
>> (8 rows)
>>
>> Feedback is very welcome.
>

Thank you for the comments!

> The presentation seems a little confusing, wouldn't it be better?
>
> I/O Timings: shared/local read=xxxx write=xxx temp read=0.487 write=2.073

Yeah, it looks better to add "shared/local".

>
> I think can remove this lines:
> + if (has_temp_timing)
> + appendStringInfoChar(es->str, ',');

But I think that it's consistent with buffers statistics in EXPLAIN
command. For example, "Buffers" in the output of EXPLAIN command could
be like:

Buffers: shared hit=1398, temp read=526 written=526

Regards,

--
Masahiko Sawada
EDB: https://www.enterprisedb.com/