Forgot to attach patch. Here it is
On Mon, Dec 18, 2023 at 12:55 PM Ashutosh Bapat
<ashutosh.bapat....@gmail.com> wrote:
>
> On Sun, Dec 17, 2023 at 10:31 PM Alvaro Herrera <alvhe...@alvh.no-ip.org>
> wrote:
> >
> > OK, I propose the following further minor tweaks. (I modified the docs
> > following the wording we have for COSTS and BUFFERS).
>
> LGTM. Included in the attached patch.
>
> >
> > There are two things that still trouble me a bit. First, we assume that
> > the planner is using an AllocSet context, which I guess is true, but if
> > somebody runs the planner in a context of a different memcxt type, it's
> > going to be a problem. So far we don't have infrastructure for creating
> > a context of the same type as another context. Maybe it's too fine a
> > point to worry about, for sure.
>
> I had considered this point. Different contexts take different
> arguments for creation, so some jugglery is required to create a
> context based on type. It looked more than necessary for the limited
> scope of this patch. That's why I settled on the assertion. If we see
> the need in future we can always add that support.
>
> >
> > The other question is about trying to support the EXPLAIN EXECUTE case.
> > Do you find that case really useful? In a majority of cases planning is
> > not going to happen because it was already done by PREPARE (where we
> > _don't_ report memory, because we don't have EXPLAIN there), so it seems
> > a bit weird. I suppose you could make it useful if you instructed the
> > user to set plan_cache_mode to custom, assuming that does actually work
> > (I didn't try).
>
> If we set plan_cache_mode to force_custom_plan, we always plan the
> statement and thus report memory.
>
> You are right that we don't always plan the statement when EXECUTE Is
> issued. But it seems we create plan underneath EXECUTE more often that
> I expected. And the report looks mildly useful and interesting.
>
> postgres@21258=#prepare stmt as select * from pg_class where oid = $1;
> PREPARE
> postgres@21258=#explain (memory) execute stmt(1); -- first time
> QUERY PLAN
> -------------------------------------------------------------------------------------
> Index Scan using pg_class_oid_index on pg_class (cost=0.27..8.29
> rows=1 width=273)
> Index Cond: (oid = '1'::oid)
> Planner Memory: used=40448 bytes allocated=81920 bytes
> (3 rows)
>
>
> postgres@21258=#explain (memory) execute stmt(1);
> QUERY PLAN
> -------------------------------------------------------------------------------------
> Index Scan using pg_class_oid_index on pg_class (cost=0.27..8.29
> rows=1 width=273)
> Index Cond: (oid = '1'::oid)
> Planner Memory: used=40368 bytes allocated=81920 bytes
> (3 rows)
>
> observe that the memory used is slightly different from the first
> time. So when the plan is created again something happens that eats
> few bytes less. I didn't investigate what.
>
> The same output repeats if the statement is executed 3 more times.
> That's as many times a custom plan is created for a statement by
> default.
>
> postgres@21258=#explain (memory) execute stmt(1);
> QUERY PLAN
> -------------------------------------------------------------------------------------
> Index Scan using pg_class_oid_index on pg_class (cost=0.27..8.29
> rows=1 width=273)
> Index Cond: (oid = $1)
> Planner Memory: used=40272 bytes allocated=81920 bytes
> (3 rows)
>
> Observe that the memory used is less here again. So when creating the
> generic plan something happened which causes the change in memory
> consumption. Didn't investigate.
>
>
> postgres@21258=#explain (memory) execute stmt(1);
> QUERY PLAN
> -------------------------------------------------------------------------------------
> Index Scan using pg_class_oid_index on pg_class (cost=0.27..8.29
> rows=1 width=273)
> Index Cond: (oid = $1)
> Planner Memory: used=3520 bytes allocated=24576 bytes
> (3 rows)
>
> And now the planner is settled on very low value but still non-zero or
> 240 bytes. I think the parameter evaluation takes that much memory.
> Haven't verified.
>
> If we use an non-parameterized statement
> postgres@21258=#prepare stmt as select * from pg_class where oid = 2345;
> PREPARE
> postgres@21258=#explain (memory) execute stmt;
> QUERY PLAN
> -------------------------------------------------------------------------------------
> Index Scan using pg_class_oid_index on pg_class (cost=0.27..8.29
> rows=1 width=273)
> Index Cond: (oid = '2345'::oid)
> Planner Memory: used=37200 bytes allocated=65536 bytes
> (3 rows)
>
> first time memory is consumed by the planner.
>
> postgres@21258=#explain (memory) execute stmt;
> QUERY PLAN
> -------------------------------------------------------------------------------------
> Index Scan using pg_class_oid_index on pg_class (cost=0.27..8.29
> rows=1 width=273)
> Index Cond: (oid = '2345'::oid)
> Planner Memory: used=240 bytes allocated=8192 bytes
> (3 rows)
>
> Next time onwards it has settled on the custom plan.
>
> I think there's something to learn and investigate from memory numbers
> here. So not completely meaningless and useless.
>
> I added that support on lines of "planning time".
>
> --
> Best Wishes,
> Ashutosh Bapat
--
Best Wishes,
Ashutosh Bapat
From 3b7dfb5ae99cd3e3ec35618007811a78341a77d4 Mon Sep 17 00:00:00 2001
From: Ashutosh Bapat <ashutosh.ba...@enterprisedb.com>
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 | 14 ++++++
src/backend/commands/explain.c | 67 +++++++++++++++++++++++++-
src/backend/commands/prepare.c | 29 +++++++++++-
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, 201 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..26809d68d5 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,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.
+ 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..2fa93998a3 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 (es->memory && mem_counts != NULL)
+ {
+ 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=%lld bytes allocated=%lld bytes",
+ (long long) (mem_counts->totalspace - mem_counts->freespace),
+ (long long) 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..e1577c791a 100644
--- a/src/backend/commands/prepare.c
+++ b/src/backend/commands/prepare.c
@@ -583,6 +583,26 @@ 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)
+ {
+ /*
+ * In order to measure planner's memory consumption accurately, create
+ * a separate AllocSet memory context.
+ *
+ * XXX if planner is called under some other memory context type, this
+ * code overrides that. Do we need support to create context of
+ * programmatically determined type?
+ */
+ 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 +644,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 +666,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
