Explain buffers wrong counter with parallel plans - Mailing list 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@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.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