Include information on buffer usage during planning phase, in EXPLAIN output.

When BUFFERS option is enabled, EXPLAIN command includes the information
on buffer usage during each plan node, in its output. In addition to that,
this commit makes EXPLAIN command include also the information on
buffer usage during planning phase, in its output. This feature makes it
easier to discern the cases where lots of buffer access happen during
planning.

Author: Julien Rouhaud, slightly revised by Fujii Masao
Reviewed-by: Justin Pryzby
Discussion: https://postgr.es/m/16109-26a1a88651e90608@postgresql.org

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index ee0e638f33d4e8819c62792b75d10fbf6340b1d3..81a18abbeb3cd6f74b70e9981cb5036fecb01371 100644 (file)
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -372,7 +372,11 @@ ExplainOneQuery(Query *query, int cursorOptions,
        PlannedStmt *plan;
        instr_time  planstart,
                    planduration;
+       BufferUsage bufusage_start,
+                   bufusage;
 
+       if (es->buffers)
+           bufusage_start = pgBufferUsage;
        INSTR_TIME_SET_CURRENT(planstart);
 
        /* plan the query */
@@ -381,9 +385,16 @@ ExplainOneQuery(Query *query, int cursorOptions,
        INSTR_TIME_SET_CURRENT(planduration);
        INSTR_TIME_SUBTRACT(planduration, planstart);
 
+       /* calc differences of buffer counters. */
+       if (es->buffers)
+       {
+           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);
+                      &planduration, (es->buffers ? &bufusage : NULL));
    }
 }
 
@@ -476,7 +487,8 @@ ExplainOneUtility(Node *utilityStmt, IntoClause *into, ExplainState *es,
 void
 ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
               const char *queryString, ParamListInfo params,
-              QueryEnvironment *queryEnv, const instr_time *planduration)
+              QueryEnvironment *queryEnv, const instr_time *planduration,
+              const BufferUsage *bufusage)
 {
    DestReceiver *dest;
    QueryDesc  *queryDesc;
@@ -560,6 +572,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
    /* Create textual dump of plan tree */
    ExplainPrintPlan(es, queryDesc);
 
+   if (es->summary && (planduration || bufusage))
+       ExplainOpenGroup("Planning", "Planning", true, es);
+
    if (es->summary && planduration)
    {
        double      plantime = INSTR_TIME_GET_DOUBLE(*planduration);
@@ -567,6 +582,19 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
        ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, 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))
+       ExplainCloseGroup("Planning", "Planning", true, es);
+
    /* Print info about runtime of triggers */
    if (es->analyze)
        ExplainPrintTriggers(es, queryDesc);

diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c
index 284a5bfbec750b2c8e8239b287fd4c0f7c17d8ce..80d6df8ac1e78e44adda1edb60ec99c728b9a994 100644 (file)
--- a/src/backend/commands/prepare.c
+++ b/src/backend/commands/prepare.c
@@ -616,7 +616,11 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
    EState     *estate = NULL;
    instr_time  planstart;
    instr_time  planduration;
+   BufferUsage bufusage_start,
+               bufusage;
 
+   if (es->buffers)
+       bufusage_start = pgBufferUsage;
    INSTR_TIME_SET_CURRENT(planstart);
 
    /* Look it up in the hash table */
@@ -654,6 +658,13 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
    INSTR_TIME_SET_CURRENT(planduration);
    INSTR_TIME_SUBTRACT(planduration, planstart);
 
+   /* calc differences of buffer counters. */
+   if (es->buffers)
+   {
+       memset(&bufusage, 0, sizeof(BufferUsage));
+       BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);
+   }
+
    plan_list = cplan->stmt_list;
 
    /* Explain each query */
@@ -663,7 +674,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
 
        if (pstmt->commandType != CMD_UTILITY)
            ExplainOnePlan(pstmt, into, es, query_string, paramLI, queryEnv,
-                          &planduration);
+                          &planduration, (es->buffers ? &bufusage : NULL));
        else
            ExplainOneUtility(pstmt->utilityStmt, into, es, query_string,
                              paramLI, queryEnv);

diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 54f6240e5e5271b04b93f214cfce844a3f16703f..739c1d0b423cb84be5f833cb62ffce717a2b3d2f 100644 (file)
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -89,7 +89,8 @@ extern void ExplainOneUtility(Node *utilityStmt, IntoClause *into,
 extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
                           ExplainState *es, const char *queryString,
                           ParamListInfo params, QueryEnvironment *queryEnv,
-                          const instr_time *planduration);
+                          const instr_time *planduration,
+                          const BufferUsage *bufusage);
 
 extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
 extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);

diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 8f31c308c6054904e98ef0bd56224602724f74a0..191ea5de7f0a015c5e303b834ab835680ea27e43 100644 (file)
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -105,7 +105,19 @@ select explain_filter('explain (analyze, buffers, format json) select * from int
        "Temp Read Blocks": N,      +
        "Temp Written Blocks": N    +
      },                            +
-     "Planning Time": N.N,         +
+     "Planning": {                 +
+       "Planning Time": N.N,       +
+       "Shared Hit Blocks": N,     +
+       "Shared Read Blocks": N,    +
+       "Shared Dirtied Blocks": N, +
+       "Shared Written Blocks": N, +
+       "Local Hit Blocks": N,      +
+       "Local Read Blocks": N,     +
+       "Local Dirtied Blocks": N,  +
+       "Local Written Blocks": N,  +
+       "Temp Read Blocks": N,      +
+       "Temp Written Blocks": N    +
+     },                            +
      "Triggers": [                 +
      ],                            +
      "Execution Time": N.N         +
@@ -142,7 +154,19 @@ select explain_filter('explain (analyze, buffers, format xml) select * from int8
        <Temp-Read-Blocks>N</Temp-Read-Blocks>          +
        <Temp-Written-Blocks>N</Temp-Written-Blocks>    +
      </Plan>                                           +
-     <Planning-Time>N.N</Planning-Time>                +
+     <Planning>                                        +
+       <Planning-Time>N.N</Planning-Time>              +
+       <Shared-Hit-Blocks>N</Shared-Hit-Blocks>        +
+       <Shared-Read-Blocks>N</Shared-Read-Blocks>      +
+       <Shared-Dirtied-Blocks>N</Shared-Dirtied-Blocks>+
+       <Shared-Written-Blocks>N</Shared-Written-Blocks>+
+       <Local-Hit-Blocks>N</Local-Hit-Blocks>          +
+       <Local-Read-Blocks>N</Local-Read-Blocks>        +
+       <Local-Dirtied-Blocks>N</Local-Dirtied-Blocks>  +
+       <Local-Written-Blocks>N</Local-Written-Blocks>  +
+       <Temp-Read-Blocks>N</Temp-Read-Blocks>          +
+       <Temp-Written-Blocks>N</Temp-Written-Blocks>    +
+     </Planning>                                       +
      <Triggers>                                        +
      </Triggers>                                       +
      <Execution-Time>N.N</Execution-Time>              +
@@ -176,7 +200,18 @@ select explain_filter('explain (analyze, buffers, format yaml) select * from int
      Local Written Blocks: N  +
      Temp Read Blocks: N      +
      Temp Written Blocks: N   +
-   Planning Time: N.N         +
+   Planning:                  +
+     Planning Time: N.N       +
+     Shared Hit Blocks: N     +
+     Shared Read Blocks: N    +
+     Shared Dirtied Blocks: N +
+     Shared Written Blocks: N +
+     Local Hit Blocks: N      +
+     Local Read Blocks: N     +
+     Local Dirtied Blocks: N  +
+     Local Written Blocks: N  +
+     Temp Read Blocks: N      +
+     Temp Written Blocks: N   +
    Triggers:                  +
    Execution Time: N.N
 (1 row)
@@ -366,9 +401,21 @@ select jsonb_pretty(
              "Shared Dirtied Blocks": 0,                    +
              "Shared Written Blocks": 0                     +
          },                                                 +
+         "Planning": {                                      +
+             "Planning Time": 0.0,                          +
+             "Local Hit Blocks": 0,                         +
+             "Temp Read Blocks": 0,                         +
+             "Local Read Blocks": 0,                        +
+             "Shared Hit Blocks": 0,                        +
+             "Shared Read Blocks": 0,                       +
+             "Temp Written Blocks": 0,                      +
+             "Local Dirtied Blocks": 0,                     +
+             "Local Written Blocks": 0,                     +
+             "Shared Dirtied Blocks": 0,                    +
+             "Shared Written Blocks": 0                     +
+         },                                                 +
          "Triggers": [                                      +
          ],                                                 +
-         "Planning Time": 0.0,                              +
          "Execution Time": 0.0                              +
      }                                                      +
  ]