public inbox for [email protected]help / color / mirror / Atom feed
Re: Report planning memory in EXPLAIN ANALYZE 4+ messages / 4 participants [nested] [flat]
* Re: Report planning memory in EXPLAIN ANALYZE @ 2023-09-25 03:35 Andy Fan <[email protected]> 0 siblings, 1 reply; 4+ messages in thread From: Andy Fan @ 2023-09-25 03:35 UTC (permalink / raw) To: Ashutosh Bapat <[email protected]>; +Cc: Lepikhov Andrei <[email protected]>; jian he <[email protected]>; David Rowley <[email protected]>; PostgreSQL Hackers <[email protected]> Hi Ashutosh, On Fri, Sep 22, 2023 at 5:56 PM Ashutosh Bapat <[email protected]> wrote: > Hi Andy, > Thanks for your feedback. > > On Fri, Sep 22, 2023 at 8:22 AM Andy Fan <[email protected]> wrote: > > > > 1). The commit message of patch 1 just says how it does but doesn't > > say why it does. After reading through the discussion, I suggest making > > it clearer to others. > > > > ... > > After the planning is done, it may still occupy lots of memory which is > > allocated but not pfree-d. All of these memories can't be used in the > later > > stage. This patch will report such memory usage in order to making some > > future mistakes can be found in an easier way. > > ... > > That's a good summary of how the memory report can be used. Will > include a line about usage in the commit message. > > > > > Planning Memory: used=15088 bytes allocated=16384 bytes > > > > Word 'Planning' is kind of a time duration, so the 'used' may be the > > 'used' during the duration or 'used' after the duration. Obviously you > > means the later one but it is not surprising others think it in the other > > way. So I'd like to reword the metrics to: > > We report "PLanning Time" hence used "Planning memory". Would > "Planner" be good instead of "Planning"? > I agree "Planner" is better than "Planning" personally. > > > Memory Occupied (Now): Parser: 1k Planner: 10k > > > > 'Now' is a cleaner signal that is a time point rather than a time > > duration. 'Parser' and 'Planner' also show a timeline about the > > important time point. At the same time, it cost very little coding > > effort based on patch 01. Different people may have different > > feelings about these words, I just hope I describe the goal clearly. > > Parsing happens before planning and that memory is not measured by > this patch. May be separately but it's out of scope of this work. > "used" and "allocated" are MemoryContext terms indicating memory > actually used vs memory allocated. Yes, I understand the terms come from MemoryContext, the complex thing here is between time duration vs time point case. Since English is not my native language, so I'm not too confident about insisting on this. So I think we can keep it as it is. > > > > Personally I am pretty like patch 1, we just need to refactor some words > > to make everything clearer. > > Thanks. > David challenged something at the begining, but IIUC he also agree the value of patch 01 as the previous statement after discussion. Since the patch is mild itself, so I will mark this commitfest entry as "Ready for committer". Please correct me if anything is wrong. -- Best Regards Andy Fan ^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: Report planning memory in EXPLAIN ANALYZE @ 2023-10-30 14:43 Ashutosh Bapat <[email protected]> parent: Andy Fan <[email protected]> 0 siblings, 1 reply; 4+ messages in thread From: Ashutosh Bapat @ 2023-10-30 14:43 UTC (permalink / raw) To: Andy Fan <[email protected]>; +Cc: Lepikhov Andrei <[email protected]>; jian he <[email protected]>; David Rowley <[email protected]>; PostgreSQL Hackers <[email protected]> > > > David challenged something at the begining, but IIUC he also agree the > value of patch 01 as the previous statement after discussion. Since the patch > is mild itself, so I will mark this commitfest entry as "Ready for committer". > Please correct me if anything is wrong. > Thanks Andy. Here's rebased patches. A conflict in explain.out resolved. -- Best Wishes, Ashutosh Bapat Attachments: [text/x-patch] 0002-Report-memory-allocated-along-with-memory-u-20231030.patch (13.8K, ../../CAExHW5sCJX7696sF-OnugAiaXS=Ag95=-m1cSrjcmyYj8Pduuw@mail.gmail.com/2-0002-Report-memory-allocated-along-with-memory-u-20231030.patch) download | inline diff: From 171ce2bd03f846e7ba3e6972b1f51a432d5f75c5 Mon Sep 17 00:00:00 2001 From: Ashutosh Bapat <[email protected]> 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 <Temp-Written-Blocks>N</Temp-Written-Blocks> + </Planning> + <Planning-Time>N.N</Planning-Time> + - <Planning-Memory>N</Planning-Memory> + + <Planning-Memory> + + <Used>N</Used> + + <Allocated>N</Allocated> + + </Planning-Memory> + <Triggers> + </Triggers> + <Execution-Time>N.N</Execution-Time> + @@ -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 [text/x-patch] 0003-Separate-memory-context-for-planner-s-memor-20231030.patch (3.9K, ../../CAExHW5sCJX7696sF-OnugAiaXS=Ag95=-m1cSrjcmyYj8Pduuw@mail.gmail.com/3-0003-Separate-memory-context-for-planner-s-memor-20231030.patch) download | inline diff: From eb1e4ceca14572c7f2f3bf7500d83a21b872846e Mon Sep 17 00:00:00 2001 From: Ashutosh Bapat <[email protected]> Date: Wed, 23 Aug 2023 11:45:47 +0530 Subject: [PATCH 3/3] Separate memory context for planner's memory measurement EXPLAIN reports memory used and allocated in current memory context by the planner. The allocated memory may be influenced by the previous activity in the current memory context. Hence use a new memory context for planning the query and report statistics from that context. Ashutosh Bapat, per suggestion from David Rowley --- src/backend/commands/explain.c | 19 +++++++++++++++++-- src/backend/commands/prepare.c | 19 +++++++++++++++++-- 2 files changed, 34 insertions(+), 4 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index efc4887244..9cd9b577c7 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -402,10 +402,24 @@ ExplainOneQuery(Query *query, int cursorOptions, MemoryContextCounters mem_counts_start; MemoryContextCounters mem_counts_end; MemUsage mem_usage; + MemoryContext planner_ctx; + MemoryContext saved_ctx; + + /* + * Create a new memory context to accurately measure memory malloc'ed + * by the planner. For further accuracy we should use the same type of + * memory context as the planner would use. That's usually AllocSet + * but ensure that. + */ + Assert(IsA(CurrentMemoryContext, AllocSetContext)); + planner_ctx = AllocSetContextCreate(CurrentMemoryContext, + "explain analyze planner context", + ALLOCSET_DEFAULT_SIZES); if (es->buffers) bufusage_start = pgBufferUsage; - MemoryContextMemConsumed(CurrentMemoryContext, &mem_counts_start); + MemoryContextMemConsumed(planner_ctx, &mem_counts_start); + saved_ctx = MemoryContextSwitchTo(planner_ctx); INSTR_TIME_SET_CURRENT(planstart); /* plan the query */ @@ -413,7 +427,8 @@ ExplainOneQuery(Query *query, int cursorOptions, INSTR_TIME_SET_CURRENT(planduration); INSTR_TIME_SUBTRACT(planduration, planstart); - MemoryContextMemConsumed(CurrentMemoryContext, &mem_counts_end); + MemoryContextSwitchTo(saved_ctx); + MemoryContextMemConsumed(planner_ctx, &mem_counts_end); calc_mem_usage(&mem_usage, &mem_counts_end, &mem_counts_start); /* calc differences of buffer counters. */ diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c index ebc0d47ba9..eb39823d7a 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -586,10 +586,24 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, MemoryContextCounters mem_counts_start; MemoryContextCounters mem_counts_end; MemUsage mem_usage; + MemoryContext planner_ctx; + MemoryContext saved_ctx; + + /* + * Create a new memory context to accurately measure memory malloc'ed by + * the planner. For further accuracy we should use the same type of memory + * context as the planner would use. That's usually AllocSet but ensure + * that. + */ + Assert(IsA(CurrentMemoryContext, AllocSetContext)); + planner_ctx = AllocSetContextCreate(CurrentMemoryContext, + "explain analyze planner context", + ALLOCSET_DEFAULT_SIZES); if (es->buffers) bufusage_start = pgBufferUsage; - MemoryContextMemConsumed(CurrentMemoryContext, &mem_counts_start); + MemoryContextMemConsumed(planner_ctx, &mem_counts_start); + saved_ctx = MemoryContextSwitchTo(planner_ctx); INSTR_TIME_SET_CURRENT(planstart); /* Look it up in the hash table */ @@ -627,7 +641,8 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, INSTR_TIME_SET_CURRENT(planduration); INSTR_TIME_SUBTRACT(planduration, planstart); - MemoryContextMemConsumed(CurrentMemoryContext, &mem_counts_end); + MemoryContextSwitchTo(saved_ctx); + MemoryContextMemConsumed(planner_ctx, &mem_counts_end); calc_mem_usage(&mem_usage, &mem_counts_end, &mem_counts_start); /* calc differences of buffer counters. */ -- 2.25.1 [text/x-patch] 0001-Report-memory-used-for-planning-a-query-in--20231030.patch (10.0K, ../../CAExHW5sCJX7696sF-OnugAiaXS=Ag95=-m1cSrjcmyYj8Pduuw@mail.gmail.com/4-0001-Report-memory-used-for-planning-a-query-in--20231030.patch) download | inline diff: From a236f4dd6c518d5338b9664ffdb69203165595df Mon Sep 17 00:00:00 2001 From: Ashutosh Bapat <[email protected]> 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 <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) @@ -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 ^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: Report planning memory in EXPLAIN ANALYZE @ 2023-11-21 18:24 Alvaro Herrera <[email protected]> parent: Ashutosh Bapat <[email protected]> 0 siblings, 0 replies; 4+ messages in thread From: Alvaro Herrera @ 2023-11-21 18:24 UTC (permalink / raw) To: Ashutosh Bapat <[email protected]>; +Cc: Andy Fan <[email protected]>; Lepikhov Andrei <[email protected]>; jian he <[email protected]>; David Rowley <[email protected]>; PostgreSQL Hackers <[email protected]> I gave this a quick look. I think the usefulness aspect is already established in general terms; the bit I'm not so sure about is whether we want it enabled by default. For many cases it'd just be noise. Perhaps we want it hidden behind something like "EXPLAIN (MEMORY)" or such, particularly since things like "allocated" (which, per David, seems to be the really useful metric) seems too much a PG-developer value rather than an end-user value. If EXPLAIN (MEMORY) is added, then probably auto_explain needs a corresponding flag, and doc updates. Some code looks to be in weird places. Why is calc_mem_usage, which operates on MemoryContextCounters, in explain.c instead of mcxt.c? why is MemUsage in explain.h instead of memnodes.h? I moved both. I also renamed them, to MemoryContextSizeDifference() and MemoryUsage respectively; fixup patch attached. I see no reason for this to be three separate patches anymore. The EXPLAIN docs (explain.sgml) need an update to mention the new flag and the new output, too. -- Álvaro Herrera Breisgau, Deutschland — https://www.EnterpriseDB.com/ commit 48b0c6682a9e8cf07096b979693fac09b2f7a0ba Author: Alvaro Herrera <[email protected]> [Álvaro Herrera <[email protected]>] AuthorDate: Tue Nov 21 18:20:32 2023 +0100 CommitDate: Tue Nov 21 19:18:18 2023 +0100 review diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 9cd9b577c7..8c7f27b661 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -123,7 +123,7 @@ 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); + const MemoryUsage *usage); static void ExplainIndexScanDetails(Oid indexid, ScanDirection indexorderdir, ExplainState *es); static void ExplainScanTarget(Scan *plan, ExplainState *es); @@ -395,14 +395,14 @@ ExplainOneQuery(Query *query, int cursorOptions, else { PlannedStmt *plan; + MemoryContext planner_ctx; instr_time planstart, planduration; BufferUsage bufusage_start, bufusage; MemoryContextCounters mem_counts_start; MemoryContextCounters mem_counts_end; - MemUsage mem_usage; - MemoryContext planner_ctx; + MemoryUsage mem_usage; MemoryContext saved_ctx; /* @@ -415,7 +415,6 @@ ExplainOneQuery(Query *query, int cursorOptions, planner_ctx = AllocSetContextCreate(CurrentMemoryContext, "explain analyze planner context", ALLOCSET_DEFAULT_SIZES); - if (es->buffers) bufusage_start = pgBufferUsage; MemoryContextMemConsumed(planner_ctx, &mem_counts_start); @@ -429,7 +428,7 @@ ExplainOneQuery(Query *query, int cursorOptions, INSTR_TIME_SUBTRACT(planduration, planstart); MemoryContextSwitchTo(saved_ctx); MemoryContextMemConsumed(planner_ctx, &mem_counts_end); - calc_mem_usage(&mem_usage, &mem_counts_end, &mem_counts_start); + MemoryContextSizeDifference(&mem_usage, &mem_counts_start, &mem_counts_end); /* calc differences of buffer counters. */ if (es->buffers) @@ -551,7 +550,7 @@ void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, const char *queryString, ParamListInfo params, QueryEnvironment *queryEnv, const instr_time *planduration, - const BufferUsage *bufusage, const MemUsage *mem_usage) + const BufferUsage *bufusage, const MemoryUsage *mem_usage) { DestReceiver *dest; QueryDesc *queryDesc; @@ -656,9 +655,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, if (es->summary && mem_usage) { - ExplainOpenGroup("Planning Memory", "Planning Memory", true, es); + ExplainOpenGroup("Planner Memory", "Planner Memory", true, es); show_planning_memory(es, mem_usage); - ExplainCloseGroup("Planning Memory", "Planning Memory", true, es); + ExplainCloseGroup("Planner Memory", "Planner Memory", true, es); } /* Print info about runtime of triggers */ @@ -3801,45 +3800,22 @@ show_wal_usage(ExplainState *es, const WalUsage *usage) * Show planner's memory usage details. */ static void -show_planning_memory(ExplainState *es, const MemUsage *usage) +show_planning_memory(ExplainState *es, const MemoryUsage *usage) { if (es->format == EXPLAIN_FORMAT_TEXT) { appendStringInfo(es->str, - "Planning Memory: used=%zu bytes allocated=%zu bytes", - usage->mem_used, usage->mem_allocated); + "Planner Memory: used=%zu bytes allocated=%zu bytes", + usage->bytes_used, usage->bytes_allocated); appendStringInfoChar(es->str, '\n'); } else { - ExplainPropertyInteger("Used", "bytes", usage->mem_used, es); - ExplainPropertyInteger("Allocated", "bytes", usage->mem_allocated, es); + ExplainPropertyInteger("Used", "bytes", usage->bytes_used, es); + ExplainPropertyInteger("Allocated", "bytes", usage->bytes_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 eb39823d7a..3d3d0ae6a3 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -585,7 +585,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, bufusage; MemoryContextCounters mem_counts_start; MemoryContextCounters mem_counts_end; - MemUsage mem_usage; + MemoryUsage mem_usage; MemoryContext planner_ctx; MemoryContext saved_ctx; @@ -643,7 +643,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, INSTR_TIME_SUBTRACT(planduration, planstart); MemoryContextSwitchTo(saved_ctx); MemoryContextMemConsumed(planner_ctx, &mem_counts_end); - calc_mem_usage(&mem_usage, &mem_counts_end, &mem_counts_start); + MemoryContextSizeDifference(&mem_usage, &mem_counts_start, &mem_counts_end); /* calc differences of buffer counters. */ if (es->buffers) diff --git a/src/backend/utils/mmgr/mcxt.c b/src/backend/utils/mmgr/mcxt.c index 94159a6799..28e5f36405 100644 --- a/src/backend/utils/mmgr/mcxt.c +++ b/src/backend/utils/mmgr/mcxt.c @@ -687,6 +687,32 @@ MemoryContextMemAllocated(MemoryContext context, bool recurse) return total; } +/* + * Compute memory usage from the start and end memory counts. + */ +void +MemoryContextSizeDifference(MemoryUsage *mem_usage, + MemoryContextCounters *start, + MemoryContextCounters *end) +{ + /* + * We compute the memory "used" as the difference, between end situation + * and start situation, of the memory that's allocated according to the + * counters, excluding memory in freelists. + */ + mem_usage->bytes_used = + (end->totalspace - end->freespace) - + (start->totalspace - start->freespace); + + /* + * 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->bytes_allocated = end->totalspace; +} + /* * MemoryContextStats * Print statistics about the named context and all its descendants. @@ -752,11 +778,11 @@ MemoryContextStatsDetail(MemoryContext context, int max_children, */ extern void MemoryContextMemConsumed(MemoryContext context, - MemoryContextCounters *mem_consumed) + MemoryContextCounters *consumed) { - memset(mem_consumed, 0, sizeof(*mem_consumed)); + memset(consumed, 0, sizeof(*consumed)); - MemoryContextStatsInternal(context, 0, false, 100, mem_consumed, false); + MemoryContextStatsInternal(context, 0, false, 0, consumed, false); } /* diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 05dcb91c49..6947cbae8b 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -62,12 +62,6 @@ 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, @@ -99,7 +93,7 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ParamListInfo params, QueryEnvironment *queryEnv, const instr_time *planduration, const BufferUsage *bufusage, - const MemUsage *mem_usage); + const MemoryUsage *mem_usage); extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc); extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc); @@ -132,8 +126,5 @@ 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/nodes/memnodes.h b/src/include/nodes/memnodes.h index ff6453bb7a..577d39cef4 100644 --- a/src/include/nodes/memnodes.h +++ b/src/include/nodes/memnodes.h @@ -34,6 +34,16 @@ typedef struct MemoryContextCounters Size freespace; /* The unused portion of totalspace */ } MemoryContextCounters; +/* + * MemoryUsage + * For concise reporting of memory consumption + */ +typedef struct MemoryUsage +{ + Size bytes_used; + Size bytes_allocated; +} MemoryUsage; + /* * MemoryContext * A logical context in which memory allocations occur. diff --git a/src/include/utils/memutils.h b/src/include/utils/memutils.h index 50b9cc06e3..24dc0e996e 100644 --- a/src/include/utils/memutils.h +++ b/src/include/utils/memutils.h @@ -84,13 +84,16 @@ 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 MemoryContextSizeDifference(MemoryUsage *mem_usage, + MemoryContextCounters *start, + MemoryContextCounters *end); extern void MemoryContextStats(MemoryContext context); extern void MemoryContextStatsDetail(MemoryContext context, int max_children, bool print_to_stderr); extern void MemoryContextAllowInCriticalSection(MemoryContext context, bool allow); -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 e4b1aa7fdf..48e4ad1c3f 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: used=N bytes allocated=N bytes + Planner 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: used=N bytes allocated=N bytes + Planner 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: used=N bytes allocated=N bytes + Planner Memory: used=N bytes allocated=N bytes Execution Time: N.N ms (4 rows) @@ -131,10 +131,10 @@ 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> + + <Planner-Memory> + <Used>N</Used> + <Allocated>N</Allocated> + - </Planning-Memory> + + </Planner-Memory> + <Triggers> + </Triggers> + <Execution-Time>N.N</Execution-Time> + @@ -181,7 +181,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: + + Planner Memory: + Used: N + Allocated: N + Triggers: + @@ -294,7 +294,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": { + + "Planner Memory": { + "Used": N, + "Allocated": N + }, + @@ -550,7 +550,7 @@ select jsonb_pretty( ], + "Planning Time": 0.0, + "Execution Time": 0.0, + - "Planning Memory": { + + "Planner Memory": { + "Used": 0, + "Allocated": 0 + } + Attachments: [text/plain] review.txt (13.9K, ../../[email protected]/2-review.txt) download | inline diff: commit 48b0c6682a9e8cf07096b979693fac09b2f7a0ba Author: Alvaro Herrera <[email protected]> [Álvaro Herrera <[email protected]>] AuthorDate: Tue Nov 21 18:20:32 2023 +0100 CommitDate: Tue Nov 21 19:18:18 2023 +0100 review diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 9cd9b577c7..8c7f27b661 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -123,7 +123,7 @@ 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); + const MemoryUsage *usage); static void ExplainIndexScanDetails(Oid indexid, ScanDirection indexorderdir, ExplainState *es); static void ExplainScanTarget(Scan *plan, ExplainState *es); @@ -395,14 +395,14 @@ ExplainOneQuery(Query *query, int cursorOptions, else { PlannedStmt *plan; + MemoryContext planner_ctx; instr_time planstart, planduration; BufferUsage bufusage_start, bufusage; MemoryContextCounters mem_counts_start; MemoryContextCounters mem_counts_end; - MemUsage mem_usage; - MemoryContext planner_ctx; + MemoryUsage mem_usage; MemoryContext saved_ctx; /* @@ -415,7 +415,6 @@ ExplainOneQuery(Query *query, int cursorOptions, planner_ctx = AllocSetContextCreate(CurrentMemoryContext, "explain analyze planner context", ALLOCSET_DEFAULT_SIZES); - if (es->buffers) bufusage_start = pgBufferUsage; MemoryContextMemConsumed(planner_ctx, &mem_counts_start); @@ -429,7 +428,7 @@ ExplainOneQuery(Query *query, int cursorOptions, INSTR_TIME_SUBTRACT(planduration, planstart); MemoryContextSwitchTo(saved_ctx); MemoryContextMemConsumed(planner_ctx, &mem_counts_end); - calc_mem_usage(&mem_usage, &mem_counts_end, &mem_counts_start); + MemoryContextSizeDifference(&mem_usage, &mem_counts_start, &mem_counts_end); /* calc differences of buffer counters. */ if (es->buffers) @@ -551,7 +550,7 @@ void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, const char *queryString, ParamListInfo params, QueryEnvironment *queryEnv, const instr_time *planduration, - const BufferUsage *bufusage, const MemUsage *mem_usage) + const BufferUsage *bufusage, const MemoryUsage *mem_usage) { DestReceiver *dest; QueryDesc *queryDesc; @@ -656,9 +655,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, if (es->summary && mem_usage) { - ExplainOpenGroup("Planning Memory", "Planning Memory", true, es); + ExplainOpenGroup("Planner Memory", "Planner Memory", true, es); show_planning_memory(es, mem_usage); - ExplainCloseGroup("Planning Memory", "Planning Memory", true, es); + ExplainCloseGroup("Planner Memory", "Planner Memory", true, es); } /* Print info about runtime of triggers */ @@ -3801,45 +3800,22 @@ show_wal_usage(ExplainState *es, const WalUsage *usage) * Show planner's memory usage details. */ static void -show_planning_memory(ExplainState *es, const MemUsage *usage) +show_planning_memory(ExplainState *es, const MemoryUsage *usage) { if (es->format == EXPLAIN_FORMAT_TEXT) { appendStringInfo(es->str, - "Planning Memory: used=%zu bytes allocated=%zu bytes", - usage->mem_used, usage->mem_allocated); + "Planner Memory: used=%zu bytes allocated=%zu bytes", + usage->bytes_used, usage->bytes_allocated); appendStringInfoChar(es->str, '\n'); } else { - ExplainPropertyInteger("Used", "bytes", usage->mem_used, es); - ExplainPropertyInteger("Allocated", "bytes", usage->mem_allocated, es); + ExplainPropertyInteger("Used", "bytes", usage->bytes_used, es); + ExplainPropertyInteger("Allocated", "bytes", usage->bytes_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 eb39823d7a..3d3d0ae6a3 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -585,7 +585,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, bufusage; MemoryContextCounters mem_counts_start; MemoryContextCounters mem_counts_end; - MemUsage mem_usage; + MemoryUsage mem_usage; MemoryContext planner_ctx; MemoryContext saved_ctx; @@ -643,7 +643,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, INSTR_TIME_SUBTRACT(planduration, planstart); MemoryContextSwitchTo(saved_ctx); MemoryContextMemConsumed(planner_ctx, &mem_counts_end); - calc_mem_usage(&mem_usage, &mem_counts_end, &mem_counts_start); + MemoryContextSizeDifference(&mem_usage, &mem_counts_start, &mem_counts_end); /* calc differences of buffer counters. */ if (es->buffers) diff --git a/src/backend/utils/mmgr/mcxt.c b/src/backend/utils/mmgr/mcxt.c index 94159a6799..28e5f36405 100644 --- a/src/backend/utils/mmgr/mcxt.c +++ b/src/backend/utils/mmgr/mcxt.c @@ -687,6 +687,32 @@ MemoryContextMemAllocated(MemoryContext context, bool recurse) return total; } +/* + * Compute memory usage from the start and end memory counts. + */ +void +MemoryContextSizeDifference(MemoryUsage *mem_usage, + MemoryContextCounters *start, + MemoryContextCounters *end) +{ + /* + * We compute the memory "used" as the difference, between end situation + * and start situation, of the memory that's allocated according to the + * counters, excluding memory in freelists. + */ + mem_usage->bytes_used = + (end->totalspace - end->freespace) - + (start->totalspace - start->freespace); + + /* + * 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->bytes_allocated = end->totalspace; +} + /* * MemoryContextStats * Print statistics about the named context and all its descendants. @@ -752,11 +778,11 @@ MemoryContextStatsDetail(MemoryContext context, int max_children, */ extern void MemoryContextMemConsumed(MemoryContext context, - MemoryContextCounters *mem_consumed) + MemoryContextCounters *consumed) { - memset(mem_consumed, 0, sizeof(*mem_consumed)); + memset(consumed, 0, sizeof(*consumed)); - MemoryContextStatsInternal(context, 0, false, 100, mem_consumed, false); + MemoryContextStatsInternal(context, 0, false, 0, consumed, false); } /* diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 05dcb91c49..6947cbae8b 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -62,12 +62,6 @@ 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, @@ -99,7 +93,7 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ParamListInfo params, QueryEnvironment *queryEnv, const instr_time *planduration, const BufferUsage *bufusage, - const MemUsage *mem_usage); + const MemoryUsage *mem_usage); extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc); extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc); @@ -132,8 +126,5 @@ 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/nodes/memnodes.h b/src/include/nodes/memnodes.h index ff6453bb7a..577d39cef4 100644 --- a/src/include/nodes/memnodes.h +++ b/src/include/nodes/memnodes.h @@ -34,6 +34,16 @@ typedef struct MemoryContextCounters Size freespace; /* The unused portion of totalspace */ } MemoryContextCounters; +/* + * MemoryUsage + * For concise reporting of memory consumption + */ +typedef struct MemoryUsage +{ + Size bytes_used; + Size bytes_allocated; +} MemoryUsage; + /* * MemoryContext * A logical context in which memory allocations occur. diff --git a/src/include/utils/memutils.h b/src/include/utils/memutils.h index 50b9cc06e3..24dc0e996e 100644 --- a/src/include/utils/memutils.h +++ b/src/include/utils/memutils.h @@ -84,13 +84,16 @@ 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 MemoryContextSizeDifference(MemoryUsage *mem_usage, + MemoryContextCounters *start, + MemoryContextCounters *end); extern void MemoryContextStats(MemoryContext context); extern void MemoryContextStatsDetail(MemoryContext context, int max_children, bool print_to_stderr); extern void MemoryContextAllowInCriticalSection(MemoryContext context, bool allow); -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 e4b1aa7fdf..48e4ad1c3f 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: used=N bytes allocated=N bytes + Planner 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: used=N bytes allocated=N bytes + Planner 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: used=N bytes allocated=N bytes + Planner Memory: used=N bytes allocated=N bytes Execution Time: N.N ms (4 rows) @@ -131,10 +131,10 @@ 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> + + <Planner-Memory> + <Used>N</Used> + <Allocated>N</Allocated> + - </Planning-Memory> + + </Planner-Memory> + <Triggers> + </Triggers> + <Execution-Time>N.N</Execution-Time> + @@ -181,7 +181,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: + + Planner Memory: + Used: N + Allocated: N + Triggers: + @@ -294,7 +294,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": { + + "Planner Memory": { + "Used": N, + "Allocated": N + }, + @@ -550,7 +550,7 @@ select jsonb_pretty( ], + "Planning Time": 0.0, + "Execution Time": 0.0, + - "Planning Memory": { + + "Planner Memory": { + "Used": 0, + "Allocated": 0 + } + ^ permalink raw reply [nested|flat] 4+ messages in thread
* [PATCH v5a 6/7] Vacuum first pass uses Streaming Read interface @ 2023-12-31 16:29 Melanie Plageman <[email protected]> 0 siblings, 0 replies; 4+ messages in thread From: Melanie Plageman @ 2023-12-31 16:29 UTC (permalink / raw) Now vacuum's first pass, which HOT prunes and records the TIDs of non-removable dead tuples, uses the streaming read API by implementing a streaming read callback which invokes heap_vac_scan_get_next_block(). --- src/backend/access/heap/vacuumlazy.c | 79 +++++++++++++++++++++------- 1 file changed, 59 insertions(+), 20 deletions(-) diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 65d257aab83..fbbc87938e4 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -54,6 +54,7 @@ #include "storage/bufmgr.h" #include "storage/freespace.h" #include "storage/lmgr.h" +#include "storage/streaming_read.h" #include "utils/lsyscache.h" #include "utils/memutils.h" #include "utils/pg_rusage.h" @@ -168,7 +169,12 @@ typedef struct LVRelState char *relnamespace; char *relname; char *indname; /* Current index name */ - BlockNumber blkno; /* used only for heap operations */ + + /* + * The current block being processed by vacuum. Used only for heap + * operations. Primarily for error reporting and logging. + */ + BlockNumber blkno; OffsetNumber offnum; /* used only for heap operations */ VacErrPhase phase; bool verbose; /* VACUUM VERBOSE? */ @@ -189,6 +195,12 @@ typedef struct LVRelState BlockNumber missed_dead_pages; /* # pages with missed dead tuples */ BlockNumber nonempty_pages; /* actually, last nonempty page + 1 */ + /* + * The most recent block submitted in the streaming read callback by the + * first vacuum pass. + */ + BlockNumber blkno_prefetch; + /* Statistics output by us, for table */ double new_rel_tuples; /* new estimated total # of tuples */ double new_live_tuples; /* new estimated total # of live tuples */ @@ -232,7 +244,7 @@ typedef struct LVSavedErrInfo /* non-export function prototypes */ static void lazy_scan_heap(LVRelState *vacrel); -static bool heap_vac_scan_get_next_block(LVRelState *vacrel, BlockNumber next_block, +static void heap_vac_scan_get_next_block(LVRelState *vacrel, BlockNumber next_block, BlockNumber *blkno, bool *all_visible_according_to_vm); static bool lazy_scan_new_or_empty(LVRelState *vacrel, Buffer buf, @@ -416,6 +428,9 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, vacrel->nonempty_pages = 0; /* dead_items_alloc allocates vacrel->dead_items later on */ + /* relies on InvalidBlockNumber overflowing to 0 */ + vacrel->blkno_prefetch = InvalidBlockNumber; + /* Allocate/initialize output statistics state */ vacrel->new_rel_tuples = 0; vacrel->new_live_tuples = 0; @@ -776,6 +791,22 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, } } +static BlockNumber +vacuum_scan_pgsr_next(PgStreamingRead *pgsr, + void *pgsr_private, void *per_buffer_data) +{ + LVRelState *vacrel = pgsr_private; + bool *all_visible_according_to_vm = per_buffer_data; + + vacrel->blkno_prefetch++; + + heap_vac_scan_get_next_block(vacrel, + vacrel->blkno_prefetch, &vacrel->blkno_prefetch, + all_visible_according_to_vm); + + return vacrel->blkno_prefetch; +} + /* * lazy_scan_heap() -- workhorse function for VACUUM * @@ -815,12 +846,11 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, static void lazy_scan_heap(LVRelState *vacrel) { + Buffer buf; BlockNumber rel_pages = vacrel->rel_pages, next_fsm_block_to_vacuum = 0; - bool all_visible_according_to_vm; + bool *all_visible_according_to_vm; - /* relies on InvalidBlockNumber overflowing to 0 */ - BlockNumber blkno = InvalidBlockNumber; VacDeadItems *dead_items = vacrel->dead_items; const int initprog_index[] = { PROGRESS_VACUUM_PHASE, @@ -828,6 +858,11 @@ lazy_scan_heap(LVRelState *vacrel) PROGRESS_VACUUM_MAX_DEAD_TUPLES }; int64 initprog_val[3]; + PgStreamingRead *pgsr; + + pgsr = pg_streaming_read_buffer_alloc(PGSR_FLAG_MAINTENANCE, vacrel, + sizeof(bool), vacrel->bstrategy, BMR_REL(vacrel->rel), + MAIN_FORKNUM, vacuum_scan_pgsr_next); /* Report that we're scanning the heap, advertising total # of blocks */ initprog_val[0] = PROGRESS_VACUUM_PHASE_SCAN_HEAP; @@ -838,13 +873,19 @@ lazy_scan_heap(LVRelState *vacrel) vacrel->skip.next_unskippable_block = InvalidBlockNumber; vacrel->skip.vmbuffer = InvalidBuffer; - while (heap_vac_scan_get_next_block(vacrel, blkno + 1, - &blkno, &all_visible_according_to_vm)) + while (BufferIsValid(buf = + pg_streaming_read_buffer_get_next(pgsr, (void **) &all_visible_according_to_vm))) { - Buffer buf; Page page; bool has_lpdead_items; bool got_cleanup_lock = false; + BlockNumber blkno; + + vacrel->blkno = blkno = BufferGetBlockNumber(buf); + + CheckBufferIsPinnedOnce(buf); + + page = BufferGetPage(buf); vacrel->scanned_pages++; @@ -912,9 +953,6 @@ lazy_scan_heap(LVRelState *vacrel) */ visibilitymap_pin(vacrel->rel, blkno, &vacrel->skip.vmbuffer); - buf = ReadBufferExtended(vacrel->rel, MAIN_FORKNUM, blkno, RBM_NORMAL, - vacrel->bstrategy); - page = BufferGetPage(buf); /* * We need a buffer cleanup lock to prune HOT chains and defragment @@ -970,7 +1008,7 @@ lazy_scan_heap(LVRelState *vacrel) */ if (got_cleanup_lock) lazy_scan_prune(vacrel, buf, blkno, page, - all_visible_according_to_vm, + *all_visible_according_to_vm, &has_lpdead_items); /* @@ -1027,7 +1065,7 @@ lazy_scan_heap(LVRelState *vacrel) } /* report that everything is now scanned */ - pgstat_progress_update_param(PROGRESS_VACUUM_HEAP_BLKS_SCANNED, blkno); + pgstat_progress_update_param(PROGRESS_VACUUM_HEAP_BLKS_SCANNED, vacrel->rel_pages); /* now we can compute the new value for pg_class.reltuples */ vacrel->new_live_tuples = vac_estimate_reltuples(vacrel->rel, rel_pages, @@ -1042,6 +1080,8 @@ lazy_scan_heap(LVRelState *vacrel) Max(vacrel->new_live_tuples, 0) + vacrel->recently_dead_tuples + vacrel->missed_dead_tuples; + pg_streaming_read_free(pgsr); + /* * Do index vacuuming (call each index's ambulkdelete routine), then do * related heap vacuuming @@ -1053,11 +1093,11 @@ lazy_scan_heap(LVRelState *vacrel) * Vacuum the remainder of the Free Space Map. We must do this whether or * not there were indexes, and whether or not we bypassed index vacuuming. */ - if (blkno > next_fsm_block_to_vacuum) - FreeSpaceMapVacuumRange(vacrel->rel, next_fsm_block_to_vacuum, blkno); + if (vacrel->rel_pages > next_fsm_block_to_vacuum) + FreeSpaceMapVacuumRange(vacrel->rel, next_fsm_block_to_vacuum, vacrel->rel_pages); /* report all blocks vacuumed */ - pgstat_progress_update_param(PROGRESS_VACUUM_HEAP_BLKS_VACUUMED, blkno); + pgstat_progress_update_param(PROGRESS_VACUUM_HEAP_BLKS_VACUUMED, vacrel->rel_pages); /* Do final index cleanup (call each index's amvacuumcleanup routine) */ if (vacrel->nindexes > 0 && vacrel->do_index_cleanup) @@ -1090,7 +1130,7 @@ lazy_scan_heap(LVRelState *vacrel) * * The block number and visibility status of the next block to process are set * in blkno and all_visible_according_to_vm. heap_vac_scan_get_next_block() - * returns false if there are no further blocks to process. + * sets blkno to InvalidBlockNumber if there are no further blocks to process. * * vacrel is an in/out parameter here; vacuum options and information about the * relation are read and vacrel->skippedallvis is set to ensure we don't @@ -1110,7 +1150,7 @@ lazy_scan_heap(LVRelState *vacrel) * older XIDs/MXIDs. The vacrel->skippedallvis flag will be set here when the * choice to skip such a range is actually made, making everything safe.) */ -static bool +static void heap_vac_scan_get_next_block(LVRelState *vacrel, BlockNumber next_block, BlockNumber *blkno, bool *all_visible_according_to_vm) { @@ -1119,7 +1159,7 @@ heap_vac_scan_get_next_block(LVRelState *vacrel, BlockNumber next_block, if (next_block >= vacrel->rel_pages) { *blkno = InvalidBlockNumber; - return false; + return; } if (vacrel->skip.next_unskippable_block == InvalidBlockNumber || @@ -1214,7 +1254,6 @@ heap_vac_scan_get_next_block(LVRelState *vacrel, BlockNumber next_block, *all_visible_according_to_vm = true; *blkno = next_block; - return true; } /* -- 2.40.1 --lb5e4aqx4b6ik5lq Content-Type: text/x-diff; charset=us-ascii Content-Disposition: attachment; filename="v5a-0007-Vacuum-second-pass-uses-Streaming-Read-interface.patch" ^ permalink raw reply [nested|flat] 4+ messages in thread
end of thread, other threads:[~2023-12-31 16:29 UTC | newest] Thread overview: 4+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2023-09-25 03:35 Re: Report planning memory in EXPLAIN ANALYZE Andy Fan <[email protected]> 2023-10-30 14:43 ` Ashutosh Bapat <[email protected]> 2023-11-21 18:24 ` Alvaro Herrera <[email protected]> 2023-12-31 16:29 [PATCH v5a 6/7] Vacuum first pass uses Streaming Read interface Melanie Plageman <[email protected]>
This inbox is served by agora; see mirroring instructions for how to clone and mirror all data and code used for this inbox