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@sss.pgh.pa.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