Add EXPLAIN (MEMORY) to report planner memory consumption
authorAlvaro Herrera <alvherre@alvh.no-ip.org>
Mon, 29 Jan 2024 16:53:03 +0000 (17:53 +0100)
committerAlvaro Herrera <alvherre@alvh.no-ip.org>
Mon, 29 Jan 2024 16:53:03 +0000 (17:53 +0100)
This adds a new "Memory:" line under the "Planning:" group (which
currently only has "Buffers:") when the MEMORY option is specified.

In order to make the reporting reasonably accurate, we create a separate
memory context for planner activities, to be used only when this option
is given.  The total amount of memory allocated by that context is
reported as "allocated"; we subtract memory in the context's freelists
from that and report that result as "used".  We use
MemoryContextStatsInternal() to obtain the quantities.

The code structure to show buffer usage during planning was not in
amazing shape, so I (Álvaro) modified the patch a bit to clean that up
in passing.

Author: Ashutosh Bapat
Reviewed-by: David Rowley, Andrey Lepikhov, Jian He, Andy Fan
Discussion: https://www.postgresql.org/message-id/CAExHW5sZA=5LJ_ZPpRO-w09ck8z9p7eaYAqq3Ks9GDfhrxeWBw@mail.gmail.com

contrib/auto_explain/auto_explain.c
doc/src/sgml/ref/explain.sgml
src/backend/commands/explain.c
src/backend/commands/prepare.c
src/backend/utils/mmgr/mcxt.c
src/include/commands/explain.h
src/include/utils/memutils.h
src/test/regress/expected/explain.out
src/test/regress/sql/explain.sql

index c7aacd7812b3a3f06b05ed6ebbbd3435ae4e6cbf..677c135f59bc2d7c5528aba8cf90eaed71fcba16 100644 (file)
@@ -396,6 +396,8 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
            es->wal = (es->analyze && auto_explain_log_wal);
            es->timing = (es->analyze && auto_explain_log_timing);
            es->summary = es->analyze;
+           /* No support for MEMORY */
+           /* es->memory = false; */
            es->format = auto_explain_log_format;
            es->settings = auto_explain_log_settings;
 
index 5ba6486da199e3f219122cb0d8081ce266bb7af2..a4b6564bdb3adda79246525a6a1826208a431a61 100644 (file)
@@ -44,6 +44,7 @@ EXPLAIN [ ( <replaceable class="parameter">option</replaceable> [, ...] ) ] <rep
     WAL [ <replaceable class="parameter">boolean</replaceable> ]
     TIMING [ <replaceable class="parameter">boolean</replaceable> ]
     SUMMARY [ <replaceable class="parameter">boolean</replaceable> ]
+    MEMORY [ <replaceable class="parameter">boolean</replaceable> ]
     FORMAT { TEXT | XML | JSON | YAML }
 </synopsis>
  </refsynopsisdiv>
@@ -250,6 +251,19 @@ ROLLBACK;
     </listitem>
    </varlistentry>
 
+   <varlistentry>
+    <term><literal>MEMORY</literal></term>
+    <listitem>
+     <para>
+      Include information on memory consumption by the query planning phase.
+      Specifically, include the precise amount of storage used by planner
+      in-memory structures, as well as total memory considering allocation
+      overhead.
+      This parameter defaults to <literal>FALSE</literal>.
+     </para>
+    </listitem>
+   </varlistentry>
+
    <varlistentry>
     <term><literal>FORMAT</literal></term>
     <listitem>
index 843472e6ddcfc412a9377eb2704523e875958490..83d00a46638d7922a13aa5d98f02443a8b1f7c8d 100644 (file)
@@ -119,9 +119,11 @@ static void show_instrumentation_count(const char *qlabel, int which,
 static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es);
 static void show_eval_params(Bitmapset *bms_params, ExplainState *es);
 static const char *explain_get_index_name(Oid indexId);
-static void show_buffer_usage(ExplainState *es, const BufferUsage *usage,
-                             bool planning);
+static bool peek_buffer_usage(ExplainState *es, const BufferUsage *usage);
+static void show_buffer_usage(ExplainState *es, const BufferUsage *usage);
 static void show_wal_usage(ExplainState *es, const WalUsage *usage);
