Re: BUG #16109: Postgres planning time is high across version (Expose buffer usage during planning in EXPLAIN)

On Wed, Apr 1, 2020 at 7:51 PM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
>
>
> On 2020/03/31 10:31, Justin Pryzby wrote:
> > On Wed, Jan 29, 2020 at 12:15:59PM +0100, Julien Rouhaud wrote:
> >> Rebase due to conflict with 3ec20c7091e97.
> >
> > This is failing to apply probably since 4a539a25ebfc48329fd656a95f3c1eb2cda38af3.
> > Could you rebase?   (Also, not sure if this can be set as RFC?)
>
> I updated the patch. Attached.

Thanks a lot!  I'm sorry I missed Justin's ping, and it I just
realized that my cron job that used to warn me about cfbot failure was
broken :(

> +/* Compute the difference between two BufferUsage */
> +BufferUsage
> +ComputeBufferCounters(BufferUsage *start, BufferUsage *stop)
>
> Since BufferUsageAccumDiff() was exported, ComputeBufferCounters() is
> no longer necessary. In the patched version, BufferUsageAccumDiff() is
> used to calculate the difference of buffer usage.

Indeed, exposing BufferUsageAccumDiff wa definitely a good thing!

> +       if (es->summary && (planduration || es->buffers))
> +               ExplainOpenGroup("Planning", "Planning", true, es);
>
> Isn't it more appropriate to check "bufusage" instead of "es->buffers" here?
> The patch changes the code so that "bufusage" is checked.

AFAICS not unless ExplainOneQuery is also changed to pass a NULL
pointer if the BUFFER option wasn't provided (and maybe also
optionally skip the planning buffer computation).  With this version
you now get:

=# explain (analyze, buffers off) update t1 set id = id;
                                              QUERY PLAN
-------------------------------------------------------------------------------------------------------
 Update on t1  (cost=0.00..22.70 rows=1270 width=42) (actual
time=0.170..0.170 rows=0 loops=1)
   ->  Seq Scan on t1  (cost=0.00..22.70 rows=1270 width=42) (actual
time=0.050..0.054 rows=1 loops=1)
 Planning Time: 1.461 ms
   Buffers: shared hit=25
 Execution Time: 1.071 ms
(5 rows)

which seems wrong to me.

I reused the es->buffers to avoid having needing something like:

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index b1f3fe13c6..9dbff97a32 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -375,7 +375,9 @@ ExplainOneQuery(Query *query, int cursorOptions,
        BufferUsage bufusage_start,
                    bufusage;

-       bufusage_start = pgBufferUsage;
+       if (ex->buffers)
+           bufusage_start = pgBufferUsage;
+
        INSTR_TIME_SET_CURRENT(planstart);

        /* plan the query */
@@ -384,13 +386,16 @@ ExplainOneQuery(Query *query, int cursorOptions,
        INSTR_TIME_SET_CURRENT(planduration);
        INSTR_TIME_SUBTRACT(planduration, planstart);

-       /* calc differences of buffer counters. */
-       memset(&bufusage, 0, sizeof(BufferUsage));
-       BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);
+       if (es->buffers)
+       {
+           /* calc differences of buffer counters. */
+           memset(&bufusage, 0, sizeof(BufferUsage));
+           BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);
+       }

        /* run it (if needed) and produce output */
        ExplainOnePlan(plan, into, es, queryString, params, queryEnv,
-                      &planduration, &bufusage);
+                      &planduration, (es->buffers ? &bufusage : NULL));
    }

which seemed like a win, but I'm not opposed to do that if you prefer.

>
> +       "Planning Time": N.N,        +
> +         "Shared Hit Blocks": N,    +
> +         "Shared Read Blocks": N,   +
> +         "Shared Dirtied Blocks": N,+
>
> Doesn't this indent look strange? IMO no indent for buffer usage is
> necessary when the format is either json, xml, and yaml. This looks
> better at least for me. OTOH, in text format, it seems better to indent
> the buffer usage for more readability. Thought?
> The patch changes the code so that "es->indent" is
> increment/decrement only when the format is text.

Indeed, that's way better!