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 <t...@sss.pgh.pa.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.1504192...@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
signature.asc
Description: OpenPGP digital signature
