Re: parallel joins, and better parallel explain

On Thu, Dec 3, 2015 at 3:25 AM, Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
>
> On Tue, Dec 1, 2015 at 7:21 AM, Amit Kapila <amit(dot)kapila16(at)gmail(dot)com>
wrote:
>
> > - There seems to be some inconsistency in Explain's output when
> > multiple workers are used.
>
>
> So the net result of this is that the times and row counts are
> *averages* across all of the loop iterations. In the case of the
> inner side of a nested loop, this means you can read the data just as
> you would in a non-parallel plan. For nodes executed exactly once per
> worker plus once in the master, the value displayed ends up being a
> per-process average of the amount of time spent, and a per-process
> average of the number of rows. On the other hand, values for buffers
> are NOT divided by the loop count, so those values are absolute
> totals. Once you understand this, I think the data is pretty easy to
> read.
>

Okay, I am able to understand the results now.

Currently if the node doesn't get executed due to any reason we
use below code to display the required information:
else if (es->analyze)
{
if (es->format == EXPLAIN_FORMAT_TEXT)
appendStringInfoString(es->str, " (never executed)");
else
{
if
(es->timing)
{
ExplainPropertyFloat("Actual Startup Time",
0.0, 3, es);
ExplainPropertyFloat("Actual Total Time", 0.0, 3, es);
}
ExplainPropertyFloat("Actual Rows", 0.0, 0, es);
ExplainPropertyFloat("Actual Loops", 0.0, 0, es);
}
}

Do you think it will be useful to display in a similar way if worker
is not able to execute plan (like before it starts execution, the other
workers have already finished the work)?

Other than that parallel-explain-v2.patch looks good.

> > -> Gather (cost=1000.00..46203.83 rows=9579 width=0) (actual
> > time=33.983..3
> > 3592.030 rows=9999 loops=1)
> > Output: c1, c2
> > Number of Workers: 4
> > Buffers: shared hit=548 read=142506
> > -> Parallel Seq Scan on public.tbl_parallel_test
> > (cost=0.00..44245.93
> > rows=2129 width=0) (actual time=13.447..33354.099 rows=2000 loops=5)
> > Output: c1, c2
> > Filter: (tbl_parallel_test.c1 < 10000)
> > Rows Removed by Filter: 198000
> > Buffers: shared hit=352 read=142506
> > Worker 0: actual time=18.422..33322.132 rows=2170 loops=1
> > Buffers: shared hit=4 read=30765
> > Worker 1: actual time=0.803..33283.979 rows=1890 loops=1
> > Buffers: shared hit=1 read=26679
> > Worker 2: actual time=0.711..33360.007 rows=1946 loops=1
> > Buffers: shared hit=197 read=30899
> > Worker 3: actual time=15.057..33252.605 rows=2145 loops=1
> > Buffers: shared hit=145 read=25433
> > Planning time: 0.217 ms
> > Execution time: 33612.964 ms
> > (22 rows)
> >
> > I am not able to understand how buffer usage add upto what is
> > shown at Gather node.
>
> It doesn't, of course. But I'm not sure it should,
>

I think the problem is at Gather node, the number of buffers (read + hit)
are greater than the number of pages in relation. The reason why it
is doing so is that in Workers (ParallelQueryMain()), it starts the buffer
usage accumulation before ExecutorStart() whereas in master backend
it always calculate it for ExecutorRun() phase, on changing it to accumulate
for ExecutorRun() phase above problem is fixed. Attached patch fixes the
problem.

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