From: hubert depesz lubaczewski <depesz@depesz.com>
To: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
Subject: I/O timigns don't include time for temp buffers
Date: Fri, 9 Jul 2021 10:43:55 +0200
Message-ID: <20210709084355.GA6251@depesz.com> (raw)
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.
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
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-bugs@postgresql.org
Cc: depesz@depesz.com, pgsql-bugs@lists.postgresql.org
Subject: Re: I/O timigns don't include time for temp buffers
In-Reply-To: <20210709084355.GA6251@depesz.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox