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

On Thu, Apr 07, 2022 at 04:24:54PM +0900, Michael Paquier wrote:
> On Thu, Apr 07, 2022 at 03:14:01PM +0800, Julien Rouhaud wrote:
> > Sure, but gettimeofday() has been implemented in vDSO for quite some time on
> > most platforms, so it shouldn't hurt that much on mainstream platforms
> > especially compared to the cost of whatever operation is actually using that
> > temporary file.
> >
> > I don't think that having an extra GUC for temp IO is sensible, if that's why
> > you're suggesting? Or are you just asking to do some benchmarking on some
> > platform where getting the time is known to be slow (Windows?).
>
> I am asking about the latter, but the former could be one solution if
> the latter proves to be a problem, and this has not been discussed on
> the thread yet. So, with some kind of worst-case scenario, how much
> worse the performance gets once you add those extra calls when
> compared to HEAD? I think that we'd better be careful with any
> additions of INSTR_TIME_SET_CURRENT().

I just did a quick test on my linux box, using this data:
CREATE TABLE tt AS select generate_series(1, 10000) id;
VACUUM ANALYZE tt;

and this scenario:
SET work_mem TO '64kB';
SELECT count(*) FROM (SELECT id FROM tt ORDER BY id) s;

which yields this plan:

QUERY PLAN
------------------------------------------------------------------------------------------------------------------
Aggregate (cost=1349.39..1349.40 rows=1 width=8) (actual time=5.417..5.417 rows=1 loops=1)
-> Sort (cost=1199.39..1224.39 rows=10000 width=4) (actual time=2.910..4.422 rows=10000 loops=1)
Sort Key: tt.id
Sort Method: external merge Disk: 144kB
-> Seq Scan on tt (cost=0.00..145.00 rows=10000 width=4) (actual time=0.008..1.239 rows=10000 loops=1)
Planning Time: 0.405 ms
Execution Time: 5.524 ms

So maybe not the worst that could be tested, but probably bad enough for this
patch.

I ran that with pgbench, 4 clients (I have 4 cores) for 30 seconds, 3 times.

Comparing master and this patch with track_io_timing activated, I see a 0.95%
overhead, with a 2.6% noise level.