Thank you for working on this issue. Your comments helped me make this
patch more correct.
Lines with "colon" format shouldn't use equal signs, and should use two
spaces
between fields.
Done. Now extra line looks like "Loop min_rows: %.0f max_rows: %.0f
total_rows: %.0f" or "Loop min_time: %.3f max_time: %.3f min_rows:
%.0f max_rows: %.0f total_rows: %.0f".
Since this is now on a separate line, the "if (nloops > 1 &&
es->verbose)"
can be after the existing "if (es->timing)", and shouldn't need its own
"if (es->timing)". It should conditionally add a separate line, rather
than
duplicating the "(actual.*" line.
- if (es->timing)
+ if (nloops > 1 && es->verbose)
New version of patch contains this correction. It helped make the patch
shorter.
In non-text mode, think you should not check "nloops > 1". Rather,
print the
field as 0.
The fields will not be zeros. New line will almost repeat the line with
main sttistics.
I think the labels in non-text format should say "Loop Min Time" or
similar.
And these variables should have a loop_ prefix like loop_min_t ?
There are good ideas. I changed it.
I apply new version of this patch. I hope it got better.
Please don't hesitate to share any thoughts on this topic.
--
Ekaterina Sokolova
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
From: "Ekaterina Sokolova" <e.sokol...@postgrespro.ru>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index b62a76e7e5a..bf8c37baefd 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1615,6 +1615,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)
{
@@ -1626,6 +1631,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
{
@@ -1635,8 +1653,21 @@ ExplainNode(PlanState *planstate, List *ancestors,
3, es);
ExplainPropertyFloat("Actual Total Time", "s", 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);
}
}
@@ -1646,6 +1677,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);
@@ -1672,12 +1704,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);
@@ -1692,6 +1734,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
{
@@ -1701,8 +1756,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 237e13361b5..d2c3e678882 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -134,7 +134,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) */
@@ -167,6 +194,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 aa8eceda5f4..93ba7c83461 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -66,7 +66,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 cda28098baa..b51659d57f3 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -351,8 +351,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, +
@@ -397,7 +402,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 1a7149bfd57..8d87af92593 100644
--- a/src/test/regress/expected/partition_prune.out
+++ b/src/test/regress/expected/partition_prune.out
@@ -1961,6 +1961,10 @@ begin
ln := regexp_replace(ln, 'Hits: \d+', 'Hits: N');
ln := regexp_replace(ln, 'Misses: \d+', 'Misses: N');
ln := regexp_replace(ln, 'Memory Usage: \d+', 'Memory Usage: N');
+ ln := regexp_replace(ln, 'Loop min_time: \d+ max_time: \d+ min_rows: \d+ max_rows: \d+ total_rows: \d+',
+ 'Loop min_time: N max_time: N min_rows: N max_rows: N total_rows: 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;
@@ -2718,6 +2722,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 247264f93b7..c1268e23f27 100644
--- a/src/test/regress/sql/partition_prune.sql
+++ b/src/test/regress/sql/partition_prune.sql
@@ -467,6 +467,10 @@ begin
ln := regexp_replace(ln, 'Hits: \d+', 'Hits: N');
ln := regexp_replace(ln, 'Misses: \d+', 'Misses: N');
ln := regexp_replace(ln, 'Memory Usage: \d+', 'Memory Usage: N');
+ ln := regexp_replace(ln, 'Loop min_time: \d+ max_time: \d+ min_rows: \d+ max_rows: \d+ total_rows: \d+',
+ 'Loop min_time: N max_time: N min_rows: N max_rows: N total_rows: 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;
@@ -657,6 +661,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);
