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

From: Huan Ruan <leohuanruan(at)gmail(dot)com>
To: pgsql-sql(at)lists(dot)postgresql(dot)org
Subject: read explain (analyse, buffers) output in Postgres 10.4 with parallel on
Date: 2018-08-06 03:24:08
Message-ID: CAGgcTZs0o02L2uoZOAzcFRD62RgtJfwu+FAPLVzw--M3jSHrhw@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-sql

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?

Thanks
Huan

Responses

Browse pgsql-sql by date

  From Date Subject
Next Message Jonathan S. Katz 2018-08-06 03:33:13 Re: read explain (analyse, buffers) output in Postgres 10.4 with parallel on
Previous Message pinker 2018-08-03 14:26:25 Re: List user who have access to schema