From 171ce2bd03f846e7ba3e6972b1f51a432d5f75c5 Mon Sep 17 00:00:00 2001 From: Ashutosh Bapat Date: Wed, 23 Aug 2023 16:23:12 +0530 Subject: [PATCH 2/3] Report memory allocated along with memory used in EXPLAIN Memory might be pallc'ed and pfree'ed during planning. The memory used at the end of planning may miss a large chunk of memory palloc'ed and pfree'ed during planning. But the corresponding memory may remain allocated in the memory context. Hence report both memory used and memory allocated to detect any such activity during planning. Ashutosh Bapat, per suggestion by David Rowley --- src/backend/commands/explain.c | 69 +++++++++++++++++++++++---- src/backend/commands/prepare.c | 12 +++-- src/backend/utils/mmgr/mcxt.c | 13 ++--- src/include/commands/explain.h | 11 ++++- src/include/utils/memutils.h | 3 +- src/test/regress/expected/explain.out | 25 +++++++--- src/tools/pgindent/typedefs.list | 1 + 7 files changed, 103 insertions(+), 31 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index dfa4447794..efc4887244 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_planning_memory(ExplainState *es, + const MemUsage *usage); static void ExplainIndexScanDetails(Oid indexid, ScanDirection indexorderdir, ExplainState *es); static void ExplainScanTarget(Scan *plan, ExplainState *es); @@ -397,11 +399,13 @@ ExplainOneQuery(Query *query, int cursorOptions, planduration; BufferUsage bufusage_start, bufusage; - Size mem_consumed; + MemoryContextCounters mem_counts_start; + MemoryContextCounters mem_counts_end; + MemUsage mem_usage; if (es->buffers) bufusage_start = pgBufferUsage; - mem_consumed = MemoryContextMemUsed(CurrentMemoryContext); + MemoryContextMemConsumed(CurrentMemoryContext, &mem_counts_start); INSTR_TIME_SET_CURRENT(planstart); /* plan the query */ @@ -409,8 +413,8 @@ ExplainOneQuery(Query *query, int cursorOptions, INSTR_TIME_SET_CURRENT(planduration); INSTR_TIME_SUBTRACT(planduration, planstart); - mem_consumed = MemoryContextMemUsed(CurrentMemoryContext) - - mem_consumed; + MemoryContextMemConsumed(CurrentMemoryContext, &mem_counts_end); + calc_mem_usage(&mem_usage, &mem_counts_end, &mem_counts_start); /* calc differences of buffer counters. */ if (es->buffers) @@ -422,7 +426,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), - &mem_consumed); + &mem_usage); } } @@ -532,7 +536,7 @@ void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, const char *queryString, ParamListInfo params, QueryEnvironment *queryEnv, const instr_time *planduration, - const BufferUsage *bufusage, const Size *mem_consumed) + const BufferUsage *bufusage, const MemUsage *mem_usage) { DestReceiver *dest; QueryDesc *queryDesc; @@ -635,9 +639,12 @@ 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); + if (es->summary && mem_usage) + { + ExplainOpenGroup("Planning Memory", "Planning Memory", true, es); + show_planning_memory(es, mem_usage); + ExplainCloseGroup("Planning Memory", "Planning Memory", true, es); + } /* Print info about runtime of triggers */ if (es->analyze) @@ -3775,6 +3782,50 @@ show_wal_usage(ExplainState *es, const WalUsage *usage) } } +/* + * Show planner's memory usage details. + */ +static void +show_planning_memory(ExplainState *es, const MemUsage *usage) +{ + if (es->format == EXPLAIN_FORMAT_TEXT) + { + appendStringInfo(es->str, + "Planning Memory: used=%zu bytes allocated=%zu bytes", + usage->mem_used, usage->mem_allocated); + appendStringInfoChar(es->str, '\n'); + } + else + { + ExplainPropertyInteger("Used", "bytes", usage->mem_used, es); + ExplainPropertyInteger("Allocated", "bytes", usage->mem_allocated, es); + } +} + +/* + * Compute memory usage from the start and end memory counts. + */ +void +calc_mem_usage(MemUsage *mem_usage, MemoryContextCounters *mem_counts_end, + MemoryContextCounters *mem_counts_start) +{ + Size mem_used_start; + Size mem_used_end; + + mem_used_start = mem_counts_start->totalspace - mem_counts_start->freespace; + mem_used_end = mem_counts_end->totalspace - mem_counts_end->freespace; + + mem_usage->mem_used = mem_used_end - mem_used_start; + + /* + * The net memory used is from total memory allocated and not necessarily + * the net memory allocated between the two given samples. Hence do not + * compute the difference between allocated memory reported in the two + * given samples. + */ + mem_usage->mem_allocated = mem_counts_end->totalspace; +} + /* * Add some additional details about an IndexScan or IndexOnlyScan */ diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c index ccae1b4477..ebc0d47ba9 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -583,11 +583,13 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, instr_time planduration; BufferUsage bufusage_start, bufusage; - Size mem_consumed; + MemoryContextCounters mem_counts_start; + MemoryContextCounters mem_counts_end; + MemUsage mem_usage; if (es->buffers) bufusage_start = pgBufferUsage; - mem_consumed = MemoryContextMemUsed(CurrentMemoryContext); + MemoryContextMemConsumed(CurrentMemoryContext, &mem_counts_start); INSTR_TIME_SET_CURRENT(planstart); /* Look it up in the hash table */ @@ -625,8 +627,8 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, INSTR_TIME_SET_CURRENT(planduration); INSTR_TIME_SUBTRACT(planduration, planstart); - mem_consumed = MemoryContextMemUsed(CurrentMemoryContext) - - mem_consumed; + MemoryContextMemConsumed(CurrentMemoryContext, &mem_counts_end); + calc_mem_usage(&mem_usage, &mem_counts_end, &mem_counts_start); /* calc differences of buffer counters. */ if (es->buffers) @@ -645,7 +647,7 @@ 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), - &mem_consumed); + &mem_usage); 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 1ea966b186..94159a6799 100644 --- a/src/backend/utils/mmgr/mcxt.c +++ b/src/backend/utils/mmgr/mcxt.c @@ -750,16 +750,13 @@ MemoryContextStatsDetail(MemoryContext context, int max_children, /* * Return the memory used in the given context and its children. */ -extern Size -MemoryContextMemUsed(MemoryContext context) +extern void +MemoryContextMemConsumed(MemoryContext context, + MemoryContextCounters *mem_consumed) { - MemoryContextCounters grand_totals; - - memset(&grand_totals, 0, sizeof(grand_totals)); - - MemoryContextStatsInternal(context, 0, false, 100, &grand_totals, false); + memset(mem_consumed, 0, sizeof(*mem_consumed)); - return grand_totals.totalspace - grand_totals.freespace; + MemoryContextStatsInternal(context, 0, false, 100, mem_consumed, false); } /* diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 381476836e..05dcb91c49 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -62,6 +62,12 @@ typedef struct ExplainState ExplainWorkersState *workers_state; /* needed if parallel plan */ } ExplainState; +typedef struct MemUsage +{ + Size mem_used; + Size mem_allocated; +} MemUsage; + /* Hook for plugins to get control in ExplainOneQuery() */ typedef void (*ExplainOneQuery_hook_type) (Query *query, int cursorOptions, @@ -93,7 +99,7 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ParamListInfo params, QueryEnvironment *queryEnv, const instr_time *planduration, const BufferUsage *bufusage, - const Size *mem_consumed); + const MemUsage *mem_usage); extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc); extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc); @@ -126,5 +132,8 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname, bool labeled, ExplainState *es); extern void ExplainCloseGroup(const char *objtype, const char *labelname, bool labeled, ExplainState *es); +extern void calc_mem_usage(MemUsage *mem_usage, + MemoryContextCounters *mem_counts_end, + MemoryContextCounters *mem_counts_start); #endif /* EXPLAIN_H */ diff --git a/src/include/utils/memutils.h b/src/include/utils/memutils.h index d7c477f229..d254a044c1 100644 --- a/src/include/utils/memutils.h +++ b/src/include/utils/memutils.h @@ -92,7 +92,8 @@ extern void MemoryContextStatsDetail(MemoryContext context, int max_children, bool print_to_stderr); extern void MemoryContextAllowInCriticalSection(MemoryContext context, bool allow); -extern Size MemoryContextMemUsed(MemoryContext context); +extern void MemoryContextMemConsumed(MemoryContext context, + MemoryContextCounters *mem_consumed); #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 2179cd4b5e..e4b1aa7fdf 100644 --- a/src/test/regress/expected/explain.out +++ b/src/test/regress/expected/explain.out @@ -65,7 +65,7 @@ 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 + Planning Memory: used=N bytes allocated=N bytes Execution Time: N.N ms (4 rows) @@ -75,7 +75,7 @@ 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 + Planning Memory: used=N bytes allocated=N bytes Execution Time: N.N ms (5 rows) @@ -84,7 +84,7 @@ select explain_filter('explain (analyze, buffers, format text) select * from int ----------------------------------------------------------------------------------------------- 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 + Planning Memory: used=N bytes allocated=N bytes Execution Time: N.N ms (4 rows) @@ -131,7 +131,10 @@ select explain_filter('explain (analyze, buffers, format xml) select * from int8 N + + N.N + - N + + + + N + + N + + + + + N.N + @@ -178,7 +181,9 @@ 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 + + Planning Memory: + + Used: N + + Allocated: N + Triggers: + Execution Time: N.N (1 row) @@ -289,7 +294,10 @@ 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, + + "Planning Memory": { + + "Used": N, + + "Allocated": N + + }, + "Triggers": [ + ], + "Execution Time": N.N + @@ -542,7 +550,10 @@ select jsonb_pretty( ], + "Planning Time": 0.0, + "Execution Time": 0.0, + - "Planning Memory": 0 + + "Planning Memory": { + + "Used": 0, + + "Allocated": 0 + + } + } + ] (1 row) diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list index 87c1aee379..bcc2f48efd 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -1547,6 +1547,7 @@ MemoryContextData MemoryContextMethodID MemoryContextMethods MemoryStatsPrintFunc +MemUsage MergeAction MergeActionState MergeAppend -- 2.25.1