From e0d92f2c112002bbacaae7abb747ea618d7fbd93 Mon Sep 17 00:00:00 2001
From: Ekaterina Sokolova <e.sokolova@postgrespro.ru>
Date: Fri, 1 Apr 2022 21:36:21 -0500
Subject: [PATCH 2/2] Add extra statistics to explain for Nested Loop

For some distributions of data in tables, different loops in nested loop
joins can take different time and process different amounts of entries.
It makes average statistics returned by explain analyze not very useful for DBA.

This patch add collecting of min, max and total statistics for time and rows
across all loops to EXPLAIN ANALYSE. You need to set the VERBOSE flag to display
this information. The patch contains regression tests.

Example of results in TEXT format:
   ->  Append (actual rows=5 loops=5)
         Loop Min Rows: 2  Max Rows: 6  Total Rows: 23

Reviewed-by: Lukas Fittl, Justin Pryzby, Yugo Nagata, Julien Rouhaud.
---
 src/backend/commands/explain.c                |  42 ++++++-
 src/backend/executor/instrument.c             |  38 +++++-
 src/include/executor/instrument.h             |  10 ++
 src/test/regress/expected/explain.out         |  10 ++
 src/test/regress/expected/partition_prune.out | 117 ++++++++++++++++++
 src/test/regress/sql/partition_prune.sql      |  32 +++++
 6 files changed, 247 insertions(+), 2 deletions(-)

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 06e089a1220..df14803ff06 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -119,7 +119,7 @@ static void show_instrumentation_count(const char *qlabel, int which,
 static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es);
 static void show_eval_params(Bitmapset *bms_params, ExplainState *es);
 static void show_loop_info(Instrumentation *instrument, bool isworker,
-		ExplainState *es);
+						   ExplainState *es);
 static const char *explain_get_index_name(Oid indexId);
 static void show_buffer_usage(ExplainState *es, const BufferUsage *usage,
 							  bool planning);
@@ -541,6 +541,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	if (es->wal)
 		instrument_option |= INSTRUMENT_WAL;
 
+	if (es->verbose)
+		instrument_option |= INSTRUMENT_EXTRA;
+
 	/*
 	 * We always collect timing for the entire statement, even when node-level
 	 * timing is off, so we don't look at es->timing here.  (We could skip
@@ -1624,6 +1627,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 			appendStringInfoString(es->str, " (never executed)");
 		else
 		{
+			/* without min and max values because actual result is 0 */
 			if (es->timing)
 			{
 				ExplainPropertyFloat("Actual Startup Time", "ms", 0.0, 3, es);
@@ -3989,6 +3993,11 @@ show_loop_info(Instrumentation *instrument, bool isworker, ExplainState *es)
 	double		startup_ms = 1000.0 * instrument->startup / nloops;
 	double		total_ms = 1000.0 * instrument->total / nloops;
 	double		rows = instrument->ntuples / nloops;
+	double		loop_total_rows = instrument->ntuples;
+	double		loop_min_r = instrument->min_tuples;
+	double		loop_max_r = instrument->max_tuples;
+	double		loop_min_t_ms = 1000.0 * instrument->min_t;
+	double		loop_max_t_ms = 1000.0 * instrument->max_t;
 
 	if (es->format == EXPLAIN_FORMAT_TEXT)
 	{
@@ -4008,6 +4017,21 @@ show_loop_info(Instrumentation *instrument, bool isworker, ExplainState *es)
 
 		if (!isworker)
 			appendStringInfoChar(es->str, ')');
+
+		if (nloops > 1 && es->verbose)
+		{
+			appendStringInfoChar(es->str, '\n');
+			ExplainIndentText(es);
+
+			if (es->timing)
+				appendStringInfo(es->str,
+								 "Loop Min Rows: %.0f  Max Rows: %.0f  Total Rows: %.0f  Min Time: %.3f  Max Time: %.3f",
+								 loop_min_r, loop_max_r, loop_total_rows, loop_min_t_ms, loop_max_t_ms);
+			else
+				appendStringInfo(es->str,
+								 "Loop Min Rows: %.0f  Max Rows: %.0f  Total Rows: %.0f",
+								 loop_min_r, loop_max_r, loop_total_rows);
+		}
 	}
 	else
 	{
@@ -4017,8 +4041,24 @@ show_loop_info(Instrumentation *instrument, bool isworker, ExplainState *es)
 								 3, es);
 			ExplainPropertyFloat("Actual Total Time", "ms", total_ms,
 								 3, es);
+			if (nloops > 1 && es->verbose)
+			{
+				ExplainPropertyFloat("Loop Min Time", "ms", loop_min_t_ms,
+									 3, es);
+				ExplainPropertyFloat("Loop Max Time", "ms", loop_max_t_ms,
+									 3, es);
+			}
 		}
