From 148b0792b8eed1527ee3266e7e627b3c75effb9e Mon Sep 17 00:00:00 2001 From: Ekaterina Sokolova Date: Thu, 12 Nov 2020 22:06:41 +0300 Subject: [PATCH] extra_statistics_v2 --- src/backend/commands/explain.c | 141 ++++++++++++++---- src/backend/executor/instrument.c | 27 ++++ src/include/executor/instrument.h | 6 + src/test/regress/expected/explain.out | 8 + src/test/regress/expected/partition_prune.out | 2 + src/test/regress/expected/timetz.out | 8 +- src/test/regress/sql/partition_prune.sql | 2 + 7 files changed, 161 insertions(+), 33 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 41317f18374..b525b12b1d6 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -1568,29 +1568,68 @@ 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 (nloops > 1 && es->verbose) + { + 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 (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, 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 +1638,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 +1664,82 @@ 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 * instrument->min_t; + max_t_ms = 1000.0 * instrument->max_t; rows = instrument->ntuples / nloops; + min_r = instrument->min_tuples; + max_r = 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 (nloops > 1) + { + 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 (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, rows, 0, es); + ExplainPropertyFloat("Max Rows", NULL, 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); @@ -3094,7 +3177,7 @@ show_hashagg_info(AggState *aggstate, ExplainState *es) if (aggstate->hash_batches_used > 1) { appendStringInfo(es->str, " Disk Usage: " UINT64_FORMAT "kB", - aggstate->hash_disk_used); + aggstate->hash_disk_used); } } diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index fbedb5aaf60..db1be682e1c 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) */ diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 9dc3ecb07d7..a458b566e0d 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..aa3955ad1fc 100644 --- a/src/test/regress/expected/explain.out +++ b/src/test/regress/expected/explain.out @@ -341,6 +341,10 @@ 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, + @@ -383,6 +387,10 @@ select jsonb_pretty( "stringu2", + "string4" + ], + + "Max Rows": 0, + + "Max Time": 0.0, + + "Min Rows": 0, + + "Min Time": 0.0, + "Sort Key": [ + "tenk1.tenthous" + ], + diff --git a/src/test/regress/expected/partition_prune.out b/src/test/regress/expected/partition_prune.out index 50d2a7e4b97..2d8ad48ff09 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; diff --git a/src/test/regress/expected/timetz.out b/src/test/regress/expected/timetz.out index 038bb5fa094..5294179aa45 100644 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; -- 2.26.0