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.sokolova@postgrespro.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