public inbox for [email protected]
help / color / mirror / Atom feedFrom: [email protected]
To: Justin Pryzby <[email protected]>
Cc: [email protected]
Subject: Re: [PATCH] Add extra statistics to explain for Nested Loop
Date: Wed, 14 Apr 2021 14:27:36 +0300
Message-ID: <[email protected]> (raw)
In-Reply-To: <[email protected]>
References: <CAFj8pRA=wMP+yebbssQByL9nV5FJe6vnkw-ZB7zta1j2W9ftjg@mail.gmail.com>
<CAOBaU_YHfFcE3HPjW1Db-qOYNZuAMw3Cjv_pFRaRAQTQy+HE0g@mail.gmail.com>
<[email protected]>
<CAOBaU_Yj6gdcc7q_CYWWMByMSUt29pO2Vky6xk9eP2g1rw_Eww@mail.gmail.com>
<[email protected]>
<20201031012053.arjh7eehmlzud45p@development>
<[email protected]>
<[email protected]>
<CAOBaU_aN4oSGXJTrgN4k44g0Z1_2cASEnaGd2M3pdRdbiQdxuQ@mail.gmail.com>
<[email protected]>
<[email protected]>
Thank you for working on this issue. Your comments helped me make this
patch more correct.
> Lines with "colon" format shouldn't use equal signs, and should use two
> spaces
> between fields.
Done. Now extra line looks like "Loop min_rows: %.0f max_rows: %.0f
total_rows: %.0f" or "Loop min_time: %.3f max_time: %.3f min_rows:
%.0f max_rows: %.0f total_rows: %.0f".
> Since this is now on a separate line, the "if (nloops > 1 &&
> es->verbose)"
> can be after the existing "if (es->timing)", and shouldn't need its own
> "if (es->timing)". It should conditionally add a separate line, rather
> than
> duplicating the "(actual.*" line.
>
>> - if (es->timing)
>> + if (nloops > 1 && es->verbose)
New version of patch contains this correction. It helped make the patch
shorter.
> In non-text mode, think you should not check "nloops > 1". Rather,
> print the
> field as 0.
The fields will not be zeros. New line will almost repeat the line with
main sttistics.
> I think the labels in non-text format should say "Loop Min Time" or
> similar.
>
> And these variables should have a loop_ prefix like loop_min_t ?
There are good ideas. I changed it.
I apply new version of this patch. I hope it got better.
Please don't hesitate to share any thoughts on this topic.
--
Ekaterina Sokolova
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
Attachments:
[text/x-diff] extra_statistics_v4.patch (14.8K, ../[email protected]/2-extra_statistics_v4.patch)
download | inline diff:
From: "Ekaterina Sokolova" <[email protected]>
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);
view thread (35+ messages) latest in thread
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected], [email protected]
Subject: Re: [PATCH] Add extra statistics to explain for Nested Loop
In-Reply-To: <[email protected]>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox