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

On Mon, Aug 23, 2021 at 10:46 AM Masahiko Sawada <sawada(dot)mshk(at)gmail(dot)com> wrote:
>
> 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've attached the updated patch that incorporates the above comment.

Regards,

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