Re: Explain buffers wrong counter with parallel plans

Hi,

On 2018-04-29 20:40:43 +0530, Amit Kapila wrote:
> On Wed, Mar 28, 2018 at 12:07 AM, Adrien Nayrat
> > 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.

Robert, you added this as an open item. I don't think it's clear that
there's a bug here, and even less clear that it's something new for
v11. Am I understanding that right? Should we close this open item?

Greetings,

Andres Freund