Re: [PATCH] Add extra statistics to explain for Nested Loop - Mailing list pgsql-hackers

Hello,

On Thu, 12 Nov 2020 23:10:05 +0300
e.sokolova@postgrespro.ru wrote:

> New version of this patch prints extra statistics for all cases of 
> multiple loops, not only for Nested Loop. Also I fixed the example by 
> adding VERBOSE.

I think this extra statistics seems good because it is useful for DBA
to understand explained plan. I reviewed this patch. Here are a few
comments:

1) 
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.163min_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?

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=0rows=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.202min_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.066min_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);


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


Regards,
Yugo Nagata

-- 
Yugo NAGATA <nagata@sraoss.co.jp>