Re: Explain buffers wrong counter with parallel plans

On Wed, Jul 25, 2018 at 7:42 PM, Jonathan S. Katz
<jonathan(dot)katz(at)excoventures(dot)com> wrote:
>
> On Jul 7, 2018, at 12:03 AM, Amit Kapila <amit(dot)kapila16(at)gmail(dot)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