From 5de890e3610d5a12cdaea36413d967cf5c544e20 Mon Sep 17 00:00:00 2001 From: Alvaro Herrera Date: Mon, 29 Jan 2024 17:53:03 +0100 Subject: [PATCH] Add EXPLAIN (MEMORY) to report planner memory consumption MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This adds a new "Memory:" line under the "Planning:" group (which currently only has "Buffers:") when the MEMORY option is specified. In order to make the reporting reasonably accurate, we create a separate memory context for planner activities, to be used only when this option is given. The total amount of memory allocated by that context is reported as "allocated"; we subtract memory in the context's freelists from that and report that result as "used". We use MemoryContextStatsInternal() to obtain the quantities. The code structure to show buffer usage during planning was not in amazing shape, so I (Álvaro) modified the patch a bit to clean that up in passing. Author: Ashutosh Bapat Reviewed-by: David Rowley, Andrey Lepikhov, Jian He, Andy Fan Discussion: https://www.postgresql.org/message-id/CAExHW5sZA=5LJ_ZPpRO-w09ck8z9p7eaYAqq3Ks9GDfhrxeWBw@mail.gmail.com --- contrib/auto_explain/auto_explain.c | 2 + doc/src/sgml/ref/explain.sgml | 14 +++ src/backend/commands/explain.c | 152 +++++++++++++++++++++----- src/backend/commands/prepare.c | 22 +++- 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 | 76 +++++++++++++ src/test/regress/sql/explain.sql | 8 ++ 9 files changed, 265 insertions(+), 28 deletions(-) diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index c7aacd7812..677c135f59 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 */ + /* 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..a4b6564bdb 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -44,6 +44,7 @@ EXPLAIN [ ( option [, ...] ) ] boolean ] TIMING [ boolean ] SUMMARY [ boolean ] + MEMORY [ boolean ] FORMAT { TEXT | XML | JSON | YAML } @@ -250,6 +251,19 @@ ROLLBACK; + + MEMORY + + + 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. + This parameter defaults to FALSE. + + + + FORMAT diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 843472e6dd..83d00a4663 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -119,9 +119,11 @@ static void show_instrumentation_count(const char *qlabel, int which, static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es); static void show_eval_params(Bitmapset *bms_params, ExplainState *es); static const char *explain_get_index_name(Oid indexId); -static void show_buffer_usage(ExplainState *es, const BufferUsage *usage, - bool planning); +static bool peek_buffer_usage(ExplainState *es, const BufferUsage *usage); +static void show_buffer_usage(ExplainState *es, const BufferUsage *usage); static void show_wal_usage(ExplainState *es, const WalUsage *usage); +static void show_memory_counters(ExplainState *es, + const MemoryContextCounters *mem_counters); 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,25 @@ ExplainOneQuery(Query *query, int cursorOptions, planduration; BufferUsage bufusage_start, bufusage; + MemoryContextCounters mem_counters; + MemoryContext planner_ctx = NULL; + MemoryContext saved_ctx = NULL; + + if (es->memory) + { + /* + * Create a new memory context to measure planner's memory + * consumption accurately. Note that if the planner were to be + * modified to use a different memory context type, here we would + * be changing that to AllocSet, which might be undesirable. + * However, we don't have a way to create a context of the same + * type as another, so we pray and hope that this is OK. + */ + planner_ctx = AllocSetContextCreate(CurrentMemoryContext, + "explain analyze planner context", + ALLOCSET_DEFAULT_SIZES); + saved_ctx = MemoryContextSwitchTo(planner_ctx); + } if (es->buffers) bufusage_start = pgBufferUsage; @@ -408,6 +431,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_counters); + } + /* calc differences of buffer counters. */ if (es->buffers) { @@ -417,7 +446,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_counters : NULL); } } @@ -527,7 +557,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_counters) { DestReceiver *dest; QueryDesc *queryDesc; @@ -615,11 +646,27 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, /* Create textual dump of plan tree */ ExplainPrintPlan(es, queryDesc); - /* Show buffer usage in planning */ - if (bufusage) + /* Show buffer and/or memory usage in planning */ + if (peek_buffer_usage(es, bufusage) || mem_counters) { ExplainOpenGroup("Planning", "Planning", true, es); - show_buffer_usage(es, bufusage, true); + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + ExplainIndentText(es); + appendStringInfoString(es->str, "Planning:\n"); + es->indent++; + } + + if (bufusage) + show_buffer_usage(es, bufusage); + + if (mem_counters) + show_memory_counters(es, mem_counters); + + if (es->format == EXPLAIN_FORMAT_TEXT) + es->indent--; + ExplainCloseGroup("Planning", "Planning", true, es); } @@ -2106,7 +2153,7 @@ ExplainNode(PlanState *planstate, List *ancestors, /* Show buffer/WAL usage */ if (es->buffers && planstate->instrument) - show_buffer_usage(es, &planstate->instrument->bufusage, false); + show_buffer_usage(es, &planstate->instrument->bufusage); if (es->wal && planstate->instrument) show_wal_usage(es, &planstate->instrument->walusage); @@ -2125,7 +2172,7 @@ ExplainNode(PlanState *planstate, List *ancestors, ExplainOpenWorker(n, es); if (es->buffers) - show_buffer_usage(es, &instrument->bufusage, false); + show_buffer_usage(es, &instrument->bufusage); if (es->wal) show_wal_usage(es, &instrument->walusage); ExplainCloseWorker(n, es); @@ -3545,10 +3592,52 @@ explain_get_index_name(Oid indexId) } /* - * Show buffer usage details. + * Return whether show_buffer_usage would have anything to print, if given + * the same 'usage' data. Note that when the format is anything other than + * text, we print even if the counters are all zeroes. + */ +static bool +peek_buffer_usage(ExplainState *es, const BufferUsage *usage) +{ + bool has_shared; + bool has_local; + bool has_temp; + bool has_shared_timing; + bool has_local_timing; + bool has_temp_timing; + + if (usage == NULL) + return false; + + if (es->format != EXPLAIN_FORMAT_TEXT) + return true; + + has_shared = (usage->shared_blks_hit > 0 || + usage->shared_blks_read > 0 || + usage->shared_blks_dirtied > 0 || + usage->shared_blks_written > 0); + has_local = (usage->local_blks_hit > 0 || + usage->local_blks_read > 0 || + usage->local_blks_dirtied > 0 || + usage->local_blks_written > 0); + has_temp = (usage->temp_blks_read > 0 || + usage->temp_blks_written > 0); + has_shared_timing = (!INSTR_TIME_IS_ZERO(usage->shared_blk_read_time) || + !INSTR_TIME_IS_ZERO(usage->shared_blk_write_time)); + has_local_timing = (!INSTR_TIME_IS_ZERO(usage->local_blk_read_time) || + !INSTR_TIME_IS_ZERO(usage->local_blk_write_time)); + has_temp_timing = (!INSTR_TIME_IS_ZERO(usage->temp_blk_read_time) || + !INSTR_TIME_IS_ZERO(usage->temp_blk_write_time)); + + return has_shared || has_local || has_temp || has_shared_timing || + has_local_timing || has_temp_timing; +} + +/* + * Show buffer usage details. This better be sync with peek_buffer_usage. */ static void -show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning) +show_buffer_usage(ExplainState *es, const BufferUsage *usage) { if (es->format == EXPLAIN_FORMAT_TEXT) { @@ -3568,18 +3657,6 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning) !INSTR_TIME_IS_ZERO(usage->local_blk_write_time)); bool has_temp_timing = (!INSTR_TIME_IS_ZERO(usage->temp_blk_read_time) || !INSTR_TIME_IS_ZERO(usage->temp_blk_write_time)); - bool show_planning = (planning && (has_shared || - has_local || has_temp || - has_shared_timing || - has_local_timing || - has_temp_timing)); - - if (show_planning) - { - ExplainIndentText(es); - appendStringInfoString(es->str, "Planning:\n"); - es->indent++; - } /* Show only positive counter values. */ if (has_shared || has_local || has_temp) @@ -3678,9 +3755,6 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning) } appendStringInfoChar(es->str, '\n'); } - - if (show_planning) - es->indent--; } else { @@ -3766,6 +3840,32 @@ show_wal_usage(ExplainState *es, const WalUsage *usage) } } +/* + * Show memory usage details. + */ +static void +show_memory_counters(ExplainState *es, const MemoryContextCounters *mem_counters) +{ + if (es->format == EXPLAIN_FORMAT_TEXT) + { + ExplainIndentText(es); + appendStringInfo(es->str, + "Memory: used=%lld bytes allocated=%lld bytes", + (long long) (mem_counters->totalspace - mem_counters->freespace), + (long long) mem_counters->totalspace); + appendStringInfoChar(es->str, '\n'); + } + else + { + ExplainPropertyInteger("Memory Used", "bytes", + mem_counters->totalspace - mem_counters->freespace, + es); + ExplainPropertyInteger("Memory Allocated", "bytes", + mem_counters->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 703976f633..bf1579d36d 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -583,6 +583,19 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, instr_time planduration; BufferUsage bufusage_start, bufusage; + MemoryContextCounters mem_counters; + MemoryContext planner_ctx = NULL; + MemoryContext saved_ctx = NULL; + + if (es->memory) + { + /* See ExplainOneQuery about this */ + 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 +637,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_counters); + } + /* calc differences of buffer counters. */ if (es->buffers) { @@ -640,7 +659,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_counters : 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 1336944084..ad7409a02c 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 1b44d483d6..7c0f0b5636 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_counters); 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 ca7858d6b6..7fd41d20ca 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..1299ee79ad 100644 --- a/src/test/regress/expected/explain.out +++ b/src/test/regress/expected/explain.out @@ -326,6 +326,82 @@ 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) + 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) + Memory: used=N bytes allocated=N bytes + Planning Time: N.N ms + 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: + + Memory Used: N + + Memory Allocated: N + + Planning Time: N.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": { + + "Memory Used": N, + + "Memory Allocated": N + + }, + + "Planning Time": N.N, + + "Triggers": [ + + ], + + "Execution Time": N.N + + } + + ] +(1 row) + +prepare int8_query as select * from int8_tbl i8; +select explain_filter('explain (memory) execute int8_query'); + explain_filter +--------------------------------------------------------- + Seq Scan on int8_tbl i8 (cost=N.N..N.N rows=N width=N) + Memory: used=N bytes allocated=N bytes +(2 rows) + -- 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..2274dc1b5a 100644 --- a/src/test/regress/sql/explain.sql +++ b/src/test/regress/sql/explain.sql @@ -94,6 +94,14 @@ 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'); +prepare int8_query as select * from int8_tbl i8; +select explain_filter('explain (memory) execute int8_query'); + -- 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