Subject: Re: Report planning memory in EXPLAIN ANALYZE

From: Ashutosh Bapat <[email-masked]>
Date: Mon, 11 Dec 2023 19:05:32 +0530

On Mon, Dec 11, 2023 at 2:06 PM jian he <[email-masked]> wrote:
>
> On Mon, Dec 4, 2023 at 3:24 PM Ashutosh Bapat
> <[email-masked]> wrote:
> >
> > On Fri, Dec 1, 2023 at 8:27 AM Andrei Lepikhov
> > <[email-masked]> wrote:
> > >
> > > On 30/11/2023 18:40, Alvaro Herrera wrote:
> > > > Well, SUMMARY is enabled by default with ANALYZE, and I'd rather not
> > > > have planner memory consumption displayed by default with all EXPLAIN
> > > > ANALYZEs.  So yeah, I still think this deserves its own option.
> > > >
> > > > But let's hear others' opinions on this point.  I'm only one vote here.
> > >
> > > I agree; it should be disabled by default. The fact that memory
> > > consumption outputs with byte precision (very uncomfortable for
> > > perception) is a sign that the primary audience is developers and for
> > > debugging purposes.
> >
> > That's 2 vs 1. Here's patch with MEMORY option added. Replying to
> > Alvaro's earlier relevant comments.
> >
>
> "Include information on planner's memory consumption. Specially,
> include the total memory allocated by the planner and net memory that
> remains used at the end of the planning. It defaults to
> <literal>FALSE</literal>.
> "
> doc/src/sgml/ref/explain.sgml
> I can view MemoryContextSizeDifference, figure out the meaning.
>
> But I am not sure "net memory that remains used at the end of the
> planning" is the correct description.
> (I am not native english speaker).

The word "net" is used as an adjective, see [1]

[1] https://www.merriam-webster.com/dictionary/net (as an adjective)

Does that help? Do you have any other wording proposal?

-- 
Best Wishes,
Ashutosh Bapat

---

From: Alvaro Herrera <[email-masked]>
Date: Tue, 12 Dec 2023 21:11:31 +0100

I would replace the text in explain.sgml with this:

+      Include information on memory consumption by the query planning phase.
+      This includes the precise amount of storage used by planner in-memory
+      structures, as well as overall total consumption of planner memory,
+      including allocation overhead.
+      This parameter defaults to </literal>FALSE</literal>.

and remove the new example you're adding; it's not really necessary.

In struct ExplainState, I'd put the new member just below summary.

If we're creating a new memory context for planner, we don't need the
"mem_counts_start" thing, and we don't need the
MemoryContextSizeDifference thing.  Just add the
MemoryContextMemConsumed() function (which ISTM should be just below
MemoryContextMemAllocated() instead of in the middle of the
MemoryContextStats implementation), and
just report the values we get there.  I think the SizeDifference stuff
increases surface damage for no good reason.

ExplainOnePlan() is given a MemoryUsage object (or, if we do as above
and no longer have a MemoryUsage struct at all in the first place, a
MemoryContextCounters object) even when the MEMORY option is false.
This means we waste computing memory usage when not needed.  Let's avoid
that useless overhead.

I'd also do away with the comment you added in explain_ExecutorEnd() and
do just this, below setting of es->summary:

+           /* No support for MEMORY option */
+           /* es->memory = false; */

We don't need to elaborate more at present.

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/
"Doing what he did amounts to sticking his fingers under the hood of the
implementation; if he gets his fingers burnt, it's his problem."  (Tom Lane)

---

From: Alvaro Herrera <[email-masked]>
Date: Tue, 12 Dec 2023 21:20:24 +0100

> +      This parameter defaults to </literal>FALSE</literal>.

(This can still use a lot more wordsmithing of course, such as avoiding
repeated use of "include/ing", ugh)

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/
"The Gord often wonders why people threaten never to come back after they've
been told never to return" (www.actsofgord.com)

---

From: Ashutosh Bapat <[email-masked]>
Date: Wed, 13 Dec 2023 16:21:30 +0530

> +      This parameter defaults to </literal>FALSE</literal>.