+
 		ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es);
+
+		if (nloops > 1 && es->verbose)
+		{
+			ExplainPropertyFloat("Loop Min Rows", NULL, loop_min_r, 0, es);
+			ExplainPropertyFloat("Loop Max Rows", NULL, loop_max_r, 0, es);
+			ExplainPropertyFloat("Loop Total Rows", NULL, loop_total_rows, 0, es);
+		}
+
 		ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es);
 	}
 }
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index c5ff02a8424..ac46011e516 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -34,11 +34,12 @@ InstrAlloc(int n, int instrument_options, bool async_mode)
 
 	/* initialize all fields to zeroes, then modify as needed */
 	instr = palloc0(n * sizeof(Instrumentation));
-	if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER | INSTRUMENT_WAL))
+	if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER | INSTRUMENT_WAL | INSTRUMENT_EXTRA))
 	{
 		bool		need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0;
 		bool		need_wal = (instrument_options & INSTRUMENT_WAL) != 0;
 		bool		need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
+		bool		need_extra = (instrument_options & INSTRUMENT_EXTRA) != 0;
 		int			i;
 
 		for (i = 0; i < n; i++)
@@ -46,6 +47,7 @@ InstrAlloc(int n, int instrument_options, bool async_mode)
 			instr[i].need_bufusage = need_buffers;
 			instr[i].need_walusage = need_wal;
 			instr[i].need_timer = need_timer;
+			instr[i].need_extra = need_extra;
 			instr[i].async_mode = async_mode;
 		}
 	}
@@ -61,6 +63,7 @@ InstrInit(Instrumentation *instr, int instrument_options)
 	instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0;
 	instr->need_walusage = (instrument_options & INSTRUMENT_WAL) != 0;
 	instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
+	instr->need_extra = (instrument_options & INSTRUMENT_EXTRA) != 0;
 }
 
 /* Entry to a plan node */
@@ -154,6 +157,35 @@ InstrEndLoop(Instrumentation *instr)
 	instr->startup += instr->firsttuple;
 	instr->total += totaltime;
 	instr->ntuples += instr->tuplecount;
+
+	/*
+	 * this is first loop
+	 *
+	 * We only initialize the min values. We don't need to bother with the
+	 * max, because those are 0 and the non-zero values will get updated a
+	 * couple lines later.
+	 */
+	if (instr->need_extra)
+	{
+		if (instr->nloops == 0)
+		{
+			instr->min_t = totaltime;
+			instr->min_tuples = instr->tuplecount;
+		}
+
+		if (instr->min_t > totaltime)
+			instr->min_t = totaltime;
+
+		if (instr->max_t < totaltime)
+			instr->max_t = totaltime;
+
+		if (instr->min_tuples > instr->tuplecount)
+			instr->min_tuples = instr->tuplecount;
+
+		if (instr->max_tuples < instr->tuplecount)
+			instr->max_tuples = instr->tuplecount;
+	}
+
 	instr->nloops += 1;
 
 	/* Reset for next cycle (if any) */
@@ -186,6 +218,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);
 
 	/* Add delta of buffer usage since entry to node's totals */
 	if (dst->need_bufusage)
diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 1b7157bdd15..e6178e248dc 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -58,6 +58,8 @@ typedef enum InstrumentOption
 	INSTRUMENT_BUFFERS = 1 << 1,	/* needs buffer usage */
 	INSTRUMENT_ROWS = 1 << 2,	/* needs row count */
 	INSTRUMENT_WAL = 1 << 3,	/* needs WAL usage */
+	INSTRUMENT_EXTRA = 1 << 4,	/* needs counters for min,
+								 * max and total values */
 	INSTRUMENT_ALL = PG_INT32_MAX
 } InstrumentOption;
 
