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

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