Re: Explain buffers wrong counter with parallel plans

Hello,

I tried to understand this issue and it seems Gather node only take account of
this own buffer usage :

create unlogged table t1 (c1 int);
insert into t1 select generate_series(1,1000000);
vacuum t1;

explain (analyze,buffers,timing off,costs off) select count(*) from t1;
QUERY PLAN
------------------------------------------------------------------------
Finalize Aggregate (actual rows=1 loops=1)
Buffers: shared hit=1531
-> Gather (actual rows=3 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=1531
-> Partial Aggregate (actual rows=1 loops=3)
Buffers: shared hit=4425
-> Parallel Seq Scan on t1 (actual rows=333333 loops=3)
Buffers: shared hit=4425

Same query without parallelism

QUERY PLAN
----------------------------------------------------
Aggregate (actual rows=1 loops=1)
Buffers: shared hit=4425
-> Seq Scan on t1 (actual rows=1000000 loops=1)
Buffers: shared hit=4425

We can notice Parallel Seq Scan and Partial Aggregate report 4425 buffers, same
for the plan without parallelism.

I put elog debug around theses lines in execParallel.c :

/* Accumulate the statistics from all workers. */
instrument = GetInstrumentationArray(instrumentation);
instrument += i * instrumentation->num_workers;
for (n = 0; n < instrumentation->num_workers; ++n)
{
elog(LOG, "worker %d - shared_blks_read: %ld - shared_blks_hit: %ld", n,
instrument[n].bufusage.shared_blks_read,instrument[n].bufusage.shared_blks_hit);
InstrAggNode(planstate->instrument, &instrument[n]);
}

And I get theses messages :

LOG: worker 0 - shared_blks_read: 0 - shared_blks_hit: 1443
LOG: worker 1 - shared_blks_read: 0 - shared_blks_hit: 1451

If you sum each worker's shared_blks_read and Gather's shared hit you get :
1443 + 1451 + 1531 = 4425 (size of t1)

It seems Gather node and Finalize Aggregate only report buffers read by the main
process. Workers seem omitted.

Same issue occurs for Gather merge :

explain (analyze,buffers,timing off,costs off)
select * from t1 where c1%10=4 order by 1;

QUERY PLAN
-----------------------------------------------------------------
Gather Merge (actual rows=100000 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=1549
-> Sort (actual rows=33333 loops=3)
Sort Key: c1
Sort Method: quicksort Memory: 3143kB
Buffers: shared hit=4521
-> Parallel Seq Scan on t1 (actual rows=33333 loops=3)
Filter: ((c1 % 10) = 4)
Rows Removed by Filter: 300000
Buffers: shared hit=4425

In my log :
worker 0 - shared_blks_read: 0 - shared_blks_hit: 1487
worker 1 - shared_blks_read: 0 - shared_blks_hit: 1485

1487 + 1485 + 1549 = 4521

I tried to understand how instrumentation works, but it is above my knowledge :(

Regards,

--
Adrien