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

On Wed, Jan 19, 2022 at 5:52 PM Julien Rouhaud <rjuju123(at)gmail(dot)com> wrote:
>
> Hi,
>
> On Tue, Nov 16, 2021 at 04:37:44PM +0900, Masahiko Sawada wrote:
> >
> > I've attached an updated patch. Please review it.
>
> 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.

I've attached updated patches. I've included an improvement of
pg_stat_statement support to support temp I/O timing.

Regards,

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