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

"Jonathan S. Katz" <[email protected]> Sun, 5 Aug 2018 23:33:13 -0400
Newsgroups	gmane.comp.db.postgresql.sql
Message-ID	<[email protected]>
> On Aug 5, 2018, at 11:24 PM, Huan Ruan <[email protected]> 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/[email protected]>

Jonathan
signature.asc (application/pgp-signature, 833 B)