<rjuju...@gmail.com> wrote:
You should update the explain_parallel_append() plpgsql function
created in that test file to make sure that both "rows" and the two
new counters are changed to "N". There might be other similar changes
needed.
Thank you for watching this issue. I made the necessary changes in tests
following your advice.
Now, for the changes themselves. For the min/max time, you're
aggregating "totaltime - instr->firsttuple". Why removing the startup
time from the loop execution time? I think this should be kept.
I think it's right remark. I fixed it.
Also, in explain.c you display the counters in the "Nested loop" node,
but this should be done in the inner plan node instead, as this is the
one being looped on. So the condition should probably be "nloops > 1"
rather than testing if it's a NestLoop.
Condition "nloops > 1" is not the same as checking if it's NestLoop.
This condition will lead to printing extra statistics for nodes with
different types of join, not only Nested Loop Join. If this statistic is
useful for other plan nodes, it makes sense to change the condition.
<and...@anarazel.de> wrote:
I'm a bit worried that further increasing the size of struct
Instrumentation will increase the overhead of EXPLAIN ANALYZE further -
in some workloads we spend a fair bit of time in code handling that. It
would be good to try to find a few bad cases, and see what the overhead
is.
Thank you for this comment, I will try to figure it out. Do you have
some examples of large overhead dependent on this struct? I think I need
some sample to know which way to think.
Thank you all for the feedback. I hope the new version of my patch will
be more correct and useful.
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 41317f18374..2132d82fe79 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 fbedb5aaf60..effe8516dba 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 9dc3ecb07d7..996433e9bb1 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 50d2a7e4b97..ba864a57677 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 9b0c418db71..e8ccd903b41 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 1e904a8c5b7..20688561614 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;
