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(dot)fujii(at)oss(dot)nttdata(dot)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!