Re: Explain buffers wrong counter with parallel plans

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.

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

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