To me consumption in the "... total consumption ..." part is same as
allocation and that includes allocation overhead as well as any memory
that was allocated but remained unused (see discussion [1] if you
haven't already) ultimately. Mentioning "total consumption" and
"allocation overhead" seems more confusing.

How about
+      Include information on memory consumption by the query planning phase.
+      Report the precise amount of storage used by planner in-memory
+      structures, and total memory considering allocation overhead.
+      The parameter defaults to <literal>FALSE</literal>.

Takes care of your complaint about multiple include/ing as well.

> and remove the new example you're adding; it's not really necessary.

Done.

> In struct ExplainState, I'd put the new member just below summary.

Done

> increases surface damage for no good reason.

240 bytes are used right after creating a memory context i.e.
mem_counts_start.totalspace = 8192 and mem_counts_start.freespace =
7952. To account for that I used two counters and calculated the
difference. If no planning is involved in EXECUTE <prepared statement>
it will show 240 bytes used instead of 0. Barring that for all
practical purposes 240 bytes negligible. E.g. 240 bytes is 4% of the
amount of memory used for planning a simple query " select 'x' ". But
your suggestion simplifies the code a lot. An error of 240 bytes seems
worth the code simplification. So did that way.

> This means we waste computing memory usage when not needed.  Let's avoid

Done.

Also avoided creating a memory context and switching to it when
es->memory = false.

> +           /* es->memory = false; */

Done.

I ended up rewriting most of the code, so squashed everything into a
single patch as attached.

-- 
Best Wishes,
Ashutosh Bapat
From 8282b3347a8535cfe09b5f2f4a0c5a6bdcba11fa Mon Sep 17 00:00:00 2001
From: Ashutosh Bapat <[email-masked]>
Date: Wed, 12 Jul 2023 14:34:14 +0530
Subject: [PATCH] EXPLAIN reports memory consumed for planning a query

The memory consumed is reported as "Planner Memory" property in EXPLAIN
output when option MEMORY is specified.

A separate memory context is allocated for measuring memory consumption
to eliminate any effect of previous activity on the calculation.  The
memory context statistics is noted before and after calling
pg_plan_query() from ExplainOneQuery(). The difference in the two
statistics is used to calculate the memory consumption.

We report two values "used" and "allocated".  The difference between
memory statistics counters totalspace and freespace gives the memory
that remains palloc'ed at the end of planning. It is reported as memory
"used". This does not account for chunks of memory that were palloc'ed
but subsequently pfree'ed. But such memory remains allocated in the
memory context is given by the totalspace counter. The value of this
counter is reported as memory "allocated".

Ashutosh Bapat, reviewed by David Rowley and Alvaro Herrera
---
 contrib/auto_explain/auto_explain.c   |  2 +
 doc/src/sgml/ref/explain.sgml         | 13 +++++
 src/backend/commands/explain.c        | 67 +++++++++++++++++++++++++-
 src/backend/commands/prepare.c        | 26 +++++++++-
 src/backend/utils/mmgr/mcxt.c         | 13 +++++
 src/include/commands/explain.h        |  4 +-
 src/include/utils/memutils.h          |  2 +
 src/test/regress/expected/explain.out | 68 +++++++++++++++++++++++++++
 src/test/regress/sql/explain.sql      |  6 +++
 9 files changed, 197 insertions(+), 4 deletions(-)

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index c3ac27ae99..26e80e4e16 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -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 option */
+			/* es->memory = false; */
 			es->format = auto_explain_log_format;
 			es->settings = auto_explain_log_settings;
 
diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index 5ba6486da1..49c61cce69 100644
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -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,18 @@ ROLLBACK;
     </listitem>
    </varlistentry>
 
+   <varlistentry>
+    <term><literal>MEMORY</literal></term>
+    <listitem>
+     <para>
+      Include information on memory consumption by the query planning phase.
+      Report the precise amount of storage used by planner in-memory
+      structures, and total memory considering allocation overhead.
+      The parameter defaults to <literal>FALSE</literal>.
+     </para>
+    </listitem>
+   </varlistentry>
+
    <varlistentry>
     <term><literal>FORMAT</literal></term>
     <listitem>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index f1d71bc54e..0a18a7abd8 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -122,6 +122,8 @@ static const char *explain_get_index_name(Oid indexId);
 static void show_buffer_usage(ExplainState *es, const BufferUsage *usage,
 							  bool planning);
 static void show_wal_usage(ExplainState *es, const WalUsage *usage);
+static void show_planner_memory(ExplainState *es,
+								const MemoryContextCounters *mem_counts);
 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,24 @@ ExplainOneQuery(Query *query, int cursorOptions,
 					planduration;
 		BufferUsage bufusage_start,
 					bufusage;
+		MemoryContextCounters mem_counts;
+		MemoryContext planner_ctx = NULL;
+		MemoryContext saved_ctx = NULL;
+
+		if (es->memory)
+		{
+			/*
+			 * Create a new memory context to measure planner's memory
+			 * consumption accurately. We should use the same type of memory
+			 * context as the planner would use. That's usually AllocSet but
+			 * ensure that.
+			 */
+			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;
@@ -408,6 +430,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_counts);
+		}
+
 		/* calc differences of buffer counters. */
 		if (es->buffers)
 		{
@@ -417,7 +445,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_counts : NULL));
 	}
 }
 