+static void show_memory_counters(ExplainState *es,
+                                const MemoryContextCounters *mem_counters);
 static void ExplainIndexScanDetails(Oid indexid, ScanDirection indexorderdir,
                                    ExplainState *es);
 static void ExplainScanTarget(Scan *plan, ExplainState *es);
@@ -202,6 +204,8 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
            summary_set = true;
            es->summary = defGetBoolean(opt);
        }
+       else if (strcmp(opt->defname, "memory") == 0)
+           es->memory = defGetBoolean(opt);
        else if (strcmp(opt->defname, "format") == 0)
        {
            char       *p = defGetString(opt);
@@ -397,6 +401,25 @@ ExplainOneQuery(Query *query, int cursorOptions,
                    planduration;
        BufferUsage bufusage_start,
                    bufusage;
+       MemoryContextCounters mem_counters;
+       MemoryContext planner_ctx = NULL;
+       MemoryContext saved_ctx = NULL;
+
+       if (es->memory)
+       {
+           /*
+            * Create a new memory context to measure planner's memory
+            * consumption accurately.  Note that if the planner were to be
+            * modified to use a different memory context type, here we would
+            * be changing that to AllocSet, which might be undesirable.
+            * However, we don't have a way to create a context of the same
+            * type as another, so we pray and hope that this is OK.
+            */
+           planner_ctx = AllocSetContextCreate(CurrentMemoryContext,
+                                               "explain analyze planner context",
+                                               ALLOCSET_DEFAULT_SIZES);
+           saved_ctx = MemoryContextSwitchTo(planner_ctx);
+       }
 
        if (es->buffers)
            bufusage_start = pgBufferUsage;
@@ -408,6 +431,12 @@ ExplainOneQuery(Query *query, int cursorOptions,
        INSTR_TIME_SET_CURRENT(planduration);
        INSTR_TIME_SUBTRACT(planduration, planstart);
 
+       if (es->memory)
+       {
+           MemoryContextSwitchTo(saved_ctx);
+           MemoryContextMemConsumed(planner_ctx, &mem_counters);
+       }
+
        /* calc differences of buffer counters. */
        if (es->buffers)
        {
@@ -417,7 +446,8 @@ ExplainOneQuery(Query *query, int cursorOptions,
 
        /* run it (if needed) and produce output */
        ExplainOnePlan(plan, into, es, queryString, params, queryEnv,
-                      &planduration, (es->buffers ? &bufusage : NULL));
+                      &planduration, (es->buffers ? &bufusage : NULL),
+                      es->memory ? &mem_counters : NULL);
    }
 }
 
@@ -527,7 +557,8 @@ void
 ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
               const char *queryString, ParamListInfo params,
               QueryEnvironment *queryEnv, const instr_time *planduration,
-              const BufferUsage *bufusage)
+              const BufferUsage *bufusage,
+              const MemoryContextCounters *mem_counters)
 {
    DestReceiver *dest;
    QueryDesc  *queryDesc;
@@ -615,11 +646,27 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
    /* Create textual dump of plan tree */
    ExplainPrintPlan(es, queryDesc);
 
-   /* Show buffer usage in planning */
-   if (bufusage)
+   /* Show buffer and/or memory usage in planning */
+   if (peek_buffer_usage(es, bufusage) || mem_counters)
    {
        ExplainOpenGroup("Planning", "Planning", true, es);
-       show_buffer_usage(es, bufusage, true);
+
+       if (es->format == EXPLAIN_FORMAT_TEXT)
+       {
+           ExplainIndentText(es);
+           appendStringInfoString(es->str, "Planning:\n");
+           es->indent++;
+       }
+
+       if (bufusage)
+           show_buffer_usage(es, bufusage);
+
+       if (mem_counters)
+           show_memory_counters(es, mem_counters);
+
+       if (es->format == EXPLAIN_FORMAT_TEXT)
+           es->indent--;
+
        ExplainCloseGroup("Planning", "Planning", true, es);
    }
 
@@ -2106,7 +2153,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 
    /* Show buffer/WAL usage */
    if (es->buffers && planstate->instrument)
-       show_buffer_usage(es, &planstate->instrument->bufusage, false);
+       show_buffer_usage(es, &planstate->instrument->bufusage);
    if (es->wal && planstate->instrument)
        show_wal_usage(es, &planstate->instrument->walusage);
 
@@ -2125,7 +2172,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 
            ExplainOpenWorker(n, es);
            if (es->buffers)
-               show_buffer_usage(es, &instrument->bufusage, false);
+               show_buffer_usage(es, &instrument->bufusage);
            if (es->wal)
                show_wal_usage(es, &instrument->walusage);
            ExplainCloseWorker(n, es);
@@ -3545,10 +3592,52 @@ explain_get_index_name(Oid indexId)
 }
 
 /*
- * Show buffer usage details.
+ * Return whether show_buffer_usage would have anything to print, if given
+ * the same 'usage' data.  Note that when the format is anything other than
+ * text, we print even if the counters are all zeroes.
+ */
+static bool
+peek_buffer_usage(ExplainState *es, const BufferUsage *usage)
+{
+   bool        has_shared;
+   bool        has_local;
+   bool        has_temp;
+   bool        has_shared_timing;
+   bool        has_local_timing;
+   bool        has_temp_timing;
+
+   if (usage == NULL)
+       return false;
+
+   if (es->format != EXPLAIN_FORMAT_TEXT)
+       return true;
+
+   has_shared = (usage->shared_blks_hit > 0 ||
+                 usage->shared_blks_read > 0 ||
+                 usage->shared_blks_dirtied > 0 ||
+                 usage->shared_blks_written > 0);
+   has_local = (usage->local_blks_hit > 0 ||
+                usage->local_blks_read > 0 ||
+                usage->local_blks_dirtied > 0 ||
+                usage->local_blks_written > 0);
+   has_temp = (usage->temp_blks_read > 0 ||
+               usage->temp_blks_written > 0);
+   has_shared_timing = (!INSTR_TIME_IS_ZERO(usage->shared_blk_read_time) ||
+                        !INSTR_TIME_IS_ZERO(usage->shared_blk_write_time));
+   has_local_timing = (!INSTR_TIME_IS_ZERO(usage->local_blk_read_time) ||
+                       !INSTR_TIME_IS_ZERO(usage->local_blk_write_time));
+   has_temp_timing = (!INSTR_TIME_IS_ZERO(usage->temp_blk_read_time) ||
+                      !INSTR_TIME_IS_ZERO(usage->temp_blk_write_time));
+
+   return has_shared || has_local || has_temp || has_shared_timing ||
+       has_local_timing || has_temp_timing;
+}
+
+/*
+ * Show buffer usage details.  This better be sync with peek_buffer_usage.
  */
 static void
