Re: [PATCH] Add extra statistics to explain for Nested Loop - Mailing list pgsql-hackers

> 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