From: | Adrien Nayrat <adrien(dot)nayrat(at)anayrat(dot)info> |
---|---|
To: | PostgreSQL mailing lists <pgsql-hackers(at)postgresql(dot)org> |
Subject: | Explain buffers wrong counter with parallel plans |
Date: | 2018-03-27 18:37:09 |
Message-ID: | 86137f17-1dfb-42f9-7421-82fd786b04a1@anayrat.info |
Views: | Raw Message | Whole Thread | Download mbox | Resend email |
Thread: | |
Lists: | pgsql-hackers |
Hello,
I notice Explain report wrong counters with parallel plans :
create unlogged table t1 (c1 int);
insert into t1 select generate_series(1,100000000);
vacuum t1;
(stop PG, drop caches,start)
set track_io_timing to on;
explain (analyze,buffers) select count(*) from t1;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=964311.55..964311.56 rows=1 width=8) (actual
time=34478.972..34478.972 rows=1 loops=1)
Buffers: shared read=147952
I/O Timings: read=20407.894
-> Gather (cost=964311.33..964311.54 rows=2 width=8) (actual
time=34478.835..34478.937 rows=3 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared read=147952
I/O Timings: read=20407.894
-> Partial Aggregate (cost=963311.33..963311.34 rows=1 width=8)
(actual time=34283.809..34283.810 rows=1 loops=3)
Buffers: shared read=442478 dirtied=1 written=1
I/O Timings: read=60706.314 write=0.498
-> Parallel Seq Scan on t1 (cost=0.00..859144.67 rows=41666667
width=0) (actual time=27.027..27405.058 rows=33333333 loops=3)
Buffers: shared read=442478 dirtied=1 written=1
I/O Timings: read=60706.314 write=0.498
Planning time: 39.037 ms
Execution time: 34480.280 ms
(stop pg, drop caches,start)
set max_parallel_workers_per_gather to 0;
explain (analyze,buffers) select count(*) from t1;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=1692478.00..1692478.01 rows=1 width=8) (actual
time=34367.678..34367.678 rows=1 loops=1)
Buffers: shared read=442478
I/O Timings: read=7977.775
-> Seq Scan on t1 (cost=0.00..1442478.00 rows=100000000 width=0) (actual
time=8.672..19685.654 rows=100000000 loops=1)
Buffers: shared read=442478
I/O Timings: read=7977.775
Planning time: 38.971 ms
Execution time: 34368.097 ms
(8 rows)
Gather and Finalize Aggregate should report shared read=442478.
I am also surprised for I/O Timings in parallel node:
I/O Timings: read=60706.314 but the query last 34s?
I played with git bisect and I found this commit :
commit 01edb5c7fc3bcf6aea15f2b3be36189b52ad9d1a
Author: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Date: Fri Sep 1 17:38:54 2017 -0400
Improve division of labor between execParallel.c and nodeGather[Merge].c.
Move the responsibility for creating/destroying TupleQueueReaders into
execParallel.c, to avoid duplicative coding in nodeGather.c and
nodeGatherMerge.c. Also, instead of having DestroyTupleQueueReader do
shm_mq_detach, do it in the caller (which is now only ExecParallelFinish).
This means execParallel.c does both the attaching and detaching of the
tuple-queue-reader shm_mqs, which seems less weird than the previous
arrangement.
These changes also eliminate a vestigial memory leak (of the pei->tqueue
array). It's now demonstrable that rescans of Gather or GatherMerge don't
leak memory.
Discussion: https://postgr.es/m/8670.1504192177@sss.pgh.pa.us
Before this commit here is the result :
explain (analyze,buffers) select count(*) from t1;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=964311.55..964311.56 rows=1 width=8) (actual
time=34745.387..34745.387 rows=1 loops=1)
Buffers: shared hit=160 read=442478 dirtied=1 written=1
I/O Timings: read=61219.308 write=0.033
-> Gather (cost=964311.33..964311.54 rows=2 width=8) (actual
time=34745.273..34745.379 rows=3 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=160 read=442478 dirtied=1 written=1
I/O Timings: read=61219.308 write=0.033
-> Partial Aggregate (cost=963311.33..963311.34 rows=1 width=8)
(actual time=34660.023..34660.023 rows=1 loops=3)
Buffers: shared read=442478 dirtied=1 written=1
I/O Timings: read=61219.308 write=0.033
-> Parallel Seq Scan on t1 (cost=0.00..859144.67 rows=41666667
width=0) (actual time=11.559..27607.271 rows=33333333 loops=3)
Buffers: shared read=442478 dirtied=1 written=1
I/O Timings: read=61219.308 write=0.033
Planning time: 38.094 ms
Execution time: 34746.395 ms
(16 rows)
set max_parallel_workers_per_gather to 0;
explain (analyze,buffers) select count(*) from t1;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=1692478.00..1692478.01 rows=1 width=8) (actual
time=34368.540..34368.540 rows=1 loops=1)
Buffers: shared read=442478
I/O Timings: read=8874.662
-> Seq Scan on t1 (cost=0.00..1442478.00 rows=100000000 width=0) (actual
time=20.604..19992.941 rows=100000000 loops=1)
Buffers: shared read=442478
I/O Timings: read=8874.662
Planning time: 37.834 ms
Execution time: 34368.817 ms
(8 rows)
I got similar results on 9.6.
Regards,
--
Adrien NAYRAT
From | Date | Subject | |
---|---|---|---|
Next Message | Jesper Pedersen | 2018-03-27 18:52:19 | Re: [HACKERS] path toward faster partition pruning |
Previous Message | Pavel Stehule | 2018-03-27 18:34:50 | Re: Re: csv format for psql |