0002-extra_statistics_v8.patch

From: Ekaterina Sokolova <e.sokolova@postgrespro.ru>
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, Greg Stark.

---
 src/backend/commands/explain.c                |  40 +++++++
 src/backend/executor/instrument.c             |  40 ++++++-
 src/include/executor/instrument.h             |  10 ++
 src/test/regress/expected/explain.out         |  10 ++
 src/test/regress/expected/partition_prune.out | 105 ++++++++++++++++++
 src/test/regress/sql/partition_prune.sql      |  34 ++++++
 6 files changed, 238 insertions(+), 1 deletion(-)

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index bd785c6741d..04e66a67cdb 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -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);
@@ -4051,6 +4055,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)
 	{
@@ -4070,6 +4079,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
 	{
@@ -4079,8 +4103,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 ceff4727d4a..e64ae77f005 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,37 @@ 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;
+		}
+		else
+		{
+			if (instr->min_t > totaltime)
+				instr->min_t = totaltime;
+
+			if (instr->min_tuples > instr->tuplecount)
+				instr->min_tuples = instr->tuplecount;
+		}
+
+		if (instr->max_t < totaltime)
+			instr->max_t = totaltime;
+
+		if (instr->max_tuples < instr->tuplecount)
+			instr->max_tuples = instr->tuplecount;
+	}
+
 	instr->nloops += 1;
 
 	/* Reset for next cycle (if any) */
@@ -186,6 +220,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 2945cce3a97..1d7a5f9c177 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -60,6 +60,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;
 
@@ -69,6 +71,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 */
@@ -81,7 +85,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 48620edbc2b..957771be2ba 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -369,8 +369,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,      +
@@ -415,7 +420,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..d8afab5025d 100644
--- a/src/test/regress/expected/partition_prune.out
+++ b/src/test/regress/expected/partition_prune.out
@@ -1962,6 +1962,23 @@ 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, '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,7 +2235,29 @@ 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
+set parallel_leader_participation = off;
+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
+   ->  Seq Scan on public.lprt_b (actual rows=N loops=N)
+         Output: lprt_b.b
+   ->  Materialize (actual rows=N loops=N)
+         Loop Min Rows: N  Max Rows: N  Total Rows: N
+         Output: lprt_a.a
+         ->  Seq Scan on public.lprt_a (actual rows=N loops=N)
+               Output: lprt_a.a
+(11 rows)
+
+drop table lprt_b;
 delete from lprt_a where a = 1;
+reset parallel_leader_participation;
 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 +2754,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..2f7927c7ec1 100644
--- a/src/test/regress/sql/partition_prune.sql
+++ b/src/test/regress/sql/partition_prune.sql
@@ -469,6 +469,24 @@ 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, '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,8 +546,17 @@ 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
+set parallel_leader_participation = off;
+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;
 
+reset parallel_leader_participation;
+
 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)');
 
 reset enable_hashjoin;
@@ -654,6 +681,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.30.1 (Apple Git-130)