Re: [PATCH] Add extra statistics to explain for Nested Loop

> diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
> index afc45429ba4..723eccca013 100644
> --- a/src/backend/commands/explain.c
> +++ b/src/backend/commands/explain.c
> @@ -1589,29 +1589,82 @@ 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 total_rows = planstate->instrument->ntuples;
> + 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 rows=%.0f loops=%.0f)\n",
> + startup_ms, total_ms, rows, nloops);
> + ExplainIndentText(es);
> + appendStringInfo(es->str,
> + "Loop: min_time=%.3f max_time=%.3f min_rows=%.0f max_rows=%.0f total_rows=%.0f",
> + min_t_ms, max_t_ms, min_r, max_r, total_rows);

Lines with "colon" format shouldn't use equal signs, and should use two spaces
between fields. See:
https://www.postgresql.org/message-id/20200619022001.GY17995@telsasoft.com
https://www.postgresql.org/message-id/20200402054120.GC14618@telsasoft.com
https://www.postgresql.org/message-id/20200407042521.GH2228%40telsasoft.com

> + }
> + else
> + {
> + appendStringInfo(es->str,
> + " (actual rows=%.0f loops=%.0f)\n",
> + rows, nloops);
> + ExplainIndentText(es);
> + appendStringInfo(es->str,
> + "Loop: min_rows=%.0f max_rows=%.0f total_rows=%.0f",
> + min_r, max_r, total_rows);
> + }
> + }
> 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

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)

In non-text mode, think you should not check "nloops > 1". Rather, print the
field as 0.

The whole logic is duplicated for parallel workers. This could instead be a
function, called from both places. I think this would handle the computation
as well as the output. This would make the patch shorter.

> + ExplainPropertyFloat("Min Time", "ms",
> + min_t_ms, 3, es);
> + ExplainPropertyFloat("Max Time", "ms",
> + max_t_ms, 3, es);

I think the labels in non-text format should say "Loop Min Time" or similar.

> 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 */

And these variables should have a loop_ prefix like loop_min_t ?

--
Justin