Hi All,
I have been looking at memory consumed when planning a partitionwise join
[1], [2] and [3]. I am using the attached patch to measure the memory
consumption. The patch has been useful to detect an increased memory
consumption in other patches e.g. [4] and [5]. The patch looks useful by
itself. So I propose this enhancement in EXPLAIN ANALYZE.
Comments/suggestions welcome.
[1]
https://www.postgresql.org/message-id/caexhw5thqef3asvqvffcghygpfpy7o3xnvhhwbgbjfmrh8k...@mail.gmail.com
[2]
https://www.postgresql.org/message-id/CAExHW5tUcVsBkq9qT=L5vYz4e-cwQNw=KAGJrtSyzOp3F=x...@mail.gmail.com
[3]
https://www.postgresql.org/message-id/CAExHW5s=bclmmq8n_bn6iu+pjau0ds3z_6dn6ile69esmsp...@mail.gmail.com
[4]
https://www.postgresql.org/message-id/CAExHW5uVZ3E5RT9cXHaxQ_DEK7tasaMN=d6rphcao5gcxan...@mail.gmail.com
[5]
https://www.postgresql.org/message-id/CAExHW5s4EqY43oB=ne6B2=-xlgrs9zgetr1nxwkgft2j-om...@mail.gmail.com
--
Best Wishes,
Ashutosh Bapat
From 1dcadcc9cb38702f9e8882bf16173715982e36da 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] Report memory used for planning a query in EXPLAIN ANALYZE
The memory used in the CurrentMemoryContext and its children is noted
before and after calling pg_plan_query() from ExplainOneQuery(). The
difference in the two values is reported as the memory consumed while
planning the query. This may not account for the memory allocated in
memory contexts which are not children of CurrentMemoryContext when
calling pg_plan_query(). These contexts are usually other long lived
contexts, e.g. CacheMemoryContext, which are shared by all the queries
run in a session. The consumption in those can not be attributed only to
a given query and hence should not be reported any way.
The memory consumption is reported as "Planning Memory" property in
EXPLAIN ANALYZE output.
Ashutosh Bapat
---
src/backend/commands/explain.c | 13 +++++++++++--
src/backend/commands/prepare.c | 7 ++++++-
src/backend/utils/mmgr/mcxt.c | 15 +++++++++++++++
src/include/commands/explain.h | 3 ++-
src/include/utils/memutils.h | 1 +
src/test/regress/expected/explain.out | 15 +++++++++++----
6 files changed, 46 insertions(+), 8 deletions(-)
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 8570b14f62..34a1c91488 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -397,16 +397,20 @@ ExplainOneQuery(Query *query, int cursorOptions,
planduration;
BufferUsage bufusage_start,
bufusage;
+ Size mem_consumed;
if (es->buffers)
bufusage_start = pgBufferUsage;
INSTR_TIME_SET_CURRENT(planstart);
+ mem_consumed = MemoryContextMemUsed(CurrentMemoryContext);
/* plan the query */
plan = pg_plan_query(query, queryString, cursorOptions, params);
INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);
+ mem_consumed = MemoryContextMemUsed(CurrentMemoryContext)
+ - mem_consumed;
/* calc differences of buffer counters. */
if (es->buffers)
@@ -417,7 +421,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),
+ &mem_consumed);
}
}
@@ -527,7 +532,7 @@ 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 Size *mem_consumed)
{
DestReceiver *dest;
QueryDesc *queryDesc;
@@ -628,6 +633,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
double plantime = INSTR_TIME_GET_DOUBLE(*planduration);
ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es);
+
+ if (mem_consumed)
+ ExplainPropertyUInteger("Planning Memory", "bytes",
+ (uint64) *mem_consumed, es);
}
/* Print info about runtime of triggers */
diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c
index 18f70319fc..84544ce481 100644
--- a/src/backend/commands/prepare.c
+++ b/src/backend/commands/prepare.c
@@ -583,10 +583,12 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
instr_time planduration;
BufferUsage bufusage_start,
bufusage;
+ Size mem_consumed;
if (es->buffers)
bufusage_start = pgBufferUsage;
INSTR_TIME_SET_CURRENT(planstart);
+ mem_consumed = MemoryContextMemUsed(CurrentMemoryContext);
/* Look it up in the hash table */
entry = FetchPreparedStatement(execstmt->name, true);
@@ -623,6 +625,8 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);
+ mem_consumed = MemoryContextMemUsed(CurrentMemoryContext)
+ - mem_consumed;
/* calc differences of buffer counters. */
if (es->buffers)
@@ -640,7 +644,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),
+ &mem_consumed);
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..1ea966b186 100644
--- a/src/backend/utils/mmgr/mcxt.c
+++ b/src/backend/utils/mmgr/mcxt.c
@@ -747,6 +747,21 @@ MemoryContextStatsDetail(MemoryContext context, int max_children,
grand_totals.totalspace - grand_totals.freespace)));
}
+/*
+ * Return the memory used in the given context and its children.
+ */
+extern Size
+MemoryContextMemUsed(MemoryContext context)
+{
+ MemoryContextCounters grand_totals;
+
+ memset(&grand_totals, 0, sizeof(grand_totals));
+
+ MemoryContextStatsInternal(context, 0, false, 100, &grand_totals, false);
+
+ return grand_totals.totalspace - grand_totals.freespace;
+}
+
/*
* MemoryContextStatsInternal
* One recursion level for MemoryContextStats
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3d3e632a0c..21e3d2f309 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -92,7 +92,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 Size *mem_consumed);
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 21640d62a6..d7c477f229 100644
--- a/src/include/utils/memutils.h
+++ b/src/include/utils/memutils.h
@@ -92,6 +92,7 @@ extern void MemoryContextStatsDetail(MemoryContext context, int max_children,
bool print_to_stderr);
extern void MemoryContextAllowInCriticalSection(MemoryContext context,
bool allow);
+extern Size MemoryContextMemUsed(MemoryContext context);
#ifdef MEMORY_CONTEXT_CHECKING
extern void MemoryContextCheck(MemoryContext context);
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 1aca77491b..123ab22f5d 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -65,8 +65,9 @@ select explain_filter('explain (analyze) select * from int8_tbl i8');
-----------------------------------------------------------------------------------------------
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
+ Planning Memory: N bytes
Execution Time: N.N ms
-(3 rows)
+(4 rows)
select explain_filter('explain (analyze, verbose) select * from int8_tbl i8');
explain_filter
@@ -74,16 +75,18 @@ select explain_filter('explain (analyze, verbose) select * from int8_tbl i8');
Seq Scan on public.int8_tbl i8 (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
Output: q1, q2
Planning Time: N.N ms
+ Planning Memory: N bytes
Execution Time: N.N ms
-(4 rows)
+(5 rows)
select explain_filter('explain (analyze, buffers, format text) 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
+ Planning Memory: N bytes
Execution Time: N.N ms
-(3 rows)
+(4 rows)
select explain_filter('explain (analyze, buffers, format xml) select * from int8_tbl i8');
explain_filter
@@ -128,6 +131,7 @@ select explain_filter('explain (analyze, buffers, format xml) select * from int8
<Temp-Written-Blocks>N</Temp-Written-Blocks> +
</Planning> +
<Planning-Time>N.N</Planning-Time> +
+ <Planning-Memory>N</Planning-Memory> +
<Triggers> +
</Triggers> +
<Execution-Time>N.N</Execution-Time> +
@@ -174,6 +178,7 @@ select explain_filter('explain (analyze, buffers, format yaml) select * from int
Temp Read Blocks: N +
Temp Written Blocks: N +
Planning Time: N.N +
+ Planning Memory: N +
Triggers: +
Execution Time: N.N
(1 row)
@@ -280,6 +285,7 @@ select explain_filter('explain (analyze, buffers, format json) select * from int
"Temp I/O Write Time": N.N +
}, +
"Planning Time": N.N, +
+ "Planning Memory": N, +
"Triggers": [ +
], +
"Execution Time": N.N +
@@ -531,7 +537,8 @@ select jsonb_pretty(
"Triggers": [ +
], +
"Planning Time": 0.0, +
- "Execution Time": 0.0 +
+ "Execution Time": 0.0, +
+ "Planning Memory": 0 +
} +
]
(1 row)
--
2.25.1
