Date: Mon, 4 Apr 2022 12:30:20 +0800
From: Julien Rouhaud <rjuju123@gmail.com>
To: Masahiko Sawada <sawada.mshk@gmail.com>
Cc: gkokolatos@pm.me, Ranier Vilela <ranier.vf@gmail.com>,
	PostgreSQL-development <pgsql-hackers@postgresql.org>,
	depesz@depesz.com
Subject: Re: Showing I/O timings spent reading/writing temp buffers in EXPLAIN
Message-ID: <Ykp0XP37Gj/sT5hB@jrouhaud>
References: 
 <CAD21AoAJgotTeP83p6HiAGDhs_9Fw9pZ2J=_tYTsiO5Ob-V5GQ@mail.gmail.com>
 <CAEudQApKndnEgtkL5o9DxfP7sNKXSw0uuWcvD4HYh6GWmkeJ1g@mail.gmail.com>
 <CAD21AoC7uaV2qiVoWPSjxyY5YAqyHa5w5XAuFCqrLtXAhwCiSQ@mail.gmail.com>
 <CAD21AoAdwWBxBn8YQucsRGEB3ToYH4C6wjGU+qajKLmiJDCJkw@mail.gmail.com>
 <CAEudQAogZVHURE7fSfbOmOZMPK7tR+FMR4b=5WKVU7BersxaOQ@mail.gmail.com>
 <2sAuEW1zGE4cTWCRPgzvAshfUAM44kW02tc3i31iLLCujLE-tczA8xOGFhs6c2EiEVM5uSQy_cJyvgAA1EKyxRtqnWM_mrirKwsTJ6Kxaaw=@pm.me>
 <CAD21AoDXgYRVrzWpAV_CoX0nbg68++Bx4RbkzY40hKm5h1mEtg@mail.gmail.com>
 <20220119085236.iuuq4rtzm6qxvzls@jrouhaud>
 <CAD21AoAca6EdwRhhqbLuAsOxMsKKZB9qMX_m9LenLS2NE6fM1A@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: 
 <CAD21AoAca6EdwRhhqbLuAsOxMsKKZB9qMX_m9LenLS2NE6fM1A@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/Ykp0XP37Gj/sT5hB%40jrouhaud>
Precedence: bulk

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.

> 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.

- 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.