-show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
+show_buffer_usage(ExplainState *es, const BufferUsage *usage)
 {
    if (es->format == EXPLAIN_FORMAT_TEXT)
    {
@@ -3568,18 +3657,6 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
                                        !INSTR_TIME_IS_ZERO(usage->local_blk_write_time));
        bool        has_temp_timing = (!INSTR_TIME_IS_ZERO(usage->temp_blk_read_time) ||
                                       !INSTR_TIME_IS_ZERO(usage->temp_blk_write_time));
-       bool        show_planning = (planning && (has_shared ||
-                                                 has_local || has_temp ||
-                                                 has_shared_timing ||
-                                                 has_local_timing ||
-                                                 has_temp_timing));
-
-       if (show_planning)
-       {
-           ExplainIndentText(es);
-           appendStringInfoString(es->str, "Planning:\n");
-           es->indent++;
-       }
 
        /* Show only positive counter values. */
        if (has_shared || has_local || has_temp)
@@ -3678,9 +3755,6 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
            }
            appendStringInfoChar(es->str, '\n');
        }
-
-       if (show_planning)
-           es->indent--;
    }
    else
    {
@@ -3766,6 +3840,32 @@ show_wal_usage(ExplainState *es, const WalUsage *usage)
    }
 }
 
+/*
+ * Show memory usage details.
+ */
+static void
+show_memory_counters(ExplainState *es, const MemoryContextCounters *mem_counters)
+{
+   if (es->format == EXPLAIN_FORMAT_TEXT)
+   {
+       ExplainIndentText(es);
+       appendStringInfo(es->str,
+                        "Memory: used=%lld bytes  allocated=%lld bytes",
+                        (long long) (mem_counters->totalspace - mem_counters->freespace),
+                        (long long) mem_counters->totalspace);
+       appendStringInfoChar(es->str, '\n');
+   }
+   else
+   {
+       ExplainPropertyInteger("Memory Used", "bytes",
+                              mem_counters->totalspace - mem_counters->freespace,
+                              es);
+       ExplainPropertyInteger("Memory Allocated", "bytes",
+                              mem_counters->totalspace, es);
+   }
+}
+
+
 /*
  * Add some additional details about an IndexScan or IndexOnlyScan
  */
