Thread: I/O timigns don't include time for temp buffers
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.428rows=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=10000000loops=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.
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.
Best regards,
depesz
On Fri, Jul 9, 2021 at 5:44 PM hubert depesz lubaczewski <depesz@depesz.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.428rows=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=10000000loops=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/
On Tue, Aug 10, 2021 at 03:15:27PM +0900, Masahiko Sawada wrote: > > 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. And this is the source of my concern. Not that we have this documented in one way or another, but why exactly aren't we taking temp buffers into timing? There are cases where it is the temp buffers IO that is using most of the time. Best regards, depesz
On Wed, Aug 11, 2021 at 5:35 PM hubert depesz lubaczewski <depesz@depesz.com> wrote: > > On Tue, Aug 10, 2021 at 03:15:27PM +0900, Masahiko Sawada wrote: > > > 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. > > And this is the source of my concern. > > Not that we have this documented in one way or another, but why exactly > aren't we taking temp buffers into timing? There are cases where it is > the temp buffers IO that is using most of the time. Yes. I agree that there is room for improvement there. It seems to me that it's an improvement, not a bug. So it would be better to discuss it on pgsql-hackers. Regards, -- Masahiko Sawada EDB: https://www.enterprisedb.com/