Re: Explain buffers wrong counter with parallel plans

> On Jul 7, 2018, at 12:03 AM, Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> On Sat, Jul 7, 2018 at 7:45 AM, Amit Kapila <amit.kapila16@gmail.com <mailto:amit.kapila16@gmail.com>> wrote:
>> On Sat, Jul 7, 2018 at 12:44 AM, Robert Haas <robertmhaas@gmail.com> wrote:
>>> On Fri, Jul 6, 2018 at 9:44 AM, Amit Kapila <amit.kapila16@gmail.com> wrote:
>>>> I have tried this idea, but it doesn't completely solve the problem.
>>>> The problem is that nodes below LIMIT won't get a chance to accumulate
>>>> the stats as they won't be able to call InstrStopNode.
>>> 
>>> I'm not sure I understand.  Why not?  I see that we'd need to insert
>>> an extra call to InstrStopNode() if we were stopping the node while it
>>> was running, because then InstrStartNode() would have already been
>>> done, but the corresponding call to InstrStopNode() would not have
>>> been done.  But I'm not sure how that would happen in this case.  Can
>>> you explain further?
>>> 
>> 
>> Okay, let me try.   The code flow is that for each node we will call
>> InstrStartNode()->ExecProcNodeReal()->InstrStopNode().  Now let's say
>> we have to execute a plan Limit->Gather-> Parallel SeqScan.  In this,
>> first for Limit node, we will call InstrStartNode() and
>> ExecProcNodeReal() and then for Gather we will call InstrStartNode(),
>> ExecProcNodeReal() and InstrStopNode().  Now, Limit node decides that
>> it needs to shutdown all the nodes (ExecShutdownNode) and after that
>> it will call InstrStopNode() for Limit node.  So, in this flow after
>> shutting down nodes, we never get chance for Gather node to use stats
>> collected during ExecShutdownNode.
>> 
> 
> I went ahead and tried the solution which I had mentioned yesterday,
> that is to allow ExecShutdownNode to count stats.  Apart from fixing
> this problem, it will also fix the problem with Gather Merge as
> reported by Adrien [1], because now Gather Merge will also get a
> chance to count stats after shutting down workers.
> 
> Note that, I have changed the location of InstrStartParallelQuery in
> ParallelQueryMain so that the buffer usage stats are accumulated only
> for the plan execution which is what we do for instrumentation
> information as well.  If we don't do that, it will count some
> additional stats for ExecutorStart which won't match with what we have
> in Instrumentation structure of each node.

I tried running the below on both 11beta2 and HEAD with the patch
applied:

	CREATE UNLOGGED TABLE t1 (c1 int);
	INSERT INTO t1 SELECT generate_series(1,100000000);
	/** restart PostgreSQL */
	EXPLAIN (analyze,buffers,timing off,costs off)
	SELECT count(*) FROM t1;
	/** repeat above two queries */

I have identical postgresql.conf files on both instances as well.

11beta2
======
    buffers=# explain (analyze,buffers,timing off,costs off) select count(*)
    from t1;
                                    QUERY PLAN
    --------------------------------------------------------------------------
     Finalize Aggregate (actual rows=1 loops=1)
       Buffers: shared read=63175
       ->  Gather (actual rows=7 loops=1)
             Workers Planned: 6
             Workers Launched: 6
             Buffers: shared read=63175
             ->  Partial Aggregate (actual rows=1 loops=7)
                   Buffers: shared read=442478
                   ->  Parallel Seq Scan on t1 (actual rows=14285714 loops=7)
                         Buffers: shared read=442478
     Planning Time: 1.422 ms
     Execution Time: 3214.407 ms
    (12 rows)

    buffers=# explain (analyze,buffers,timing off,costs off) select count(*)
    from t1;
                                    QUERY PLAN
    --------------------------------------------------------------------------
     Finalize Aggregate (actual rows=1 loops=1)
       Buffers: shared hit=27 read=64960
       ->  Gather (actual rows=7 loops=1)
             Workers Planned: 6
             Workers Launched: 6
             Buffers: shared hit=27 read=64960
             ->  Partial Aggregate (actual rows=1 loops=7)
                   Buffers: shared hit=224 read=442254
                   ->  Parallel Seq Scan on t1 (actual rows=14285714 loops=7)
                         Buffers: shared hit=224 read=442254
     Planning Time: 0.080 ms
     Execution Time: 3774.091 ms
    (12 rows)

HEAD
=====
    buffers=# explain (analyze,buffers,timing off,costs off) select count(*)
    from t1;
                                    QUERY PLAN
    --------------------------------------------------------------------------
     Finalize Aggregate (actual rows=1 loops=1)
       Buffers: shared read=442478
       ->  Gather (actual rows=7 loops=1)
             Workers Planned: 6
             Workers Launched: 6
             Buffers: shared read=442478
             ->  Partial Aggregate (actual rows=1 loops=7)
                   Buffers: shared read=442478
                   ->  Parallel Seq Scan on t1 (actual rows=14285714 loops=7)
                         Buffers: shared read=442478
     Planning Time: 1.594 ms
     Execution Time: 6207.799 ms
    (12 rows)

    buffers=# explain (analyze,buffers,timing off,costs off) select count(*)
    from t1;
                                    QUERY PLAN
    --------------------------------------------------------------------------
     Finalize Aggregate (actual rows=1 loops=1)
       Buffers: shared hit=224 read=442254
       ->  Gather (actual rows=7 loops=1)
             Workers Planned: 6
             Workers Launched: 6
             Buffers: shared hit=224 read=442254
             ->  Partial Aggregate (actual rows=1 loops=7)
                   Buffers: shared hit=224 read=442254
                   ->  Parallel Seq Scan on t1 (actual rows=14285714 loops=7)
                         Buffers: shared hit=224 read=442254
     Planning Time: 0.074 ms
     Execution Time: 5006.395 ms
    (12 rows)

Notice the “read” numbers just before the “Finalize Aggregate” is much
higher, and there appears to be a performance hit.

Jonathan