Re: I/O timigns don't include time for temp buffers

On Fri, Jul 9, 2021 at 5:44 PM hubert depesz lubaczewski
<depesz(at)depesz(dot)com> wrote:
>
> Hi,
> I tested it on newest 15devel from git, but I believe it goes back.
>
> It looks that I/O timings in explain show that that was necessary to
> read/write *shared* and *local* buffers, but temp are excluded for some
> reason.
>
> For example:
> $ explain (analyze, buffers) select count(*) from plans.part_0;
> QUERY PLAN
> ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
> Aggregate (cost=464.74..464.75 rows=1 width=8) (actual time=14.580..14.582 rows=1 loops=1)
> Buffers: shared hit=13 read=16 dirtied=7
> I/O Timings: read=6.325
> -> Index Only Scan using part_0_added_by_idx on part_0 (cost=0.29..413.82 rows=20369 width=0) (actual time=0.031..11.428 rows=20359 loops=1)
> Heap Fetches: 50
> Buffers: shared hit=13 read=16 dirtied=7
> I/O Timings: read=6.325
> Planning:
> Buffers: shared hit=166
> Planning Time: 0.414 ms
> Execution Time: 14.618 ms
> (11 rows)
>
> Shows that we have normal I/O Timings info, 6.3ms for reading 16 pages.
>
> But when I don't touch any shared/local pages:
> $ explain (analyze, buffers) select count(*) from generate_series(1,10000000);
> QUERY PLAN
> ────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
> Aggregate (cost=125000.00..125000.01 rows=1 width=8) (actual time=1536.899..1536.900 rows=1 loops=1)
> Buffers: temp read=17090 written=17090
> -> Function Scan on generate_series (cost=0.00..100000.00 rows=10000000 width=0) (actual time=611.066..1210.260 rows=10000000 loops=1)
> Buffers: temp read=17090 written=17090
> Planning Time: 0.071 ms
> JIT:
> Functions: 4
> Options: Inlining false, Optimization false, Expressions true, Deforming true
> Timing: Generation 0.202 ms, Inlining 0.000 ms, Optimization 0.089 ms, Emission 1.528 ms, Total 1.819 ms
> Execution Time: 1565.635 ms
> (10 rows)
>
> The I/O timings info is fully missing.
>
> With more info you can see it in https://explain.depesz.com/s/xWRP#source
>
> Line 11 (Hash) has info:
> Buffers: shared hit=229 read=19,627 written=3, temp written=1,100
> I/O Timings: read=31.173 write=0.049
>
> and it's only subnode (Nested loop) shows:
>
> Buffers: shared hit=229 read=19,627 written=3
> I/O Timings: read=31.173 write=0.049
>
> This shows that the Hash wrote 1100 temp buffers, but I/O timings didn't increase at all.

Yes, we don't collect the time spent reading and writing temp files.

>
> So far it looks that only shared/local buffers are taken into account
> for I/O timings, but, as far as I can read it,
> https://www.postgresql.org/docs/current/sql-explain.html doesn't mention
> this.

The doc says:

---
Specifically, include the number of shared blocks hit, read, dirtied,
and written, the number of local blocks hit, read, dirtied, and
written, the number of temp blocks read and written, and the time
spent reading and writing data file blocks (in milliseconds) if
track_io_timing is enabled.
(snip)
Shared blocks contain data from regular tables and indexes; local
blocks contain data from temporary tables and indexes; while temp
blocks contain short-term working data used in sorts, hashes,
Materialize plan nodes, and similar cases.
---

I thought the doc is clear since 'data file blocks' in the first
sentence probably mean the table/index data on shared/local buffers
(we don't necessarily block read/write for temp files). But we use the
terms 'shared blocks', 'local blocks', and 'temp blocks' later. Does
this make the first sentence sound like that the time includes not
only shared/local buffer but also temp files?

Regards,

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