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