Hi, hackers.
I apply the new version of patch.
Justin Pryzby <pry...@telsasoft.com> wrote:
I'm curious to hear what you and others think of the refactoring.
Thank you so much. With your changes, the patch has become more
understandable and readable.
It'd be nice if there's a good way to add a test case for verbose
output
involving parallel workers, but the output is unstable ...
Done!
Lukas Fittl <lu...@fittl.com> wrote:
I've briefly thought whether this needs documentation (currently the
patch includes none),
but there does not appear to be a good place to add documentation about
this from a
quick glance, so it seems acceptable to leave this out given the lack
of more detailed
EXPLAIN documentation in general.
You're right! I added feature description to the patch header.
Whilst no specific bad cases were provided, I wonder if even a simple
pgbench with
auto_explain (and log_analyze=1) would be a way to test this?
I wanted to measure overheads, but could't choose correct way. Thanks
for idea with auto_explain.
I loaded it and made 10 requests of pgbench (number of clients: 1, of
threads: 1).
I'm not sure I chose the right way to measure overhead, so any
suggestions are welcome.
Current results are in file overhead_v0.txt.
Please feel free to share your suggestions and comments. Regards,
--
Ekaterina Sokolova
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
From: Ekaterina Sokolova <e.sokol...@postgrespro.ru>
Subject: [PATCH] Add extra statistics to explain for Nested Loop
For some distributions of data in tables, different loops in nested loop
joins can take different time and process different amounts of entries.
It makes average statistics returned by explain analyze not very useful for DBA.
This patch add collecting of min, max and total statistics for time and rows
across all loops to EXPLAIN ANALYSE. You need to set the VERBOSE flag to display
this information. The patch contains regression tests.
Example of results in TEXT format:
-> Append (actual rows=5 loops=5)
Loop Min Rows: 2 Max Rows: 6 Total Rows: 23
Reviewed-by: Lukas Fittl, Justin Pryzby, Yugo Nagata, Julien Rouhaud.
---
src/backend/commands/explain.c | 147 +++++++++++++++-----------
src/backend/executor/instrument.c | 31 ++++++
src/include/executor/instrument.h | 6 ++
src/test/regress/expected/explain.out | 10 ++
src/test/regress/expected/partition_prune.out | 117 ++++++++++++++++++++
src/test/regress/sql/partition_prune.sql | 32 ++++++
6 files changed, 280 insertions(+), 63 deletions(-)
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 10644dfac44..458f37c3fc6 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -118,6 +118,8 @@ static void show_instrumentation_count(const char *qlabel, int which,
PlanState *planstate, ExplainState *es);
static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es);
static void show_eval_params(Bitmapset *bms_params, ExplainState *es);
+static void show_loop_info(Instrumentation *instrument, bool isworker,
+ ExplainState *es);
static const char *explain_get_index_name(Oid indexId);
static void show_buffer_usage(ExplainState *es, const BufferUsage *usage,
bool planning);
@@ -1606,42 +1608,14 @@ ExplainNode(PlanState *planstate, List *ancestors,
if (es->analyze &&
planstate->instrument && planstate->instrument->nloops > 0)
- {
- double nloops = planstate->instrument->nloops;
- double startup_ms = 1000.0 * planstate->instrument->startup / nloops;
- double total_ms = 1000.0 * planstate->instrument->total / nloops;
- double rows = planstate->instrument->ntuples / nloops;
-
- 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);
- else
- appendStringInfo(es->str,
- " (actual rows=%.0f loops=%.0f)",
- rows, nloops);
- }
- 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);
- }
- }
+ show_loop_info(planstate->instrument, false, es);
else if (es->analyze)
{
if (es->format == EXPLAIN_FORMAT_TEXT)
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);
@@ -1664,44 +1638,14 @@ ExplainNode(PlanState *planstate, List *ancestors,
for (int n = 0; n < w->num_workers; n++)
{
Instrumentation *instrument = &w->instrument[n];
- double nloops = instrument->nloops;
- double startup_ms;
- double total_ms;
- double rows;
- if (nloops <= 0)
+ if (instrument->nloops <= 0)
continue;
- startup_ms = 1000.0 * instrument->startup / nloops;
- total_ms = 1000.0 * instrument->total / nloops;
- rows = instrument->ntuples / nloops;
ExplainOpenWorker(n, es);
-
+ show_loop_info(instrument, true, 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);
- else
- appendStringInfo(es->str,
- "actual rows=%.0f loops=%.0f\n",
- rows, nloops);
- }
- 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);
- }
-
+ appendStringInfoChar(es->str, '\n');
ExplainCloseWorker(n, es);
}
}
@@ -3995,6 +3939,83 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors,
ExplainCloseGroup("Target Tables", "Target Tables", false, es);
}
+void
+show_loop_info(Instrumentation *instrument, bool isworker, ExplainState *es)
+{
+ double nloops = instrument->nloops;
+ double startup_ms = 1000.0 * instrument->startup / nloops;
+ double total_ms = 1000.0 * instrument->total / nloops;
+ double rows = instrument->ntuples / nloops;
+ double loop_total_rows = instrument->ntuples;
+ double loop_min_r = instrument->min_tuples;
+ double loop_max_r = instrument->max_tuples;
+ double loop_min_t_ms = 1000.0 * instrument->min_t;
+ double loop_max_t_ms = 1000.0 * instrument->max_t;
+
+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ {
+ if (isworker)
+ ExplainIndentText(es);
+ else
+ appendStringInfo(es->str, " (");
+
+ 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);
+
+ if (!isworker)
+ appendStringInfoChar(es->str, ')');
+
+ if (nloops > 1 && es->verbose)
+ {
+ appendStringInfoChar(es->str, '\n');
+ ExplainIndentText(es);
+
+ if (es->timing)
+ appendStringInfo(es->str,
+ "Loop Min Rows: %.0f Max Rows: %.0f Total Rows: %.0f Min Time: %.3f Max Time: %.3f",
+ loop_min_r, loop_max_r, loop_total_rows, loop_min_t_ms, loop_max_t_ms);
+ else
+ appendStringInfo(es->str,
+ "Loop Min Rows: %.0f Max Rows: %.0f Total Rows: %.0f",
+ loop_min_r, loop_max_r, loop_total_rows);
+ }
+ }
+ else
+ {
+ if (es->timing)
+ {
+ ExplainPropertyFloat("Actual Startup Time", "ms", startup_ms,
+ 3, es);
+ ExplainPropertyFloat("Actual Total Time", "ms", total_ms,
+ 3, es);
+ if (nloops > 1 && es->verbose)
+ {
+ 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 && 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);
+ }
+}
+
/*
* Explain the constituent plans of an Append, MergeAppend,
* BitmapAnd, or BitmapOr node.
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index 2b106d8473c..a49308ed126 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -153,7 +153,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) */
@@ -186,6 +213,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 2f9905b7c8e..e2ff330b8f1 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -79,7 +79,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 1734dfee8cc..275cdb37672 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -354,8 +354,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, +
@@ -400,7 +405,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 7555764c779..18617b9e206 100644
--- a/src/test/regress/expected/partition_prune.out
+++ b/src/test/regress/expected/partition_prune.out
@@ -1962,6 +1962,24 @@ begin
end loop;
end;
$$;
+create function explain_verbose_parallel_append(text) returns setof text
+language plpgsql as
+$$
+declare
+ ln text;
+begin
+ for ln in
+ execute format('explain (analyze, verbose, costs off, summary off, timing off) %s',
+ $1)
+ 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, '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;
+$$;
prepare ab_q4 (int, int) as
select avg(a) from ab where a between $1 and $2 and b < 4;
-- Encourage use of parallel plans
@@ -2218,6 +2236,39 @@ select explain_parallel_append('select avg(ab.a) from ab inner join lprt_a a on
Index Cond: (a = a.a)
(28 rows)
+-- Tests for extra statistics
+create table lprt_b (b int not null);
+insert into lprt_b select generate_series(1,20);
+select explain_verbose_parallel_append('select * from lprt_a join lprt_b on a != b');
+ explain_verbose_parallel_append
+------------------------------------------------------------------------------
+ Nested Loop (actual rows=N loops=N)
+ Output: lprt_a.a, lprt_b.b
+ Join Filter: (lprt_a.a <> lprt_b.b)
+ Rows Removed by Join Filter: 4
+ -> Gather (actual rows=N loops=N)
+ Output: lprt_b.b
+ Workers Planned: 2
+ Workers Launched: N
+ -> Parallel Seq Scan on public.lprt_b (actual rows=N loops=N)
+ Loop Min Rows: N Max Rows: N Total Rows: N
+ Output: lprt_b.b
+ Worker 0: actual rows=N loops=N
+ Worker 1: actual rows=N loops=N
+ -> Materialize (actual rows=N loops=N)
+ Loop Min Rows: N Max Rows: N Total Rows: N
+ Output: lprt_a.a
+ -> Gather (actual rows=N loops=N)
+ Output: lprt_a.a
+ Workers Planned: 1
+ Workers Launched: N
+ -> Parallel Seq Scan on public.lprt_a (actual rows=N loops=N)
+ Loop Min Rows: N Max Rows: N Total Rows: N
+ Output: lprt_a.a
+ Worker 0: actual rows=N loops=N
+(24 rows)
+
+drop table lprt_b;
delete from lprt_a where a = 1;
select explain_parallel_append('select avg(ab.a) from ab inner join lprt_a a on ab.a = a.a where a.a in(1, 0, 0)');
explain_parallel_append
@@ -2715,6 +2766,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 d70bd8610cb..68110e20eeb 100644
--- a/src/test/regress/sql/partition_prune.sql
+++ b/src/test/regress/sql/partition_prune.sql
@@ -469,6 +469,25 @@ begin
end;
$$;
+create function explain_verbose_parallel_append(text) returns setof text
+language plpgsql as
+$$
+declare
+ ln text;
+begin
+ for ln in
+ execute format('explain (analyze, verbose, costs off, summary off, timing off) %s',
+ $1)
+ 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, '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;
+$$;
+
prepare ab_q4 (int, int) as
select avg(a) from ab where a between $1 and $2 and b < 4;
@@ -528,6 +547,12 @@ insert into lprt_a values(3),(3);
select explain_parallel_append('select avg(ab.a) from ab inner join lprt_a a on ab.a = a.a where a.a in(1, 0, 3)');
select explain_parallel_append('select avg(ab.a) from ab inner join lprt_a a on ab.a = a.a where a.a in(1, 0, 0)');
+-- Tests for extra statistics
+create table lprt_b (b int not null);
+insert into lprt_b select generate_series(1,20);
+select explain_verbose_parallel_append('select * from lprt_a join lprt_b on a != b');
+drop table lprt_b;
+
delete from lprt_a where a = 1;
select explain_parallel_append('select avg(ab.a) from ab inner join lprt_a a on ab.a = a.a where a.a in(1, 0, 0)');
@@ -654,6 +679,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);
| master latency (ms) | master tps | | new latency (ms) | new tps
--------------------------------------------------------------------------
1 | 2,462 | 406,190341 | | 4,485 | 222,950527
2 | 3,877 | 257,89813 | | 4,141 | 241,493395
3 | 3,789 | 263,935811 | | 2,837 | 352,522297
4 | 3,53 | 283,310196 | | 5,510 | 181,488203
5 | 3,413 | 292,997363 | | 6,475 | 154,432999
6 | 3,757 | 266,148564 | | 4,073 | 245,507218
7 | 3,752 | 266,560043 | | 3,901 | 256,331385
8 | 4,389 | 227,847524 | | 4,658 | 214,675196
9 | 4,341 | 230,372282 | | 4,220 | 236,983672
10 | 3,893 | 256,891104 | | 7.059 | 141,667139
--------------------------------------------------------------------------
avg| 3,7203 | 275,215136 | | 4,03 | 224,8052031
master/new latency | 0,92315 |
master/new tps | 1,22424 |
new/master latency | 1,08325 |
new/master tps | 0,81683 |