@@ -67,6 +69,8 @@ typedef struct Instrumentation
 	bool		need_timer;		/* true if we need timer data */
 	bool		need_bufusage;	/* true if we need buffer usage data */
 	bool		need_walusage;	/* true if we need WAL usage data */
+	bool		need_extra;		/* true if we need min, max and total
+								 * statistics for loops */
 	bool		async_mode;		/* true if node is in async mode */
 	/* Info about current plan cycle: */
 	bool		running;		/* true if we've completed first tuple */
@@ -79,7 +83,13 @@ typedef struct Instrumentation
 	/* Accumulated statistics across all completed cycles: */
 	double		startup;		/* total startup time (in seconds) */
 	double		total;			/* total time (in seconds) */
+	double		min_t;			/* time of fastest loop (in seconds) */
+	double		max_t;			/* time of slowest loop (in seconds) */
 	double		ntuples;		/* total tuples produced */
+	double		min_tuples;		/* min counter of produced tuples for all
+								 * loops */
+	double		max_tuples;		/* max counter of produced tuples for all
+								 * loops */
 	double		ntuples2;		/* secondary node-specific tuple counter */
 	double		nloops;			/* # of run cycles for this node */
 	double		nfiltered1;		/* # of tuples removed by scanqual or joinqual */
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index bc361759219..c70d0e288da 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -357,8 +357,13 @@ select jsonb_pretty(
                              "Actual Loops": 0,             +
                              "Startup Cost": 0.0,           +
                              "Async Capable": false,        +
+                             "Loop Max Rows": 0,            +
+                             "Loop Max Time": 0.0,          +
+                             "Loop Min Rows": 0,            +
+                             "Loop Min Time": 0.0,          +
                              "Relation Name": "tenk1",      +
                              "Parallel Aware": true,        +
+                             "Loop Total Rows": 0,          +
                              "Local Hit Blocks": 0,         +
                              "Temp Read Blocks": 0,         +
                              "Actual Total Time": 0.0,      +
@@ -403,7 +408,12 @@ select jsonb_pretty(
                      "Actual Loops": 0,                     +
                      "Startup Cost": 0.0,                   +
                      "Async Capable": false,                +
+                     "Loop Max Rows": 0,                    +
+                     "Loop Max Time": 0.0,                  +
+                     "Loop Min Rows": 0,                    +
+                     "Loop Min Time": 0.0,                  +
                      "Parallel Aware": false,               +
+                     "Loop Total Rows": 0,                  +
                      "Sort Space Used": 0,                  +
                      "Local Hit Blocks": 0,                 +
                      "Temp Read Blocks": 0,                 +
diff --git a/src/test/regress/expected/partition_prune.out b/src/test/regress/expected/partition_prune.out
index 7555764c779..18617b9e206 100644
--- a/src/test/regress/expected/partition_prune.out
+++ b/src/test/regress/expected/partition_prune.out
@@ -1962,6 +1962,24 @@ begin
     end loop;
 end;
 $$;
+create function explain_verbose_parallel_append(text) returns setof text
+language plpgsql as
+$$
+declare
+    ln text;
+begin
+    for ln in
+        execute format('explain (analyze, verbose, costs off, summary off, timing off) %s',
+            $1)
+    loop
+        ln := regexp_replace(ln, 'Workers Launched: \d+', 'Workers Launched: N');
+        ln := regexp_replace(ln, 'actual rows=\d+ loops=\d+', 'actual rows=N loops=N');
+        ln := regexp_replace(ln, 'Loop Min Rows: \d+  Max Rows: \d+  Total Rows: \d+',
+                                 'Loop Min Rows: N  Max Rows: N  Total Rows: N');
+        return next ln;
+    end loop;
+end;
+$$;
 prepare ab_q4 (int, int) as
 select avg(a) from ab where a between $1 and $2 and b < 4;
 -- Encourage use of parallel plans
@@ -2218,6 +2236,39 @@ select explain_parallel_append('select avg(ab.a) from ab inner join lprt_a a on
                                  Index Cond: (a = a.a)
 (28 rows)
 
+-- Tests for extra statistics
+create table lprt_b (b int not null);
+insert into lprt_b select generate_series(1,20);
+select explain_verbose_parallel_append('select * from lprt_a join lprt_b on a != b');
+                       explain_verbose_parallel_append                        
+------------------------------------------------------------------------------
+ Nested Loop (actual rows=N loops=N)
+   Output: lprt_a.a, lprt_b.b
+   Join Filter: (lprt_a.a <> lprt_b.b)
+   Rows Removed by Join Filter: 4
+   ->  Gather (actual rows=N loops=N)
+         Output: lprt_b.b
+         Workers Planned: 2
+         Workers Launched: N
+         ->  Parallel Seq Scan on public.lprt_b (actual rows=N loops=N)
+               Loop Min Rows: N  Max Rows: N  Total Rows: N
+               Output: lprt_b.b
+               Worker 0:  actual rows=N loops=N
+               Worker 1:  actual rows=N loops=N
+   ->  Materialize (actual rows=N loops=N)
+         Loop Min Rows: N  Max Rows: N  Total Rows: N
+         Output: lprt_a.a
+         ->  Gather (actual rows=N loops=N)
+               Output: lprt_a.a
+               Workers Planned: 1
+               Workers Launched: N
+               ->  Parallel Seq Scan on public.lprt_a (actual rows=N loops=N)
+                     Loop Min Rows: N  Max Rows: N  Total Rows: N
+                     Output: lprt_a.a
+                     Worker 0:  actual rows=N loops=N
+(24 rows)
+
+drop table lprt_b;
 delete from lprt_a where a = 1;
 select explain_parallel_append('select avg(ab.a) from ab inner join lprt_a a on ab.a = a.a where a.a in(1, 0, 0)');
                                      explain_parallel_append                                     
@@ -2715,6 +2766,72 @@ order by tbl1.col1, tprt.col1;
  1001 | 1001
 (3 rows)
 
+-- Tests for extra statistics
+explain (analyze, verbose, costs off, summary off, timing off)
+select * from tbl1 inner join tprt on tbl1.col1 > tprt.col1;
+                                   QUERY PLAN                                    
+---------------------------------------------------------------------------------
+ Nested Loop (actual rows=23 loops=1)
+   Output: tbl1.col1, tprt.col1
+   ->  Seq Scan on public.tbl1 (actual rows=5 loops=1)
+         Output: tbl1.col1
+   ->  Append (actual rows=5 loops=5)
+         Loop Min Rows: 2  Max Rows: 6  Total Rows: 23
+         ->  Index Scan using tprt1_idx on public.tprt_1 (actual rows=2 loops=5)
+               Loop Min Rows: 2  Max Rows: 2  Total Rows: 10
+               Output: tprt_1.col1
+               Index Cond: (tprt_1.col1 < tbl1.col1)
+         ->  Index Scan using tprt2_idx on public.tprt_2 (actual rows=3 loops=4)
+               Loop Min Rows: 2  Max Rows: 3  Total Rows: 11
+               Output: tprt_2.col1
+               Index Cond: (tprt_2.col1 < tbl1.col1)
+         ->  Index Scan using tprt3_idx on public.tprt_3 (actual rows=1 loops=2)
+               Loop Min Rows: 1  Max Rows: 1  Total Rows: 2
+               Output: tprt_3.col1
+               Index Cond: (tprt_3.col1 < tbl1.col1)
+         ->  Index Scan using tprt4_idx on public.tprt_4 (never executed)
+               Output: tprt_4.col1
+               Index Cond: (tprt_4.col1 < tbl1.col1)
+         ->  Index Scan using tprt5_idx on public.tprt_5 (never executed)
+               Output: tprt_5.col1
+               Index Cond: (tprt_5.col1 < tbl1.col1)
+         ->  Index Scan using tprt6_idx on public.tprt_6 (never executed)
+               Output: tprt_6.col1
+               Index Cond: (tprt_6.col1 < tbl1.col1)
+(27 rows)
+
+explain (analyze, verbose, costs off, summary off, timing off)
+select * from tbl1 inner join tprt on tbl1.col1 = tprt.col1;
+                                   QUERY PLAN                                    
+---------------------------------------------------------------------------------
+ Nested Loop (actual rows=3 loops=1)
+   Output: tbl1.col1, tprt.col1
+   ->  Seq Scan on public.tbl1 (actual rows=5 loops=1)
+         Output: tbl1.col1
+   ->  Append (actual rows=1 loops=5)
+         Loop Min Rows: 0  Max Rows: 1  Total Rows: 3
+         ->  Index Scan using tprt1_idx on public.tprt_1 (never executed)
+               Output: tprt_1.col1
+               Index Cond: (tprt_1.col1 = tbl1.col1)
+         ->  Index Scan using tprt2_idx on public.tprt_2 (actual rows=1 loops=2)
+               Loop Min Rows: 1  Max Rows: 1  Total Rows: 2
+               Output: tprt_2.col1
+               Index Cond: (tprt_2.col1 = tbl1.col1)
+         ->  Index Scan using tprt3_idx on public.tprt_3 (actual rows=0 loops=3)
+               Loop Min Rows: 0  Max Rows: 1  Total Rows: 1
+               Output: tprt_3.col1
+               Index Cond: (tprt_3.col1 = tbl1.col1)
+         ->  Index Scan using tprt4_idx on public.tprt_4 (never executed)
+               Output: tprt_4.col1
+               Index Cond: (tprt_4.col1 = tbl1.col1)
+         ->  Index Scan using tprt5_idx on public.tprt_5 (never executed)
+               Output: tprt_5.col1
+               Index Cond: (tprt_5.col1 = tbl1.col1)
+         ->  Index Scan using tprt6_idx on public.tprt_6 (never executed)
+               Output: tprt_6.col1
+               Index Cond: (tprt_6.col1 = tbl1.col1)
+(26 rows)
+
 -- Last partition
 delete from tbl1;
 insert into tbl1 values (4400);
diff --git a/src/test/regress/sql/partition_prune.sql b/src/test/regress/sql/partition_prune.sql
index d70bd8610cb..68110e20eeb 100644
--- a/src/test/regress/sql/partition_prune.sql
+++ b/src/test/regress/sql/partition_prune.sql
@@ -469,6 +469,25 @@ begin
 end;
 $$;
 
+create function explain_verbose_parallel_append(text) returns setof text
+language plpgsql as
+$$
+declare
+    ln text;
+begin
+    for ln in
+        execute format('explain (analyze, verbose, costs off, summary off, timing off) %s',
+            $1)
+    loop
+        ln := regexp_replace(ln, 'Workers Launched: \d+', 'Workers Launched: N');
+        ln := regexp_replace(ln, 'actual rows=\d+ loops=\d+', 'actual rows=N loops=N');
+        ln := regexp_replace(ln, 'Loop Min Rows: \d+  Max Rows: \d+  Total Rows: \d+',
+                                 'Loop Min Rows: N  Max Rows: N  Total Rows: N');
+        return next ln;
+    end loop;
+end;
+$$;
+
 prepare ab_q4 (int, int) as
 select avg(a) from ab where a between $1 and $2 and b < 4;
 
@@ -528,6 +547,12 @@ insert into lprt_a values(3),(3);
 select explain_parallel_append('select avg(ab.a) from ab inner join lprt_a a on ab.a = a.a where a.a in(1, 0, 3)');
 select explain_parallel_append('select avg(ab.a) from ab inner join lprt_a a on ab.a = a.a where a.a in(1, 0, 0)');
 
+-- Tests for extra statistics
+create table lprt_b (b int not null);
+insert into lprt_b select generate_series(1,20);
+select explain_verbose_parallel_append('select * from lprt_a join lprt_b on a != b');
+drop table lprt_b;
+
 delete from lprt_a where a = 1;
 
 select explain_parallel_append('select avg(ab.a) from ab inner join lprt_a a on ab.a = a.a where a.a in(1, 0, 0)');
@@ -654,6 +679,13 @@ select tbl1.col1, tprt.col1 from tbl1
 inner join tprt on tbl1.col1 = tprt.col1
 order by tbl1.col1, tprt.col1;
 
+-- Tests for extra statistics
+explain (analyze, verbose, costs off, summary off, timing off)
+select * from tbl1 inner join tprt on tbl1.col1 > tprt.col1;
+
+explain (analyze, verbose, costs off, summary off, timing off)
+select * from tbl1 inner join tprt on tbl1.col1 = tprt.col1;
+
 -- Last partition
 delete from tbl1;
 insert into tbl1 values (4400);
-- 
2.17.1

