From 670a84a4281b7e17a3a61df0ce0737daff94840f Mon Sep 17 00:00:00 2001 From: Ashutosh Bapat Date: Wed, 12 Jul 2023 14:34:14 +0530 Subject: [PATCH 1/2] Report memory used for planning a query in EXPLAIN ANALYZE The memory used in the CurrentMemoryContext and its children is sampled before and after calling pg_plan_query() from ExplainOneQuery(). The difference in the two samples 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. 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 | 12 ++++++++++-- src/backend/commands/prepare.c | 7 ++++++- src/backend/utils/mmgr/mcxt.c | 19 +++++++++++++++++++ src/include/commands/explain.h | 3 ++- src/include/utils/memutils.h | 1 + src/test/regress/expected/explain.out | 15 +++++++++++---- 6 files changed, 49 insertions(+), 8 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 8570b14f62..9f859949f0 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,7 @@ 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 +531,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 +632,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..43af271f33 100644 --- a/src/backend/utils/mmgr/mcxt.c +++ b/src/backend/utils/mmgr/mcxt.c @@ -747,6 +747,25 @@ MemoryContextStatsDetail(MemoryContext context, int max_children, grand_totals.totalspace - grand_totals.freespace))); } +/* + * Compute the memory used in the given context and its children. + * + * XXX: Instead of this separate function we could modify + * MemoryContextStatsDetail() to report used memory and disable printing the + * detailed stats. + */ +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 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) @@ -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