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

On Mon, Apr 4, 2022 at 1:30 PM Julien Rouhaud <rjuju123(at)gmail(dot)com> wrote:
>
> Hi,
>
> On Tue, Mar 01, 2022 at 11:35:32AM +0900, Masahiko Sawada wrote:
> > On Wed, Jan 19, 2022 at 5:52 PM Julien Rouhaud <rjuju123(at)gmail(dot)com> wrote:
> > >
> > > It seems that the regression tests aren't entirely stable, per cfbot:
> > > https://cirrus-ci.com/github/postgresql-cfbot/postgresql/commitfest/36/3298.
> > >
> > > The failures look like:
> > >
> > > diff -U3 /tmp/cirrus-ci-build/src/test/recovery/../regress/expected/explain.out /tmp/cirrus-ci-build/src/test/recovery/tmp_check/results/explain.out
> > > --- /tmp/cirrus-ci-build/src/test/recovery/../regress/expected/explain.out 2022-01-19 03:50:37.087931908 +0000
> > > +++ /tmp/cirrus-ci-build/src/test/recovery/tmp_check/results/explain.out 2022-01-19 03:57:41.013616137 +0000
> > > @@ -512,9 +512,10 @@
> > > I/O Timings: temp read=N.N write=N.N
> > > -> Function Scan on generate_series (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
> > > I/O Timings: temp read=N.N write=N.N
> > > + I/O Timings: shared/local read=N.N
> > > Planning Time: N.N ms
> > > Execution Time: N.N ms
> > > -(6 rows)
> > > +(7 rows)
> > >
> > > select explain_filter('explain (analyze, buffers, format json) select count(*) from generate_series(1, 100000)');
> > > explain_filter
> > >
> > >
> > > I don't see any obvious error in the code, so I'm wondering if it's simply
> > > the result of populating the cache with generate_series() info.
> >
> > Thank you for reporting.
> >
> > You're right, the regression test with track_io_timing = on is not
> > entirely stable because we may read catalog data during planning time,
> > resulting in an additional line in the EXPLAIN output. I've removed
> > the regression tests.
>
> Hmm, but AFAICS the json format would be stable as the counters are always
> shown even if zero. So just doing the json format first and then the text
> format should also work. Although if you're really unlucky there could be a
> cache invalidation in between so we could just ignore the text format. But I
> think we should at least keep a regression test with the json format, with a
> comment explain why only this one is tested.

Fair point. By commit 7e12256b478 we disabled track_io_timing, but
probably we can temporarily enable it and run one query with "buffers"
and "format json" options.

>
> > I've attached updated patches. I've included an improvement of
> > pg_stat_statement support to support temp I/O timing.
>
> Great!
>
> Some other considerations:
>
> - should we update pg_stat_statements documentation (and comments) for
> blk_(read|write)_time to mention that it's for *data file* blocks rather than
> simply blocks? It seems obvious now that we'd have
> temp_blk_(read|write)_time, but still. This part should probably be
> backpatched.

Agreed.

>
> - not really your patch fault I guess, but I see that extendBufFile() isn't
> handled. There shouldn't be much activity there so maybe it's ok.
> This is likely because smgr_extend is also not handled, but this one seems
> much more likely to take quite some time, and therefore should bump the
> timing counters.

You mean we should include the time for opening files as write time?
IIUC smgrextend() writes data while extending file whereas
extendBufFile() doesn't do that but just opens a new file.

Regards,

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