index 703976f633505aee5348980b3983ea63ac0bc708..bf1579d36d74bbbd6226b612e8bab73015e24cda 100644 (file)
@@ -583,6 +583,19 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
    instr_time  planduration;
    BufferUsage bufusage_start,
                bufusage;
+   MemoryContextCounters mem_counters;
+   MemoryContext planner_ctx = NULL;
+   MemoryContext saved_ctx = NULL;
+
+   if (es->memory)
+   {
+       /* See ExplainOneQuery about this */
+       Assert(IsA(CurrentMemoryContext, AllocSetContext));
+       planner_ctx = AllocSetContextCreate(CurrentMemoryContext,
+                                           "explain analyze planner context",
+                                           ALLOCSET_DEFAULT_SIZES);
+       saved_ctx = MemoryContextSwitchTo(planner_ctx);
+   }
 
    if (es->buffers)
        bufusage_start = pgBufferUsage;
@@ -624,6 +637,12 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
    INSTR_TIME_SET_CURRENT(planduration);
    INSTR_TIME_SUBTRACT(planduration, planstart);
 
+   if (es->memory)
+   {
+       MemoryContextSwitchTo(saved_ctx);
+       MemoryContextMemConsumed(planner_ctx, &mem_counters);
+   }
+
    /* calc differences of buffer counters. */
    if (es->buffers)
    {
@@ -640,7 +659,8 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
 
        if (pstmt->commandType != CMD_UTILITY)
            ExplainOnePlan(pstmt, into, es, query_string, paramLI, queryEnv,
-                          &planduration, (es->buffers ? &bufusage : NULL));
+                          &planduration, (es->buffers ? &bufusage : NULL),
+                          es->memory ? &mem_counters : NULL);
        else
            ExplainOneUtility(pstmt->utilityStmt, into, es, query_string,
                              paramLI, queryEnv);
index 1336944084df01c526acecaef7f09aa44d63b8ab..ad7409a02cdda3947c631a84b5e19c234f7c5d3c 100644 (file)
@@ -687,6 +687,19 @@ MemoryContextMemAllocated(MemoryContext context, bool recurse)
    return total;
 }
 
+/*
+ * Return the memory consumption statistics about the given context and its
+ * children.
+ */
+void
+MemoryContextMemConsumed(MemoryContext context,
+                        MemoryContextCounters *consumed)
+{
+   memset(consumed, 0, sizeof(*consumed));
+
+   MemoryContextStatsInternal(context, 0, false, 0, consumed, false);
+}
+
 /*
  * MemoryContextStats
  *     Print statistics about the named context and all its descendants.
index 1b44d483d6c3e0e40bcdbf577b66bba79335da7f..7c0f0b56365289a25ad1c121f82592ff0010bb57 100644 (file)
@@ -45,6 +45,7 @@ typedef struct ExplainState
    bool        wal;            /* print WAL usage */
    bool        timing;         /* print detailed node timing */
    bool        summary;        /* print total planning and execution timing */
+   bool        memory;         /* print planner's memory usage information */
    bool        settings;       /* print modified settings */
    bool        generic;        /* generate a generic plan */
    ExplainFormat format;       /* output format */
@@ -92,7 +93,8 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
                           ExplainState *es, const char *queryString,
                           ParamListInfo params, QueryEnvironment *queryEnv,
                           const instr_time *planduration,
-                          const BufferUsage *bufusage);
+                          const BufferUsage *bufusage,
+                          const MemoryContextCounters *mem_counters);
 
 extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
 extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
index ca7858d6b661245c37fde178d39acf11a4a79771..7fd41d20caf6f1150f17ff0d29e13e8f874c8dcf 100644 (file)
@@ -84,6 +84,8 @@ extern Size GetMemoryChunkSpace(void *pointer);
 extern MemoryContext MemoryContextGetParent(MemoryContext context);
 extern bool MemoryContextIsEmpty(MemoryContext context);
 extern Size MemoryContextMemAllocated(MemoryContext context, bool recurse);
+extern void MemoryContextMemConsumed(MemoryContext context,
+                                    MemoryContextCounters *consumed);
 extern void MemoryContextStats(MemoryContext context);
 extern void MemoryContextStatsDetail(MemoryContext context, int max_children,
                                     bool print_to_stderr);
