Hi, hackers.
Here is the new version of patch that add printing of min, max and total
statistics for time and rows across all loops to EXPLAIN ANALYSE.
1) Please add VERBOSE to display extra statistics.
2) Format of extra statistics is:
a) FORMAT TEXT
Loop min_time: N max_time: N min_rows: N max_rows: N total_rows: N
Output: ...
b) FORMAT JSON
...
"Actual Total Time": N,
"Loop Min Time": N,
"Loop Max Time": N,
"Actual Rows": N,
"Loop Min Rows": N,
"Loop Max Rows": N,
"Loop Total Rows": N,
"Actual Loops": N,
...
I hope you find this patch useful.
Please don't hesitate to share any thoughts on this topic!
--
Ekaterina Sokolova
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
Author: Ekaterina Sokolova <e.sokol...@postgrespro.ru>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 10644dfac44..9c71819deb2 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1611,6 +1611,11 @@ ExplainNode(PlanState *planstate, List *ancestors,
double startup_ms = 1000.0 * planstate->instrument->startup / nloops;
double total_ms = 1000.0 * planstate->instrument->total / nloops;
double rows = planstate->instrument->ntuples / nloops;
+ double loop_total_rows = planstate->instrument->ntuples;
+ double loop_min_r = planstate->instrument->min_tuples;
+ double loop_max_r = planstate->instrument->max_tuples;
+ double loop_min_t_ms = 1000.0 * planstate->instrument->min_t;
+ double loop_max_t_ms = 1000.0 * planstate->instrument->max_t;
if (es->format == EXPLAIN_FORMAT_TEXT)
{
@@ -1622,6 +1627,19 @@ ExplainNode(PlanState *planstate, List *ancestors,
appendStringInfo(es->str,
" (actual rows=%.0f loops=%.0f)",
rows, nloops);
+ if (nloops > 1 && es->verbose)
+ {
+ appendStringInfo(es->str, "\n");
+ ExplainIndentText(es);
+ if (es->timing)
+ appendStringInfo(es->str,
+ "Loop min_time: %.3f max_time: %.3f min_rows: %.0f max_rows: %.0f total_rows: %.0f",
+ loop_min_t_ms, loop_max_t_ms, loop_min_r, loop_max_r, loop_total_rows);
+ else
+ appendStringInfo(es->str,
+ "Loop min_rows: %.0f max_rows: %.0f total_rows: %.0f",
+ loop_min_r, loop_max_r, loop_total_rows);
+ }
}
else
{
@@ -1631,8 +1649,21 @@ ExplainNode(PlanState *planstate, List *ancestors,
3, es);
ExplainPropertyFloat("Actual Total Time", "ms", total_ms,
3, es);
+ if (nloops > 1 && es->verbose)
+ {
+ ExplainPropertyFloat("Loop Min Time", "s", loop_min_t_ms,
+ 3, es);
+ ExplainPropertyFloat("Loop Max Time", "s", 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);
}
}
@@ -1642,6 +1673,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);
@@ -1668,12 +1700,22 @@ ExplainNode(PlanState *planstate, List *ancestors,
double startup_ms;
double total_ms;
double rows;
+ double loop_min_t_ms;
+ double loop_max_t_ms;
+ double loop_min_r;
+ double loop_max_r;
+ double loop_total_rows;
if (nloops <= 0)
continue;
startup_ms = 1000.0 * instrument->startup / nloops;
total_ms = 1000.0 * instrument->total / nloops;
rows = instrument->ntuples / nloops;
+ loop_min_t_ms = 1000.0 * instrument->min_t;
+ loop_max_t_ms = 1000.0 * instrument->max_t;
+ loop_min_r = instrument->min_tuples;
+ loop_max_r = instrument->max_tuples;
+ loop_total_rows = instrument->ntuples;
ExplainOpenWorker(n, es);
@@ -1688,6 +1730,19 @@ ExplainNode(PlanState *planstate, List *ancestors,
appendStringInfo(es->str,
"actual rows=%.0f loops=%.0f\n",
rows, nloops);
+ if (nloops > 1)
+ {
+ appendStringInfo(es->str, "\n");
+ ExplainIndentText(es);
+ if (es->timing)
+ appendStringInfo(es->str,
+ "Loop min_time: %.3f max_time: %.3f min_rows: %.0f max_rows: %.0f total_rows: %.0f",
+ loop_min_t_ms, loop_max_t_ms, loop_min_r, loop_max_r, loop_total_rows);
+ else
+ appendStringInfo(es->str,
+ "Loop min_rows: %.0f max_rows: %.0f total_rows: %.0f",
+ loop_min_r, loop_max_r, loop_total_rows);
+ }
}
else
{
@@ -1697,8 +1752,21 @@ ExplainNode(PlanState *planstate, List *ancestors,
startup_ms, 3, es);
ExplainPropertyFloat("Actual Total Time", "ms",
total_ms, 3, es);
+ if (nloops > 1)
+ {
+ 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)
+ {
+ 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 2b106d8473c..6588ce2db6a 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -153,7 +153,34 @@ InstrEndLoop(Instrumentation *instr)
instr->startup += instr->firsttuple;
instr->total += totaltime;
+
+ /*
+ * 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->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;
+
instr->ntuples += instr->tuplecount;
+
+ 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 +213,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 2f9905b7c8e..e2ff330b8f1 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -79,7 +79,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 1734dfee8cc..275cdb37672 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -354,8 +354,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, +
@@ -400,7 +405,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..0e1242c089a 100644
--- a/src/test/regress/expected/partition_prune.out
+++ b/src/test/regress/expected/partition_prune.out
@@ -2715,6 +2715,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..d5ba8d6f386 100644
--- a/src/test/regress/sql/partition_prune.sql
+++ b/src/test/regress/sql/partition_prune.sql
@@ -654,6 +654,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);
