From a236f4dd6c518d5338b9664ffdb69203165595df Mon Sep 17 00:00:00 2001 From: Ashutosh Bapat Date: Wed, 12 Jul 2023 14:34:14 +0530 Subject: [PATCH 1/3] Report memory used for planning a query in EXPLAIN The memory used is reported as "Planning Memory" property in EXPLAIN output when any of options ANALYZE or SUMMARY is specified. 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 reported can be used to detect any large variations in memory consumption during planning. 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 f1d71bc54e..dfa4447794 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -397,9 +397,11 @@ ExplainOneQuery(Query *query, int cursorOptions, planduration; BufferUsage bufusage_start, bufusage; + Size mem_consumed; if (es->buffers) bufusage_start = pgBufferUsage; + mem_consumed = MemoryContextMemUsed(CurrentMemoryContext); INSTR_TIME_SET_CURRENT(planstart); /* plan the query */ @@ -407,6 +409,8 @@ ExplainOneQuery(Query *query, int cursorOptions, 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; @@ -630,6 +635,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es); } + if (es->summary && mem_consumed) + ExplainPropertyUInteger("Planning Memory", "bytes", + (uint64) *mem_consumed, 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 18f70319fc..ccae1b4477 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -583,9 +583,11 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, instr_time planduration; BufferUsage bufusage_start, bufusage; + Size mem_consumed; if (es->buffers) bufusage_start = pgBufferUsage; + mem_consumed = MemoryContextMemUsed(CurrentMemoryContext); INSTR_TIME_SET_CURRENT(planstart); /* Look it up in the hash table */ @@ -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 f9525fb572..381476836e 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 809655e16e..2179cd4b5e 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 N + + N.N + + N + + + N.N + @@ -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) @@ -284,6 +289,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 + @@ -535,7 +541,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