From: "Ekaterina Sokolova" 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;