index 809655e16ea72d47a8717f646d51cac662d15306..1299ee79ad58c50358ee25c1eb3daba64e7b4e2a 100644 (file)
@@ -326,6 +326,82 @@ select explain_filter('explain (generic_plan) select unique1 from tenk1 where th
 select explain_filter('explain (analyze, generic_plan) select unique1 from tenk1 where thousand = $1');
 ERROR:  EXPLAIN options ANALYZE and GENERIC_PLAN cannot be used together
 CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+-- MEMORY option
+select explain_filter('explain (memory) select * from int8_tbl i8');
+                     explain_filter                      
+---------------------------------------------------------
+ Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N)
+   Memory: used=N bytes  allocated=N bytes
+(2 rows)
+
+select explain_filter('explain (memory, analyze) select * from int8_tbl i8');
+                                        explain_filter                                         
+-----------------------------------------------------------------------------------------------
+ Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+   Memory: used=N bytes  allocated=N bytes
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+(4 rows)
+
+select explain_filter('explain (memory, summary, format yaml) select * from int8_tbl i8');
+        explain_filter         
+-------------------------------
+ - Plan:                      +
+     Node Type: "Seq Scan"    +
+     Parallel Aware: false    +
+     Async Capable: false     +
+     Relation Name: "int8_tbl"+
+     Alias: "i8"              +
+     Startup Cost: N.N        +
+     Total Cost: N.N          +
+     Plan Rows: N             +
+     Plan Width: N            +
+   Planning:                  +
+     Memory Used: N           +
+     Memory Allocated: N      +
+   Planning Time: N.N
+(1 row)
+
+select explain_filter('explain (memory, analyze, format json) select * from int8_tbl i8');
+           explain_filter           
+------------------------------------
+ [                                 +
+   {                               +
+     "Plan": {                     +
+       "Node Type": "Seq Scan",    +
+       "Parallel Aware": false,    +
+       "Async Capable": false,     +
+       "Relation Name": "int8_tbl",+
+       "Alias": "i8",              +
+       "Startup Cost": N.N,        +
+       "Total Cost": N.N,          +
+       "Plan Rows": N,             +
+       "Plan Width": N,            +
+       "Actual Startup Time": N.N, +
+       "Actual Total Time": N.N,   +
+       "Actual Rows": N,           +
+       "Actual Loops": N           +
+     },                            +
+     "Planning": {                 +
+       "Memory Used": N,           +
+       "Memory Allocated": N       +
+     },                            +
+     "Planning Time": N.N,         +
+     "Triggers": [                 +
+     ],                            +
+     "Execution Time": N.N         +
+   }                               +
+ ]
+(1 row)
+
+prepare int8_query as select * from int8_tbl i8;
+select explain_filter('explain (memory) execute int8_query');
+                     explain_filter                      
+---------------------------------------------------------
+ Seq Scan on int8_tbl i8  (cost=N.N..N.N rows=N width=N)
+   Memory: used=N bytes  allocated=N bytes
+(2 rows)
+
 -- Test EXPLAIN (GENERIC_PLAN) with partition pruning
 -- partitions should be pruned at plan time, based on constants,
 -- but there should be no pruning based on parameter placeholders
index b6b7beab27ad8bdc314d84ddebdd96a4d866236a..2274dc1b5a662d91b6788e873a441037a5d71453 100644 (file)
@@ -94,6 +94,14 @@ select explain_filter('explain (generic_plan) select unique1 from tenk1 where th
 -- should fail
 select explain_filter('explain (analyze, generic_plan) select unique1 from tenk1 where thousand = $1');
 
+-- MEMORY option
+select explain_filter('explain (memory) select * from int8_tbl i8');
+select explain_filter('explain (memory, analyze) select * from int8_tbl i8');
+select explain_filter('explain (memory, summary, format yaml) select * from int8_tbl i8');
+select explain_filter('explain (memory, analyze, format json) select * from int8_tbl i8');
+prepare int8_query as select * from int8_tbl i8;
+select explain_filter('explain (memory) execute int8_query');
+
 -- Test EXPLAIN (GENERIC_PLAN) with partition pruning
 -- partitions should be pruned at plan time, based on constants,
 -- but there should be no pruning based on parameter placeholders