Re: Explain buffers wrong counter with parallel plans

On Wed, Mar 28, 2018 at 12:07 AM, Adrien Nayrat
<adrien(dot)nayrat(at)anayrat(dot)info> wrote:
> 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
now> Execution time: 34368.097 ms
> (8 rows)
>
>
>
> Gather and Finalize Aggregate should report shared read=442478.
>

Yeah, it would have been convenient, if Gather and Finalize Aggregate
displays that way as it would have been easier for users to
understand. However, as of now, the aggregated stats for parallel
workers and leader are displayed at parallel/partial nodes as is
displayed in the plan. So according to me, what you are seeing is
okay, it is only slightly tricky to understand it.

> I am also surprised for I/O Timings in parallel node:
> I/O Timings: read=60706.314 but the query last 34s?
>

This is the aggregated time of all the parallel workers, so you need
to divide it by loops (which in your case is 3).

> 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
>

I think you were seeing different results before this commit because
before that we were shutting down workers as soon as parallel workers
are done and the buffer_usage stats were accumulated and were being
used for upper nodes. According to me behavior after the commit is
consistent, for example, I think if you check the case of GatherMerge
before this commit, you will still get the stats in the way it is
after commit.

--
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com