Thank you all for your feedback and reforms.
I attach a new version of the patch with the some changes and fixes.
Here's a list of the major changes:
1) New format of extra statistics. This is now contained in a line
separate from the main statistics.
Julien Rouhaud писал 2021-02-01 08:28:
On Thu, Jan 28, 2021 at 8:38 PM Yugo NAGATA <[email protected]>
wrote:
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.163 min_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
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) Correction of the case of parallel scan
In parallel scan, the extra statistics are not reported correctly.
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.
3) Adding extra statistics about total number of rows (total rows).
There were many wishes for this here.
Please don't hesitate to share any thoughts on this topic.
--
Ekaterina Sokolova
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index afc45429ba4..723eccca013 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1589,29 +1589,82 @@ 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 total_rows = planstate->instrument->ntuples;
+ double min_r = planstate->instrument->min_tuples;
+ double max_r = planstate->instrument->max_tuples;
+ double min_t_ms = 1000.0 * planstate->instrument->min_t;
+ double max_t_ms = 1000.0 * planstate->instrument->max_t;
if (es->format == EXPLAIN_FORMAT_TEXT)
{
- if (es->timing)
- appendStringInfo(es->str,
- " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
- startup_ms, total_ms, rows, nloops);
+ if (nloops > 1 && es->verbose)
+ {
+ if (es->timing)
+ {
+ appendStringInfo(es->str,
+ " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)\n",
+ startup_ms, total_ms, rows, nloops);
+ ExplainIndentText(es);
+ appendStringInfo(es->str,
+ "Loop: min_time=%.3f max_time=%.3f min_rows=%.0f max_rows=%.0f total_rows=%.0f",
+ min_t_ms, max_t_ms, min_r, max_r, total_rows);
+ }
+ else
+ {
+ appendStringInfo(es->str,
+ " (actual rows=%.0f loops=%.0f)\n",
+ rows, nloops);
+ ExplainIndentText(es);
+ appendStringInfo(es->str,
+ "Loop: min_rows=%.0f max_rows=%.0f total_rows=%.0f",
+ min_r, max_r, total_rows);
+ }
+ }
else
- appendStringInfo(es->str,
- " (actual rows=%.0f loops=%.0f)",
- rows, nloops);
+ {
+ if (es->timing)
+ appendStringInfo(es->str,
+ " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
+ startup_ms, total_ms, rows, nloops);
+ else
+ appendStringInfo(es->str,
+ " (actual rows=%.0f loops=%.0f)",
+ rows, nloops);
+ }
}
else
{
- if (es->timing)
+ if (nloops > 1 && es->verbose)
+ {
+ if (es->timing)
+ {
+ ExplainPropertyFloat("Actual Startup Time", "s", startup_ms,
+ 3, es);
+ ExplainPropertyFloat("Actual Total Time", "s", total_ms,
+ 3, es);
+ ExplainPropertyFloat("Min Time", "s", min_t_ms,
+ 3, es);
+ ExplainPropertyFloat("Max Time", "s", max_t_ms,
+ 3, es);
+ }
+ ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es);
+ ExplainPropertyFloat("Min Rows", NULL, min_r, 0, es);
+ ExplainPropertyFloat("Max Rows", NULL, max_r, 0, es);
+ ExplainPropertyFloat("Total Rows", NULL, total_rows, 0, es);
+ ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es);
+ }
+ else
{
- ExplainPropertyFloat("Actual Startup Time", "s", startup_ms,
- 3, es);
- ExplainPropertyFloat("Actual Total Time", "s", total_ms,
- 3, es);
+ if (es->timing)
+ {
+ ExplainPropertyFloat("Actual Startup Time", "s", startup_ms,
+ 3, es);
+ ExplainPropertyFloat("Actual Total Time", "s", total_ms,
+ 3, es);
+ }
+ ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es);
+ ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es);
}
- ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es);
- ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es);
}
}
else if (es->analyze)
@@ -1620,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);
@@ -1646,38 +1700,96 @@ ExplainNode(PlanState *planstate, List *ancestors,
double startup_ms;
double total_ms;
double rows;
+ double min_t_ms;
+ double max_t_ms;
+ double min_r;
+ double max_r;
+ double total_rows;
if (nloops <= 0)
continue;
startup_ms = 1000.0 * instrument->startup / nloops;
total_ms = 1000.0 * instrument->total / nloops;
rows = instrument->ntuples / nloops;
+ min_t_ms = 1000.0 * instrument->min_t;
+ max_t_ms = 1000.0 * instrument->max_t;
+ min_r = instrument->min_tuples;
+ max_r = instrument->max_tuples;
+ total_rows = instrument->ntuples;
ExplainOpenWorker(n, es);
if (es->format == EXPLAIN_FORMAT_TEXT)
{
ExplainIndentText(es);
- if (es->timing)
- appendStringInfo(es->str,
- "actual time=%.3f..%.3f rows=%.0f loops=%.0f\n",
- startup_ms, total_ms, rows, nloops);
+ if (nloops > 1)
+ {
+ if (es->timing)
+ {
+ appendStringInfo(es->str,
+ "actual time=%.3f..%.3f rows=%.0f loops=%.0f\n",
+ startup_ms, total_ms, rows, nloops);
+ ExplainIndentText(es);
+ appendStringInfo(es->str,
+ "Loop: min_time=%.3f max_time=%.3f min_rows=%.0f max_rows=%.0f total_rows=%.0f",
+ min_t_ms, max_t_ms, min_r, max_r, total_rows);
+ }
+ else
+ {
+ appendStringInfo(es->str,
+ "actual rows=%.0f loops=%.0f\n",
+ rows, nloops);
+ ExplainIndentText(es);
+ appendStringInfo(es->str,
+ "Loop: min_rows=%.0f max_rows=%.0f total_rows=%.0f",
+ min_r, max_r, total_rows);
+ }
+ }
else
- appendStringInfo(es->str,
- "actual rows=%.0f loops=%.0f\n",
- rows, nloops);
+ {
+ if (es->timing)
+ appendStringInfo(es->str,
+ "actual time=%.3f..%.3f rows=%.0f loops=%.0f\n",
+ startup_ms, total_ms, rows, nloops);
+ else
+ appendStringInfo(es->str,
+ "actual rows=%.0f loops=%.0f\n",
+ rows, nloops);
+ }
}
else
{
- if (es->timing)
+ if (nloops > 1)
{
- ExplainPropertyFloat("Actual Startup Time", "ms",
- startup_ms, 3, es);
- ExplainPropertyFloat("Actual Total Time", "ms",
- total_ms, 3, es);
+ if (es->timing)
+ {
+ ExplainPropertyFloat("Actual Startup Time", "ms",
+ startup_ms, 3, es);
+ ExplainPropertyFloat("Actual Total Time", "ms",
+ total_ms, 3, es);
+ ExplainPropertyFloat("Min Time", "ms",
+ min_t_ms, 3, es);
+ ExplainPropertyFloat("Max Time", "ms",
+ max_t_ms, 3, es);
+ }
+ ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es);
+ ExplainPropertyFloat("Min Rows", NULL, min_r, 0, es);
+ ExplainPropertyFloat("Max Rows", NULL, max_r, 0, es);
+ ExplainPropertyFloat("Total Rows", NULL, total_rows, 0, es);
+ ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es);
+ }
+ else
+ {
+ if (es->timing)
+ {
+ ExplainPropertyFloat("Actual Startup Time", "ms",
+ startup_ms, 3, es);
+ ExplainPropertyFloat("Actual Total Time", "ms",
+ total_ms, 3, es);
+ }
+ ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es);
+ ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es);
}
- ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es);
- ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es);
}
ExplainCloseWorker(n, 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 dc7ab2ce8bf..0569662ca50 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -341,10 +341,15 @@ select jsonb_pretty(
"string4" +
], +
"Schema": "public", +
+ "Max Rows": 0, +
+ "Max Time": 0.0, +
+ "Min Rows": 0, +
+ "Min Time": 0.0, +
"Node Type": "Seq Scan", +
"Plan Rows": 0, +
"Plan Width": 0, +
"Total Cost": 0.0, +
+ "Total Rows": 0, +
"Actual Rows": 0, +
"Actual Loops": 0, +
"Startup Cost": 0.0, +
@@ -383,6 +388,10 @@ select jsonb_pretty(
"stringu2", +
"string4" +
], +
+ "Max Rows": 0, +
+ "Max Time": 0.0, +
+ "Min Rows": 0, +
+ "Min Time": 0.0, +
"Sort Key": [ +
"tenk1.tenthous" +
], +
@@ -390,6 +399,7 @@ select jsonb_pretty(
"Plan Rows": 0, +
"Plan Width": 0, +
"Total Cost": 0.0, +
+ "Total Rows": 0, +
"Actual Rows": 0, +
"Actual Loops": 0, +
"Startup Cost": 0.0, +
diff --git a/src/test/regress/expected/partition_prune.out b/src/test/regress/expected/partition_prune.out
index bde29e38a94..bb979432405 100644
--- a/src/test/regress/expected/partition_prune.out
+++ b/src/test/regress/expected/partition_prune.out
@@ -1957,6 +1957,8 @@ begin
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');
ln := regexp_replace(ln, 'Rows Removed by Filter: \d+', 'Rows Removed by Filter: N');
return next ln;
end loop;
@@ -2761,6 +2763,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 6ccb52ad1d6..6224e3a4964 100644
--- a/src/test/regress/sql/partition_prune.sql
+++ b/src/test/regress/sql/partition_prune.sql
@@ -463,6 +463,8 @@ begin
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');
ln := regexp_replace(ln, 'Rows Removed by Filter: \d+', 'Rows Removed by Filter: N');
return next ln;
end loop;
@@ -652,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);
