Re: [PATCH] Add extra statistics to explain for Nested Loop

On Thu, Jan 28, 2021 at 8:38 PM Yugo NAGATA <nagata(at)sraoss(dot)co(dot)jp> wrote:
>
> postgres=# explain (analyze, verbose) select * from a,b where a.i=b.j;
> QUERY PLAN
> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> Nested Loop (cost=0.00..2752.00 rows=991 width=8) (actual time=0.021..17.651 rows=991 loops=1)
> Output: a.i, b.j
> Join Filter: (a.i = b.j)
> Rows Removed by Join Filter: 99009
> -> Seq Scan on public.b (cost=0.00..2.00 rows=100 width=4) (actual time=0.009..0.023 rows=100 loops=1)
> Output: b.j
> -> Seq Scan on public.a (cost=0.00..15.00 rows=1000 width=4) (actual time=0.005..0.091 min_time=0.065 max_time=0.163 min_rows=1000 rows=1000 max_rows=1000 loops=100)
> Output: a.i
> Planning Time: 0.066 ms
> Execution Time: 17.719 ms
> (10 rows)
>
> I don't like this format where the extra statistics appear in the same
> line of existing information because the output format differs depended
> on whether the plan node's loops > 1 or not. This makes the length of a
> line too long. Also, other information reported by VERBOSE doesn't change
> the exiting row format and just add extra rows for new information.
>
> Instead, it seems good for me to add extra rows for the new statistics
> without changint the existing row format as other VERBOSE information,
> like below.
>
> -> Seq Scan on public.a (cost=0.00..15.00 rows=1000 width=4) (actual time=0.005..0.091 rows=1000 loops=100)
> Output: a.i
> Min Time: 0.065 ms
> Max Time: 0.163 ms
> Min Rows: 1000
> Max Rows: 1000
>
> or, like Buffers,
>
> -> Seq Scan on public.a (cost=0.00..15.00 rows=1000 width=4) (actual time=0.005..0.091 rows=1000 loops=100)
> Output: a.i
> Loops: min_time=0.065 max_time=0.163 min_rows=1000 max_rows=1000
>
> and so on. What do you think about it?

It's true that the current output is a bit long, which isn't really
convenient to read. Using one of those alternative format would also
have the advantage of not breaking compatibility with tools that
process those entries. I personally prefer the 2nd option with the
extra "Loops:" line . For non text format, should we keep the current
format?

> 2)
> In parallel scan, the extra statistics are not reported correctly.
>
> postgres=# explain (analyze, verbose) select * from a,b where a.i=b.j;
> QUERY PLAN
> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> Gather (cost=1000.00..2463.52 rows=991 width=8) (actual time=0.823..25.651 rows=991 loops=1)
> Output: a.i, b.j
> Workers Planned: 2
> Workers Launched: 2
> -> Nested Loop (cost=0.00..1364.42 rows=413 width=8) (actual time=9.426..16.723 min_time=0.000 max_time=22.017 min_rows=0 rows=330 max_rows=991 loops=3)
> Output: a.i, b.j
> Join Filter: (a.i = b.j)
> Rows Removed by Join Filter: 33003
> Worker 0: actual time=14.689..14.692 rows=0 loops=1
> Worker 1: actual time=13.458..13.460 rows=0 loops=1
> -> Parallel Seq Scan on public.a (cost=0.00..9.17 rows=417 width=4) (actual time=0.049..0.152 min_time=0.000 max_time=0.202 min_rows=0 rows=333 max_rows=452 loops=3)
> Output: a.i
> Worker 0: actual time=0.040..0.130 rows=322 loops=1
> Worker 1: actual time=0.039..0.125 rows=226 loops=1
> -> Seq Scan on public.b (cost=0.00..2.00 rows=100 width=4) (actual time=0.006..0.026 min_time=0.012 max_time=0.066 min_rows=100 rows=100 max_rows=100 loops=1000)
> Output: b.j
> Worker 0: actual time=0.006..0.024 min_time=0.000 max_time=0.000 min_rows=0 rows=100 max_rows=0 loops=322
> Worker 1: actual time=0.008..0.030 min_time=0.000 max_time=0.000 min_rows=0 rows=100 max_rows=0 loops=226
> Planning Time: 0.186 ms
> Execution Time: 25.838 ms
> (20 rows)
>
> This reports max/min rows or time of inner scan as 0 in parallel workers,
> and as a result only the leader process's ones are accounted. To fix this,
> we would change InstrAggNode as below.
>
> @@ -167,6 +196,10 @@ InstrAggNode(Instrumentation *dst, Instrumentation *add)
> dst->nloops += add->nloops;
> dst->nfiltered1 += add->nfiltered1;
> dst->nfiltered2 += add->nfiltered2;
> + dst->min_t = Min(dst->min_t, add->min_t);
> + dst->max_t = Max(dst->max_t, add->max_t);
> + dst->min_tuples = Min(dst->min_tuples, add->min_tuples);
> + dst->max_tuples = Max(dst->max_tuples, add->max_tuples);

Agreed.

> 3)
> There are garbage lines and I could not apply this patch.
>
> diff --git a/src/test/regress/expected/timetz.out b/src/test/regress/expected/timetz.out
> index 038bb5fa094..5294179aa45 100644

I also switch the patch to "waiting on author" on the commit fest app.