@@ -527,7 +556,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_counts)
 {
 	DestReceiver *dest;
 	QueryDesc  *queryDesc;
@@ -630,6 +660,13 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es);
 	}
 
+	if (mem_counts)
+	{
+		ExplainOpenGroup("Planner Memory", "Planner Memory", true, es);
+		show_planner_memory(es, mem_counts);
+		ExplainCloseGroup("Planner Memory", "Planner Memory", true, es);
+	}
+
 	/* Print info about runtime of triggers */
 	if (es->analyze)
 		ExplainPrintTriggers(es, queryDesc);
@@ -3766,6 +3803,32 @@ show_wal_usage(ExplainState *es, const WalUsage *usage)
 	}
 }
 
+/*
+ * Show planner's memory usage details.
+ */
+static void
+show_planner_memory(ExplainState *es,
+					const MemoryContextCounters *mem_counts)
+{
+	if (es->format == EXPLAIN_FORMAT_TEXT)
+	{
+		appendStringInfo(es->str,
+						 "Planner Memory: used=%zu bytes allocated=%zu bytes",
+						 mem_counts->totalspace - mem_counts->freespace,
+						 mem_counts->totalspace);
+		appendStringInfoChar(es->str, '\n');
+	}
+	else
+	{
+		ExplainPropertyInteger("Used", "bytes",
+							   mem_counts->totalspace - mem_counts->freespace,
+							   es);
+		ExplainPropertyInteger("Allocated", "bytes",
+							   mem_counts->totalspace, es);
+	}
+}
+
+
 /*
  * Add some additional details about an IndexScan or IndexOnlyScan
  */
diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c
index 18f70319fc..7e947e023b 100644
--- a/src/backend/commands/prepare.c
+++ b/src/backend/commands/prepare.c
@@ -583,6 +583,23 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
 	instr_time	planduration;
 	BufferUsage bufusage_start,
 				bufusage;
+	MemoryContextCounters mem_counts;
+	MemoryContext planner_ctx = NULL;
+	MemoryContext saved_ctx = NULL;
+
+	if (es->memory)
+	{
+		/*
+		 * Create a new memory context to measure planner's memory consumption
+		 * accurately. We should use the same type of memory context as the
+		 * planner would use. That's usually AllocSet but ensure that.
+		 */
+		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 +641,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_counts);
+	}
+
 	/* calc differences of buffer counters. */
 	if (es->buffers)
 	{
@@ -640,7 +663,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_counts : NULL));
 		else
 			ExplainOneUtility(pstmt->utilityStmt, into, es, query_string,
 							  paramLI, queryEnv);
diff --git a/src/backend/utils/mmgr/mcxt.c b/src/backend/utils/mmgr/mcxt.c
index 9fc83f11f6..58634e5ad6 100644
--- a/src/backend/utils/mmgr/mcxt.c
+++ b/src/backend/utils/mmgr/mcxt.c
@@ -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.
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index f9525fb572..798d1be2de 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -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_counts);
 
 extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
 extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
diff --git a/src/include/utils/memutils.h b/src/include/utils/memutils.h
index d14e8546a6..6f2abcfe4e 100644
--- a/src/include/utils/memutils.h
+++ b/src/include/utils/memutils.h
@@ -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);
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 809655e16e..86bfdfd29e 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -326,6 +326,74 @@ 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)
+ Planner 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)
+ Planning Time: N.N ms
+ Planner Memory: used=N bytes allocated=N bytes
+ 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 Time: N.N         +
+   Planner Memory:            +
+     Used: N                  +
+     Allocated: 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 Time": N.N,         +
+     "Planner Memory": {           +
+       "Used": N,                  +
+       "Allocated": N              +
+     },                            +
+     "Triggers": [                 +
+     ],                            +
+     "Execution Time": N.N         +
+   }                               +
+ ]
+(1 row)
+
 -- 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
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index b6b7beab27..f719e92f84 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -94,6 +94,12 @@ 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');
+
 -- 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
-- 
2.25.1