Re: read explain (analyse, buffers) output in Postgres 10.4 with parallel on

Many thanks Jonathan. I will check it out when 10.5 is released.

On Mon, 6 Aug 2018 at 13:33 Jonathan S. Katz <jonathan(dot)katz(at)excoventures(dot)com>
wrote:

>
> On Aug 5, 2018, at 11:24 PM, Huan Ruan <leohuanruan(at)gmail(dot)com> wrote:
>
> Hi
>
> PostgreSQL 10.4 on CentOS 7.2 64 bit
>
> As per doc states in
> https://www.postgresql.org/docs/current/static/sql-explain.html, under
> the BUFFERS section:
>
> *The number of blocks shown for an upper-level node includes those used by
> all its child nodes.*
>
> However, with parallel execution, the output of 'explain (analyse,
> buffers)' does not seem to match the above doc..
>
> To illustrate,
> psql -qE <<EOF
> drop database IF EXISTS test_db;
> create database test_db;
> \c test_db
> create table t1 as select f from generate_series(1, 1000000) as t(f);
> -- warm up cache
> select count(*) from t1;
>
> set max_parallel_workers_per_gather to 0;
> explain (analyse, buffers) select count(*) from t1;
>
> set max_parallel_workers_per_gather to 4;
> explain (analyse, buffers) select count(*) from t1;
> EOF
>
> *Output*
> QUERY PLAN
>
> -------------------------------------------------------------------------------------------------------------------
> Aggregate (cost=63664.69..63664.74 rows=1 width=8) (actual
> time=176.344..176.344 rows=1 loops=1)
> *Buffers: shared hit=4425*
> -> Seq Scan on t1 (cost=0.00..60843.75 rows=1128375 width=0) (actual
> time=0.010..91.800 rows=1000000 loops=1)
> Buffers: shared hit=4425
> Planning time: 0.101 ms
> Execution time: 176.418 ms
> (6 rows)
>
> QUERY PLAN
>
> --------------------------------------------------------------------------------------------------------------------------------------
> Finalize Aggregate (cost=30108.46..30108.51 rows=1 width=8) (actual
> time=88.572..88.572 rows=1 loops=1)
> *Buffers: shared hit=2075*
> -> Gather (cost=30108.20..30108.45 rows=2 width=8) (actual
> time=88.549..88.567 rows=3 loops=1)
> Workers Planned: 2
> Workers Launched: 2
> Buffers: shared hit=2075
> -> Partial Aggregate (cost=29108.20..29108.25 rows=1 width=8)
> (actual time=83.902..83.902 rows=1 loops=3)
> Buffers: shared hit=4425
> -> Parallel Seq Scan on t1 (cost=0.00..27932.81
> rows=470156 width=0) (actual time=0.026..48.045 rows=333333 loops=3)
> Buffers: shared hit=4425
> Planning time: 0.201 ms
> Execution time: 91.212 ms
> (12 rows)
>
> I would've thought the *highlighted* nodes are at top-level.
>
> - Output 1 with parallel off seems to match the doc.
> - Output 2 with parallel on does not seem to match the doc.
>
> Am I missing something in interpreting output 2? What is the expected way
> to work out a query's total buffer usage?
>
>
> This will be fixed in 10.5, which is being released on 2018-08-09.
>
> If you want some history on the issue, you can read about it here:
>
>
> https://www.postgresql.org/message-id/flat/86137f17-1dfb-42f9-7421-82fd786b04a1%40anayrat.info
> <https://www.postgresql.org/message-id/flat/86137f17-1dfb-42f9-7421-82fd786b04a1(at)anayrat(dot)info>
>
> Jonathan
>