Re: EXPLAIN: Non-parallel ancestor plan nodes exclude parallel worker instrumentation

On Tue, Jun 23, 2020 at 12:55 AM Maciek Sakrejda <m(dot)sakrejda(at)gmail(dot)com> wrote:
>
> Hello,
>
> I had some questions about the behavior of some accounting in parallel
> EXPLAIN plans. Take the following plan:
>
>
..
>
> The Nested Loop here aggregates data for metrics like `buffers read`
> from its workers, and to calculate a metric like `buffers read` for
> the parallel leader, we can subtract the values recorded in each
> individual worker. This happens in the Seq Scan and Index Scan
> children, as well. However, the Gather node appears to only include
> values from its direct parallel leader child (excluding that child's
> workers).
>

I have tried to check a similar plan and for me, the values at Gather
node seems to be considering the values from all workers and leader
(aka whatever is displayed at "Nested Loop " node), see below. I have
tried the test on HEAD. Which version of PostgreSQL are you using?
If you are also using the latest version then it is possible that in
some cases it is not displaying correct data. If that turns out to be
the case, then feel to share the test case. Sorry, for the confusion
caused by my previous reply.

Gather (actual time=2.083..550.093 rows=10000 loops=1)
Output: t1.c1, t1.c2, t2.c1, t2.c2
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=1012621 read=84
I/O Timings: read=0.819
-> Nested Loop (actual time=0.084..541.882 rows=3333 loops=3)
Output: t1.c1, t1.c2, t2.c1, t2.c2
Buffers: shared hit=1012621 read=84
I/O Timings: read=0.819
Worker 0: actual time=0.069..541.249 rows=3155 loops=1
Buffers: shared hit=326529 read=29
I/O Timings: read=0.325
Worker 1: actual time=0.063..541.376 rows=3330 loops=1
Buffers: shared hit=352045 read=26
I/O Timings: read=0.179
-> Parallel Seq Scan on public.t1 (actual time=0.011..34.250
rows=166667 loops=3)
Output: t1.c1, t1.c2
Buffers: shared hit=2703
Worker 0: actual time=0.011..33.785 rows=161265 loops=1
Buffers: shared hit=872
Worker 1: actual time=0.009..34.582 rows=173900 loops=1
Buffers: shared hit=940
-> Index Scan using idx_t2 on public.t2 (actual
time=0.003..0.003 rows=0 loops=500000)
Output: t2.c1, t2.c2
Index Cond: (t2.c1 = t1.c1)
Buffers: shared hit=1009918 read=84
I/O Timings: read=0.819
Worker 0: actual time=0.003..0.003 rows=0 loops=161265
Buffers: shared hit=325657 read=29
I/O Timings: read=0.325
Worker 1: actual time=0.002..0.002 rows=0 loops=173900
Buffers: shared hit=351105 read=26
I/O Timings: read=0.179

--
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com