Re: [PG13] Planning (time + buffers) data structure in explain plan (format text)

[Julien Rouhaud]

On Tue, Aug 18, 2020 at 10:27:06PM -0500, Justin Pryzby wrote:
> On Fri, Aug 07, 2020 at 02:30:01PM +0200, Pierre Giraud wrote:
> > Hi all,
> > 
> > As far as I understand, in the upcoming version 13, information about
> > buffers used during planning is now available in the explain plan.
> > 
> > […]
> >  Planning Time: 0.203 ms
> >    Buffers: shared hit=14
> > […]
> > 
> > For a matter of consistency, I wonder if it would be possible to format
> > it like the following:
> > 
> > […]
> >  Planning:
> >    Planning Time: 0.203 ms
> >    Buffers: shared hit=14
> 
> Thanks for reporting.  I added this here.
> https://wiki.postgresql.org/wiki/PostgreSQL_13_Open_Items

Thanks Justin!

Hearing no objection, here's a patch to change the output as suggested by
Pierre:

=# explain (analyze, buffers) select * from pg_class;
                                               QUERY PLAN                       
                       >
------------------------------------------------------------------------------------------------------->
 Seq Scan on pg_class  (cost=0.00..16.86 rows=386 width=265) (actual 
time=0.020..0.561 rows=386 loops=1)
   Buffers: shared hit=9 read=4
 Planning:
   Planning Time: 4.345 ms
   Buffers: shared hit=103 read=12
 Execution Time: 1.447 ms
(6 rows)

=# explain (analyze, buffers, format json) select * from pg_class;
             QUERY PLAN
-------------------------------------
 [                                  +
   {                                +
     "Plan": {                      +
       "Node Type": "Seq Scan",     +
       "Parallel Aware": false,     +
[...]
       "Temp Written Blocks": 0     +
     },                             +
     "Planning": {                  +
       "Planning Time": 4.494,      +
       "Shared Hit Blocks": 103,    +
       "Shared Read Blocks": 12,    +
       "Shared Dirtied Blocks": 0,  +
       "Shared Written Blocks": 0,  +
       "Local Hit Blocks": 0,       +
       "Local Read Blocks": 0,      +
       "Local Dirtied Blocks": 0,   +
       "Local Written Blocks": 0,   +
       "Temp Read Blocks": 0,       +
       "Temp Written Blocks": 0     +
     },                             +
     "Triggers": [                  +
     ],                             +
     "Execution Time": 1.824        +
   }                                +
 ]
(1 row)

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 30e0a7ee7f..375431acee 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -587,7 +587,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, 
ExplainState *es,
        ExplainPrintPlan(es, queryDesc);
 
        if (es->summary && (planduration || bufusage))
+       {
                ExplainOpenGroup("Planning", "Planning", true, es);
+               if (es->format == EXPLAIN_FORMAT_TEXT)
+               {
+                       ExplainIndentText(es);
+                       appendStringInfoString(es->str, "Planning:\n");
+                       es->indent++;
+               }
+       }
 
        if (es->summary && planduration)
        {
@@ -598,16 +606,14 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause 
*into, ExplainState *es,
 
        /* Show buffer usage */
        if (es->summary && bufusage)
-       {
-               if (es->format == EXPLAIN_FORMAT_TEXT)
-                       es->indent++;
                show_buffer_usage(es, bufusage);
-               if (es->format == EXPLAIN_FORMAT_TEXT)
-                       es->indent--;
-       }
 
        if (es->summary && (planduration || bufusage))
+       {
+               if (es->format == EXPLAIN_FORMAT_TEXT)
+                       es->indent--;
                ExplainCloseGroup("Planning", "Planning", true, es);
+       }
 
        /* Print info about runtime of triggers */
        if (es->analyze)