Re: Explain buffers wrong counter with parallel plans

> On Jul 25, 2018, at 10:25 PM, Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> On Wed, Jul 25, 2018 at 7:42 PM, Jonathan S. Katz
> <jonathan.katz@excoventures.com> wrote:
>> 
>> On Jul 7, 2018, at 12:03 AM, Amit Kapila <amit.kapila16@gmail.com> wrote:
>> 
>> 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,
>> 
> 
> You mean to say the number (Buffers: shared read=442478) in HEAD,
> right?  If so, yeah, I am also wondering why the results of the patch
> are different in HEAD and 11beta2.  So, if I read correctly, the
> numbers in 11beta2 appears correct, but on HEAD it is not correct, it
> should have divided the buffers read by loops.  I will figure that
> out, but this is just to clarify that both of us are seeing the
> results in the same way.

I’ll try it again but patch it against 11beta2 and see what results I get.

> 
>> and there appears to be a performance hit.
>> 
> 
> Do you mean to say the performance of the same query in 11beta2 and
> HEAD or something else?

Correct. But per your advice let me try running it against a patched
version of 11beta2 and see what happens.

Jonathan