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

On Aug 5, 2018, at 11:24 PM, Huan Ruan <leohuanruan@gmail.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

Jonathan