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

Hi, and sorry to take such a long break from this patch.

On Wed, Apr 14, 2021 at 02:27:36PM +0300, e(dot)sokolova(at)postgrespro(dot)ru wrote:
> 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);

Now that I see it, I think it should say it with spaces, and not underscores,
like
| Loop Min Time: %.3f Max Time: %.3f ...

"Memory Usage:" already has spaces in its fields names, so this is more
consistent, and isn't doing anything new.

I think the min/max/total should be first, and the timing should follow, if
enabled. The "if(timing)" doesn't even need to duplicate the output, it could
append just the timing part.

I refactored this all into a separate function. I don't see why we'd repeat
these.

+ 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;

I realize the duplication doesn't originate with your patch. But because of
the duplication, there can be inconsistencies; for example, you wrote "ms" in
one place and "s" in another. Maybe you copied from before
f90c708a048667befbf6bbe5f48ae9695cb89de4 (an issue I reported the first time I
was looking at this patch).

I think the non-text format timing stuff needs to be within "if (timing)".

I'm curious to hear what you and others think of the refactoring.

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 ...

--
Justin