Re: Showing I/O timings spent reading/writing temp buffers in EXPLAIN - Mailing list pgsql-hackers

On Mon, Apr 4, 2022 at 1:30 PM Julien Rouhaud <rjuju123@gmail.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@gmail.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/