Hello Ekaterina,
seems like an interesting and useful improvement. I did a quick review
of the patch - attached is a 0002 patch with a couple minor changes (the
0001 is just your v1 patch, to keep cfbot happy).
1) There's a couple changes to follow project code style (e.g. brackets
after "if" on a separate line, no brackets around single-line blocks,
etc.). I've reverted some unnecessary whitespace changes. Minor stuff.
2) I don't think InstrEndLoop needs to check if min_t == 0 before
initializing it in the first loop. It certainly has to be 0, no? Same
for min_tuples. I also suggest comment explaining that we don't have to
initialize the max values.
3) In ExplainNode, in the part processing per-worker stats, I think some
of the fields are incorrectly referencing planstate->instrument instead
of using the 'instrument' variable from WorkerInstrumentation.
In general, I agree with Andres this might add overhead to explain
analyze, although I doubt it's going to be measurable. But maybe try
doing some measurements for common and worst-cases.
I wonder if we should have another option EXPLAIN option enabling this.
I.e. by default we'd not collect/print this, and users would have to
pass some option to EXPLAIN. Or maybe we could tie this to VERBOSE?
Also, why print this only for nested loop, and not for all nodes with
(nloops > 1)? I see there was some discussion why checking nodeTag is
necessary to identify NL, but that's not my point.
regards
--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
>From 903c203e7e5f298f927ade97ca03a0e129c31e75 Mon Sep 17 00:00:00 2001
From: Tomas Vondra <to...@2ndquadrant.com>
Date: Sat, 31 Oct 2020 01:47:46 +0100
Subject: [PATCH 1/2] extra_statistics_v1
---
src/backend/commands/explain.c | 131 ++++++++++++++----
src/backend/executor/instrument.c | 32 ++++-
src/include/executor/instrument.h | 4 +
src/test/regress/expected/partition_prune.out | 36 ++---
src/test/regress/expected/select_parallel.out | 12 +-
src/test/regress/sql/partition_prune.sql | 2 +
6 files changed, 163 insertions(+), 54 deletions(-)
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 43f9b01e83..72dae57ee2 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1568,29 +1568,64 @@ 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 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 (nodeTag(plan) == T_NestLoop) {
+ if (es->timing)
+ appendStringInfo(es->str,
+ "
(actual time=%.3f..%.3f min_time=%.3f max_time=%.3f min_rows=%.0f rows=%.0f
max_rows=%.0f loops=%.0f)",
+
startup_ms, total_ms, min_t_ms, max_t_ms, min_r, rows, max_r, nloops);
+ else
+ appendStringInfo(es->str,
+ "
(actual min_rows=%.0f rows=%.0f max_rows=%.0f loops=%.0f)",
+ min_r,
rows, max_r, nloops);
+ }
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 (nodeTag(plan) == T_NestLoop) {
+ 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, rows, 0,
es);
+ ExplainPropertyFloat("Max Rows", NULL, 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)
@@ -1599,6 +1634,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);
@@ -1624,39 +1660,78 @@ ExplainNode(PlanState *planstate, List *ancestors,
double nloops = instrument->nloops;
double startup_ms;
double total_ms;
+ double min_t_ms;
+ double max_t_ms;
double rows;
+ double min_r;
+ double max_r;
if (nloops <= 0)
continue;
startup_ms = 1000.0 * instrument->startup / nloops;
total_ms = 1000.0 * instrument->total / nloops;
+ min_t_ms = 1000.0 * planstate->instrument->min_t;
+ max_t_ms = 1000.0 * planstate->instrument->max_t;
rows = instrument->ntuples / nloops;
+ min_r = planstate->instrument->min_tuples;
+ max_r = planstate->instrument->max_tuples;
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 (nodeTag(plan) == T_NestLoop) {
+ if (es->timing)
+ appendStringInfo(es->str,
+
"actual time=%.3f..%.3f min_time=%.3f max_time=%.3f min_rows=%.0f rows=%.0f
max_rows=%.0f loops=%.0f\n",
+
startup_ms, total_ms, min_t_ms, max_t_ms, min_r, rows, max_r, nloops);
+ else
+ appendStringInfo(es->str,
+
"actual min_rows=%.0f rows=%.0f max_rows=%.0f loops=%.0f\n",
+
min_r, rows, max_r, nloops);
+ }
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 (nodeTag(plan) == T_NestLoop) {
+ 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,
rows, 0, es);
+ ExplainPropertyFloat("Max Rows", NULL,
rows, 0, es);
+ ExplainPropertyFloat("Actual Loops",
NULL, nloops, 0, es);
+ }
+ else
{
- 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("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 fbedb5aaf6..b0748721c3 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -118,9 +118,8 @@ InstrStopNode(Instrumentation *instr, double nTuples)
/* Finish a run cycle for a plan node */
void
-InstrEndLoop(Instrumentation *instr)
-{
- double totaltime;
+InstrEndLoop(Instrumentation *instr) {
+ double totaltime;
/* Skip if nothing has happened, or already shut down */
if (!instr->running)
@@ -134,7 +133,34 @@ InstrEndLoop(Instrumentation *instr)
instr->startup += instr->firsttuple;
instr->total += totaltime;
+ if (instr->nloops == 0) /* this is
first loop */
+ {
+ if (instr->min_t == 0)
+ {
+ instr->min_t = totaltime; /* init min_t */
+ }
+ if (instr->min_tuples == 0)
+ {
+ instr->min_tuples = instr->tuplecount; /* init
min_tuples */
+ }
+ }
+ 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) */
diff --git a/src/include/executor/instrument.h
b/src/include/executor/instrument.h
index 9dc3ecb07d..dbfac349cc 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -66,7 +66,11 @@ 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/partition_prune.out
b/src/test/regress/expected/partition_prune.out
index 50d2a7e4b9..ba864a5767 100644
--- a/src/test/regress/expected/partition_prune.out
+++ b/src/test/regress/expected/partition_prune.out
@@ -1929,6 +1929,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, 'actual min_rows=\d+ rows=\d+ max_rows=\d+
loops=\d+',
+ 'actual min_rows=N rows=N max_rows=N loops=N');
ln := regexp_replace(ln, 'Rows Removed by Filter: \d+', 'Rows Removed
by Filter: N');
return next ln;
end loop;
@@ -2065,7 +2067,7 @@ select explain_parallel_append('select avg(ab.a) from ab
inner join lprt_a a on
Workers Planned: 1
Workers Launched: N
-> Partial Aggregate (actual rows=N loops=N)
- -> Nested Loop (actual rows=N loops=N)
+ -> Nested Loop (actual min_rows=N rows=N max_rows=N loops=N)
-> Parallel Seq Scan on lprt_a a (actual rows=N loops=N)
Filter: (a = ANY ('{0,0,1}'::integer[]))
-> Append (actual rows=N loops=N)
@@ -2099,7 +2101,7 @@ select explain_parallel_append('select avg(ab.a) from ab
inner join lprt_a a on
Workers Planned: 1
Workers Launched: N
-> Partial Aggregate (actual rows=N loops=N)
- -> Nested Loop (actual rows=N loops=N)
+ -> Nested Loop (actual min_rows=N rows=N max_rows=N loops=N)
-> Parallel Seq Scan on lprt_a a (actual rows=N loops=N)
Filter: (a = ANY ('{0,0,1}'::integer[]))
-> Append (actual rows=N loops=N)
@@ -2132,7 +2134,7 @@ select explain_parallel_append('select avg(ab.a) from ab
inner join lprt_a a on
Workers Planned: 1
Workers Launched: N
-> Partial Aggregate (actual rows=N loops=N)
- -> Nested Loop (actual rows=N loops=N)
+ -> Nested Loop (actual min_rows=N rows=N max_rows=N loops=N)
-> Parallel Seq Scan on lprt_a a (actual rows=N loops=N)
Filter: (a = ANY ('{1,0,3}'::integer[]))
-> Append (actual rows=N loops=N)
@@ -2164,7 +2166,7 @@ select explain_parallel_append('select avg(ab.a) from ab
inner join lprt_a a on
Workers Planned: 1
Workers Launched: N
-> Partial Aggregate (actual rows=N loops=N)
- -> Nested Loop (actual rows=N loops=N)
+ -> Nested Loop (actual min_rows=N rows=N max_rows=N loops=N)
-> Parallel Seq Scan on lprt_a a (actual rows=N loops=N)
Filter: (a = ANY ('{1,0,0}'::integer[]))
Rows Removed by Filter: N
@@ -2198,7 +2200,7 @@ select explain_parallel_append('select avg(ab.a) from ab
inner join lprt_a a on
Workers Planned: 1
Workers Launched: N
-> Partial Aggregate (actual rows=N loops=N)
- -> Nested Loop (actual rows=N loops=N)
+ -> Nested Loop (actual min_rows=N rows=N max_rows=N loops=N)
-> Parallel Seq Scan on lprt_a a (actual rows=N loops=N)
Filter: (a = ANY ('{1,0,0}'::integer[]))
Rows Removed by Filter: N
@@ -2441,7 +2443,7 @@ update ab_a1 set b = 3 from ab where ab.a = 1 and ab.a =
ab_a1.a;
Update on ab_a1_b1 ab_a1_1
Update on ab_a1_b2 ab_a1_2
Update on ab_a1_b3 ab_a1_3
- -> Nested Loop (actual rows=0 loops=1)
+ -> Nested Loop (actual min_rows=0 rows=0 max_rows=0 loops=1)
-> Append (actual rows=1 loops=1)
-> Bitmap Heap Scan on ab_a1_b1 ab_1 (actual rows=0 loops=1)
Recheck Cond: (a = 1)
@@ -2461,7 +2463,7 @@ update ab_a1 set b = 3 from ab where ab.a = 1 and ab.a =
ab_a1.a;
Recheck Cond: (a = 1)
-> Bitmap Index Scan on ab_a1_b1_a_idx (actual rows=0
loops=1)
Index Cond: (a = 1)
- -> Nested Loop (actual rows=1 loops=1)
+ -> Nested Loop (actual min_rows=1 rows=1 max_rows=1 loops=1)
-> Append (actual rows=1 loops=1)
-> Bitmap Heap Scan on ab_a1_b1 ab_1 (actual rows=0 loops=1)
Recheck Cond: (a = 1)
@@ -2482,7 +2484,7 @@ update ab_a1 set b = 3 from ab where ab.a = 1 and ab.a =
ab_a1.a;
Heap Blocks: exact=1
-> Bitmap Index Scan on ab_a1_b2_a_idx (actual rows=1
loops=1)
Index Cond: (a = 1)
- -> Nested Loop (actual rows=0 loops=1)
+ -> Nested Loop (actual min_rows=0 rows=0 max_rows=0 loops=1)
-> Append (actual rows=1 loops=1)
-> Bitmap Heap Scan on ab_a1_b1 ab_1 (actual rows=0 loops=1)
Recheck Cond: (a = 1)
@@ -2523,7 +2525,7 @@ update ab_a1 set b = 3 from ab_a2 where ab_a2.b = (select
1);
Update on ab_a1_b3 ab_a1_3
InitPlan 1 (returns $0)
-> Result (actual rows=1 loops=1)
- -> Nested Loop (actual rows=1 loops=1)
+ -> Nested Loop (actual min_rows=1 rows=1 max_rows=1 loops=1)
-> Seq Scan on ab_a1_b1 ab_a1_1 (actual rows=1 loops=1)
-> Materialize (actual rows=1 loops=1)
-> Append (actual rows=1 loops=1)
@@ -2533,7 +2535,7 @@ update ab_a1 set b = 3 from ab_a2 where ab_a2.b = (select
1);
Filter: (b = $0)
-> Seq Scan on ab_a2_b3 ab_a2_3 (never executed)
Filter: (b = $0)
- -> Nested Loop (actual rows=1 loops=1)
+ -> Nested Loop (actual min_rows=1 rows=1 max_rows=1 loops=1)
-> Seq Scan on ab_a1_b2 ab_a1_2 (actual rows=1 loops=1)
-> Materialize (actual rows=1 loops=1)
-> Append (actual rows=1 loops=1)
@@ -2543,7 +2545,7 @@ update ab_a1 set b = 3 from ab_a2 where ab_a2.b = (select
1);
Filter: (b = $0)
-> Seq Scan on ab_a2_b3 ab_a2_3 (never executed)
Filter: (b = $0)
- -> Nested Loop (actual rows=1 loops=1)
+ -> Nested Loop (actual min_rows=1 rows=1 max_rows=1 loops=1)
-> Seq Scan on ab_a1_b3 ab_a1_3 (actual rows=1 loops=1)
-> Materialize (actual rows=1 loops=1)
-> Append (actual rows=1 loops=1)
@@ -2589,7 +2591,7 @@ explain (analyze, costs off, summary off, timing off)
select * from tbl1 join tprt on tbl1.col1 > tprt.col1;
QUERY PLAN
--------------------------------------------------------------------------
- Nested Loop (actual rows=6 loops=1)
+ Nested Loop (actual min_rows=6 rows=6 max_rows=6 loops=1)
-> Seq Scan on tbl1 (actual rows=2 loops=1)
-> Append (actual rows=3 loops=2)
-> Index Scan using tprt1_idx on tprt_1 (actual rows=2 loops=2)
@@ -2610,7 +2612,7 @@ explain (analyze, costs off, summary off, timing off)
select * from tbl1 join tprt on tbl1.col1 = tprt.col1;
QUERY PLAN
--------------------------------------------------------------------------
- Nested Loop (actual rows=2 loops=1)
+ Nested Loop (actual min_rows=2 rows=2 max_rows=2 loops=1)
-> Seq Scan on tbl1 (actual rows=2 loops=1)
-> Append (actual rows=1 loops=2)
-> Index Scan using tprt1_idx on tprt_1 (never executed)
@@ -2655,7 +2657,7 @@ explain (analyze, 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)
+ Nested Loop (actual min_rows=23 rows=23 max_rows=23 loops=1)
-> Seq Scan on tbl1 (actual rows=5 loops=1)
-> Append (actual rows=5 loops=5)
-> Index Scan using tprt1_idx on tprt_1 (actual rows=2 loops=5)
@@ -2676,7 +2678,7 @@ explain (analyze, 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)
+ Nested Loop (actual min_rows=3 rows=3 max_rows=3 loops=1)
-> Seq Scan on tbl1 (actual rows=5 loops=1)
-> Append (actual rows=1 loops=5)
-> Index Scan using tprt1_idx on tprt_1 (never executed)
@@ -2740,7 +2742,7 @@ explain (analyze, costs off, summary off, timing off)
select * from tbl1 join tprt on tbl1.col1 < tprt.col1;
QUERY PLAN
--------------------------------------------------------------------------
- Nested Loop (actual rows=1 loops=1)
+ Nested Loop (actual min_rows=1 rows=1 max_rows=1 loops=1)
-> Seq Scan on tbl1 (actual rows=1 loops=1)
-> Append (actual rows=1 loops=1)
-> Index Scan using tprt1_idx on tprt_1 (never executed)
@@ -2772,7 +2774,7 @@ explain (analyze, costs off, summary off, timing off)
select * from tbl1 join tprt on tbl1.col1 = tprt.col1;
QUERY PLAN
-------------------------------------------------------------------
- Nested Loop (actual rows=0 loops=1)
+ Nested Loop (actual min_rows=0 rows=0 max_rows=0 loops=1)
-> Seq Scan on tbl1 (actual rows=1 loops=1)
-> Append (actual rows=0 loops=1)
-> Index Scan using tprt1_idx on tprt_1 (never executed)
diff --git a/src/test/regress/expected/select_parallel.out
b/src/test/regress/expected/select_parallel.out
index 9b0c418db7..e8ccd903b4 100644
--- a/src/test/regress/expected/select_parallel.out
+++ b/src/test/regress/expected/select_parallel.out
@@ -547,10 +547,10 @@ alter table tenk2 set (parallel_workers = 0);
explain (analyze, timing off, summary off, costs off)
select count(*) from tenk1, tenk2 where tenk1.hundred > 1
and tenk2.thousand=0;
- QUERY PLAN
---------------------------------------------------------------------------
+ QUERY PLAN
+-----------------------------------------------------------------------------
Aggregate (actual rows=1 loops=1)
- -> Nested Loop (actual rows=98000 loops=1)
+ -> Nested Loop (actual min_rows=98000 rows=98000 max_rows=98000 loops=1)
-> Seq Scan on tenk2 (actual rows=10 loops=1)
Filter: (thousand = 0)
Rows Removed by Filter: 9990
@@ -581,9 +581,9 @@ begin
end;
$$;
select * from explain_parallel_sort_stats();
- explain_parallel_sort_stats
---------------------------------------------------------------------------
- Nested Loop Left Join (actual rows=30000 loops=1)
+ explain_parallel_sort_stats
+---------------------------------------------------------------------------------
+ Nested Loop Left Join (actual min_rows=30000 rows=30000 max_rows=30000
loops=1)
-> Values Scan on "*VALUES*" (actual rows=3 loops=1)
-> Gather Merge (actual rows=10000 loops=3)
Workers Planned: 4
diff --git a/src/test/regress/sql/partition_prune.sql
b/src/test/regress/sql/partition_prune.sql
index 1e904a8c5b..2068856161 100644
--- a/src/test/regress/sql/partition_prune.sql
+++ b/src/test/regress/sql/partition_prune.sql
@@ -452,6 +452,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, 'actual min_rows=\d+ rows=\d+ max_rows=\d+
loops=\d+',
+ 'actual min_rows=N rows=N max_rows=N loops=N');
ln := regexp_replace(ln, 'Rows Removed by Filter: \d+', 'Rows Removed
by Filter: N');
return next ln;
end loop;
--
2.26.2
>From 28f3bdd55cd8784d0af4d53a4e88845782e2eaa0 Mon Sep 17 00:00:00 2001
From: Tomas Vondra <to...@2ndquadrant.com>
Date: Sat, 31 Oct 2020 02:07:20 +0100
Subject: [PATCH 2/2] minor tweaks
---
src/backend/commands/explain.c | 32 +++++++++++++++----------
src/backend/executor/instrument.c | 39 ++++++++++++++++---------------
2 files changed, 40 insertions(+), 31 deletions(-)
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 72dae57ee2..fa8deac55a 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1575,7 +1575,8 @@ ExplainNode(PlanState *planstate, List *ancestors,
if (es->format == EXPLAIN_FORMAT_TEXT)
{
- if (nodeTag(plan) == T_NestLoop) {
+ if (nodeTag(plan) == T_NestLoop)
+ {
if (es->timing)
appendStringInfo(es->str,
"
(actual time=%.3f..%.3f min_time=%.3f max_time=%.3f min_rows=%.0f rows=%.0f
max_rows=%.0f loops=%.0f)",
@@ -1599,8 +1600,10 @@ ExplainNode(PlanState *planstate, List *ancestors,
}
else
{
- if (nodeTag(plan) == T_NestLoop) {
- if (es->timing) {
+ if (nodeTag(plan) == T_NestLoop)
+ {
+ if (es->timing)
+ {
ExplainPropertyFloat("Actual Startup
Time", "s", startup_ms,
3, es);
ExplainPropertyFloat("Actual Total
Time", "s", total_ms,
@@ -1617,7 +1620,8 @@ ExplainNode(PlanState *planstate, List *ancestors,
}
else
{
- if (es->timing) {
+ if (es->timing)
+ {
ExplainPropertyFloat("Actual Startup
Time", "s", startup_ms,
3, es);
ExplainPropertyFloat("Actual Total
Time", "s", total_ms,
@@ -1670,18 +1674,19 @@ ExplainNode(PlanState *planstate, List *ancestors,
continue;
startup_ms = 1000.0 * instrument->startup / nloops;
total_ms = 1000.0 * instrument->total / nloops;
- min_t_ms = 1000.0 * planstate->instrument->min_t;
- max_t_ms = 1000.0 * planstate->instrument->max_t;
+ min_t_ms = 1000.0 * instrument->min_t;
+ max_t_ms = 1000.0 * instrument->max_t;
rows = instrument->ntuples / nloops;
- min_r = planstate->instrument->min_tuples;
- max_r = planstate->instrument->max_tuples;
+ min_r = instrument->min_tuples;
+ max_r = instrument->max_tuples;
ExplainOpenWorker(n, es);
if (es->format == EXPLAIN_FORMAT_TEXT)
{
ExplainIndentText(es);
- if (nodeTag(plan) == T_NestLoop) {
+ if (nodeTag(plan) == T_NestLoop)
+ {
if (es->timing)
appendStringInfo(es->str,
"actual time=%.3f..%.3f min_time=%.3f max_time=%.3f min_rows=%.0f rows=%.0f
max_rows=%.0f loops=%.0f\n",
@@ -1705,8 +1710,10 @@ ExplainNode(PlanState *planstate, List *ancestors,
}
else
{
- if (nodeTag(plan) == T_NestLoop) {
- if (es->timing) {
+ if (nodeTag(plan) == T_NestLoop)
+ {
+ if (es->timing)
+ {
ExplainPropertyFloat("Actual
Startup Time", "ms",
startup_ms, 3, es);
ExplainPropertyFloat("Actual
Total Time", "ms",
@@ -1723,7 +1730,8 @@ ExplainNode(PlanState *planstate, List *ancestors,
}
else
{
- if (es->timing) {
+ if (es->timing)
+ {
ExplainPropertyFloat("Actual
Startup Time", "ms",
startup_ms, 3, es);
ExplainPropertyFloat("Actual
Total Time", "ms",
diff --git a/src/backend/executor/instrument.c
b/src/backend/executor/instrument.c
index b0748721c3..0198bb3a5a 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -118,8 +118,9 @@ InstrStopNode(Instrumentation *instr, double nTuples)
/* Finish a run cycle for a plan node */
void
-InstrEndLoop(Instrumentation *instr) {
- double totaltime;
+InstrEndLoop(Instrumentation *instr)
+{
+ double totaltime;
/* Skip if nothing has happened, or already shut down */
if (!instr->running)
@@ -133,34 +134,34 @@ InstrEndLoop(Instrumentation *instr) {
instr->startup += instr->firsttuple;
instr->total += totaltime;
- if (instr->nloops == 0) /* this is
first loop */
+
+ /*
+ * 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)
{
- if (instr->min_t == 0)
- {
- instr->min_t = totaltime; /* init min_t */
- }
- if (instr->min_tuples == 0)
- {
- instr->min_tuples = instr->tuplecount; /* init
min_tuples */
- }
+ 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) */
--
2.26.2
