Location via proxy:   [ UP ]  
[Report a bug]   [Manage cookies]                
Skip to content

Commit 5de890e

Browse files
committed
Add EXPLAIN (MEMORY) to report planner memory consumption
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
1 parent 6a1ea02 commit 5de890e

File tree

9 files changed

+265
-28
lines changed

9 files changed

+265
-28
lines changed

contrib/auto_explain/auto_explain.c

+2
Original file line numberDiff line numberDiff line change
@@ -396,6 +396,8 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
396396
es->wal = (es->analyze && auto_explain_log_wal);
397397
es->timing = (es->analyze && auto_explain_log_timing);
398398
es->summary = es->analyze;
399+
/* No support for MEMORY */
400+
/* es->memory = false; */
399401
es->format = auto_explain_log_format;
400402
es->settings = auto_explain_log_settings;
401403

doc/src/sgml/ref/explain.sgml

+14
Original file line numberDiff line numberDiff line change
@@ -44,6 +44,7 @@ EXPLAIN [ ( <replaceable class="parameter">option</replaceable> [, ...] ) ] <rep
4444
WAL [ <replaceable class="parameter">boolean</replaceable> ]
4545
TIMING [ <replaceable class="parameter">boolean</replaceable> ]
4646
SUMMARY [ <replaceable class="parameter">boolean</replaceable> ]
47+
MEMORY [ <replaceable class="parameter">boolean</replaceable> ]
4748
FORMAT { TEXT | XML | JSON | YAML }
4849
</synopsis>
4950
</refsynopsisdiv>
@@ -250,6 +251,19 @@ ROLLBACK;
250251
</listitem>
251252
</varlistentry>
252253

254+
<varlistentry>
255+
<term><literal>MEMORY</literal></term>
256+
<listitem>
257+
<para>
258+
Include information on memory consumption by the query planning phase.
259+
Specifically, include the precise amount of storage used by planner
260+
in-memory structures, as well as total memory considering allocation
261+
overhead.
262+
This parameter defaults to <literal>FALSE</literal>.
263+
</para>
264+
</listitem>
265+
</varlistentry>
266+
253267
<varlistentry>
254268
<term><literal>FORMAT</literal></term>
255269
<listitem>

src/backend/commands/explain.c

+126-26
Original file line numberDiff line numberDiff line change
@@ -119,9 +119,11 @@ static void show_instrumentation_count(const char *qlabel, int which,
119119
static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es);
120120
static void show_eval_params(Bitmapset *bms_params, ExplainState *es);
121121
static const char *explain_get_index_name(Oid indexId);
122-
static void show_buffer_usage(ExplainState *es, const BufferUsage *usage,
123-
bool planning);
122+
static bool peek_buffer_usage(ExplainState *es, const BufferUsage *usage);
123+
static void show_buffer_usage(ExplainState *es, const BufferUsage *usage);
124124
static void show_wal_usage(ExplainState *es, const WalUsage *usage);
125+
static void show_memory_counters(ExplainState *es,
126+
const MemoryContextCounters *mem_counters);
125127
static void ExplainIndexScanDetails(Oid indexid, ScanDirection indexorderdir,
126128
ExplainState *es);
127129
static void ExplainScanTarget(Scan *plan, ExplainState *es);
@@ -202,6 +204,8 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
202204
summary_set = true;
203205
es->summary = defGetBoolean(opt);
204206
}
207+
else if (strcmp(opt->defname, "memory") == 0)
208+
es->memory = defGetBoolean(opt);
205209
else if (strcmp(opt->defname, "format") == 0)
206210
{
207211
char *p = defGetString(opt);
@@ -397,6 +401,25 @@ ExplainOneQuery(Query *query, int cursorOptions,
397401
planduration;
398402
BufferUsage bufusage_start,
399403
bufusage;
404+
MemoryContextCounters mem_counters;
405+
MemoryContext planner_ctx = NULL;
406+
MemoryContext saved_ctx = NULL;
407+
408+
if (es->memory)
409+
{
410+
/*
411+
* Create a new memory context to measure planner's memory
412+
* consumption accurately. Note that if the planner were to be
413+
* modified to use a different memory context type, here we would
414+
* be changing that to AllocSet, which might be undesirable.
415+
* However, we don't have a way to create a context of the same
416+
* type as another, so we pray and hope that this is OK.
417+
*/
418+
planner_ctx = AllocSetContextCreate(CurrentMemoryContext,
419+
"explain analyze planner context",
420+
ALLOCSET_DEFAULT_SIZES);
421+
saved_ctx = MemoryContextSwitchTo(planner_ctx);
422+
}
400423

401424
if (es->buffers)
402425
bufusage_start = pgBufferUsage;
@@ -408,6 +431,12 @@ ExplainOneQuery(Query *query, int cursorOptions,
408431
INSTR_TIME_SET_CURRENT(planduration);
409432
INSTR_TIME_SUBTRACT(planduration, planstart);
410433

434+
if (es->memory)
435+
{
436+
MemoryContextSwitchTo(saved_ctx);
437+
MemoryContextMemConsumed(planner_ctx, &mem_counters);
438+
}
439+
411440
/* calc differences of buffer counters. */
412441
if (es->buffers)
413442
{
@@ -417,7 +446,8 @@ ExplainOneQuery(Query *query, int cursorOptions,
417446

418447
/* run it (if needed) and produce output */
419448
ExplainOnePlan(plan, into, es, queryString, params, queryEnv,
420-
&planduration, (es->buffers ? &bufusage : NULL));
449+
&planduration, (es->buffers ? &bufusage : NULL),
450+
es->memory ? &mem_counters : NULL);
421451
}
422452
}
423453

@@ -527,7 +557,8 @@ void
527557
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
528558
const char *queryString, ParamListInfo params,
529559
QueryEnvironment *queryEnv, const instr_time *planduration,
530-
const BufferUsage *bufusage)
560+
const BufferUsage *bufusage,
561+
const MemoryContextCounters *mem_counters)
531562
{
532563
DestReceiver *dest;
533564
QueryDesc *queryDesc;
@@ -615,11 +646,27 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
615646
/* Create textual dump of plan tree */
616647
ExplainPrintPlan(es, queryDesc);
617648

618-
/* Show buffer usage in planning */
619-
if (bufusage)
649+
/* Show buffer and/or memory usage in planning */
650+
if (peek_buffer_usage(es, bufusage) || mem_counters)
620651
{
621652
ExplainOpenGroup("Planning", "Planning", true, es);
622-
show_buffer_usage(es, bufusage, true);
653+
654+
if (es->format == EXPLAIN_FORMAT_TEXT)
655+
{
656+
ExplainIndentText(es);
657+
appendStringInfoString(es->str, "Planning:\n");
658+
es->indent++;
659+
}
660+
661+
if (bufusage)
662+
show_buffer_usage(es, bufusage);
663+
664+
if (mem_counters)
665+
show_memory_counters(es, mem_counters);
666+
667+
if (es->format == EXPLAIN_FORMAT_TEXT)
668+
es->indent--;
669+
623670
ExplainCloseGroup("Planning", "Planning", true, es);
624671
}
625672

@@ -2106,7 +2153,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
21062153

21072154
/* Show buffer/WAL usage */
21082155
if (es->buffers && planstate->instrument)
2109-
show_buffer_usage(es, &planstate->instrument->bufusage, false);
2156+
show_buffer_usage(es, &planstate->instrument->bufusage);
21102157
if (es->wal && planstate->instrument)
21112158
show_wal_usage(es, &planstate->instrument->walusage);
21122159

@@ -2125,7 +2172,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
21252172

21262173
ExplainOpenWorker(n, es);
21272174
if (es->buffers)
2128-
show_buffer_usage(es, &instrument->bufusage, false);
2175+
show_buffer_usage(es, &instrument->bufusage);
21292176
if (es->wal)
21302177
show_wal_usage(es, &instrument->walusage);
21312178
ExplainCloseWorker(n, es);
@@ -3545,10 +3592,52 @@ explain_get_index_name(Oid indexId)
35453592
}
35463593

35473594
/*
3548-
* Show buffer usage details.
3595+
* Return whether show_buffer_usage would have anything to print, if given
3596+
* the same 'usage' data. Note that when the format is anything other than
3597+
* text, we print even if the counters are all zeroes.
3598+
*/
3599+
static bool
3600+
peek_buffer_usage(ExplainState *es, const BufferUsage *usage)
3601+
{
3602+
bool has_shared;
3603+
bool has_local;
3604+
bool has_temp;
3605+
bool has_shared_timing;
3606+
bool has_local_timing;
3607+
bool has_temp_timing;
3608+
3609+
if (usage == NULL)
3610+
return false;
3611+
3612+
if (es->format != EXPLAIN_FORMAT_TEXT)
3613+
return true;
3614+
3615+
has_shared = (usage->shared_blks_hit > 0 ||
3616+
usage->shared_blks_read > 0 ||
3617+
usage->shared_blks_dirtied > 0 ||
3618+
usage->shared_blks_written > 0);
3619+
has_local = (usage->local_blks_hit > 0 ||
3620+
usage->local_blks_read > 0 ||
3621+
usage->local_blks_dirtied > 0 ||
3622+
usage->local_blks_written > 0);
3623+
has_temp = (usage->temp_blks_read > 0 ||
3624+
usage->temp_blks_written > 0);
3625+
has_shared_timing = (!INSTR_TIME_IS_ZERO(usage->shared_blk_read_time) ||
3626+
!INSTR_TIME_IS_ZERO(usage->shared_blk_write_time));
3627+
has_local_timing = (!INSTR_TIME_IS_ZERO(usage->local_blk_read_time) ||
3628+
!INSTR_TIME_IS_ZERO(usage->local_blk_write_time));
3629+
has_temp_timing = (!INSTR_TIME_IS_ZERO(usage->temp_blk_read_time) ||
3630+
!INSTR_TIME_IS_ZERO(usage->temp_blk_write_time));
3631+
3632+
return has_shared || has_local || has_temp || has_shared_timing ||
3633+
has_local_timing || has_temp_timing;
3634+
}
3635+
3636+
/*
3637+
* Show buffer usage details. This better be sync with peek_buffer_usage.
35493638
*/
35503639
static void
3551-
show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
3640+
show_buffer_usage(ExplainState *es, const BufferUsage *usage)
35523641
{
35533642
if (es->format == EXPLAIN_FORMAT_TEXT)
35543643
{
@@ -3568,18 +3657,6 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
35683657
!INSTR_TIME_IS_ZERO(usage->local_blk_write_time));
35693658
bool has_temp_timing = (!INSTR_TIME_IS_ZERO(usage->temp_blk_read_time) ||
35703659
!INSTR_TIME_IS_ZERO(usage->temp_blk_write_time));
3571-
bool show_planning = (planning && (has_shared ||
3572-
has_local || has_temp ||
3573-
has_shared_timing ||
3574-
has_local_timing ||
3575-
has_temp_timing));
3576-
3577-
if (show_planning)
3578-
{
3579-
ExplainIndentText(es);
3580-
appendStringInfoString(es->str, "Planning:\n");
3581-
es->indent++;
3582-
}
35833660

35843661
/* Show only positive counter values. */
35853662
if (has_shared || has_local || has_temp)
@@ -3678,9 +3755,6 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
36783755
}
36793756
appendStringInfoChar(es->str, '\n');
36803757
}
3681-
3682-
if (show_planning)
3683-
es->indent--;
36843758
}
36853759
else
36863760
{
@@ -3766,6 +3840,32 @@ show_wal_usage(ExplainState *es, const WalUsage *usage)
37663840
}
37673841
}
37683842

3843+
/*
3844+
* Show memory usage details.
3845+
*/
3846+
static void
3847+
show_memory_counters(ExplainState *es, const MemoryContextCounters *mem_counters)
3848+
{
3849+
if (es->format == EXPLAIN_FORMAT_TEXT)
3850+
{
3851+
ExplainIndentText(es);
3852+
appendStringInfo(es->str,
3853+
"Memory: used=%lld bytes allocated=%lld bytes",
3854+
(long long) (mem_counters->totalspace - mem_counters->freespace),
3855+
(long long) mem_counters->totalspace);
3856+
appendStringInfoChar(es->str, '\n');
3857+
}
3858+
else
3859+
{
3860+
ExplainPropertyInteger("Memory Used", "bytes",
3861+
mem_counters->totalspace - mem_counters->freespace,
3862+
es);
3863+
ExplainPropertyInteger("Memory Allocated", "bytes",
3864+
mem_counters->totalspace, es);
3865+
}
3866+
}
3867+
3868+
37693869
/*
37703870
* Add some additional details about an IndexScan or IndexOnlyScan
37713871
*/

src/backend/commands/prepare.c

+21-1
Original file line numberDiff line numberDiff line change
@@ -583,6 +583,19 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
583583
instr_time planduration;
584584
BufferUsage bufusage_start,
585585
bufusage;
586+
MemoryContextCounters mem_counters;
587+
MemoryContext planner_ctx = NULL;
588+
MemoryContext saved_ctx = NULL;
589+
590+
if (es->memory)
591+
{
592+
/* See ExplainOneQuery about this */
593+
Assert(IsA(CurrentMemoryContext, AllocSetContext));
594+
planner_ctx = AllocSetContextCreate(CurrentMemoryContext,
595+
"explain analyze planner context",
596+
ALLOCSET_DEFAULT_SIZES);
597+
saved_ctx = MemoryContextSwitchTo(planner_ctx);
598+
}
586599

587600
if (es->buffers)
588601
bufusage_start = pgBufferUsage;
@@ -624,6 +637,12 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
624637
INSTR_TIME_SET_CURRENT(planduration);
625638
INSTR_TIME_SUBTRACT(planduration, planstart);
626639

640+
if (es->memory)
641+
{
642+
MemoryContextSwitchTo(saved_ctx);
643+
MemoryContextMemConsumed(planner_ctx, &mem_counters);
644+
}
645+
627646
/* calc differences of buffer counters. */
628647
if (es->buffers)
629648
{
@@ -640,7 +659,8 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
640659

641660
if (pstmt->commandType != CMD_UTILITY)
642661
ExplainOnePlan(pstmt, into, es, query_string, paramLI, queryEnv,
643-
&planduration, (es->buffers ? &bufusage : NULL));
662+
&planduration, (es->buffers ? &bufusage : NULL),
663+
es->memory ? &mem_counters : NULL);
644664
else
645665
ExplainOneUtility(pstmt->utilityStmt, into, es, query_string,
646666
paramLI, queryEnv);

src/backend/utils/mmgr/mcxt.c

+13
Original file line numberDiff line numberDiff line change
@@ -687,6 +687,19 @@ MemoryContextMemAllocated(MemoryContext context, bool recurse)
687687
return total;
688688
}
689689

690+
/*
691+
* Return the memory consumption statistics about the given context and its
692+
* children.
693+
*/
694+
void
695+
MemoryContextMemConsumed(MemoryContext context,
696+
MemoryContextCounters *consumed)
697+
{
698+
memset(consumed, 0, sizeof(*consumed));
699+
700+
MemoryContextStatsInternal(context, 0, false, 0, consumed, false);
701+
}
702+
690703
/*
691704
* MemoryContextStats
692705
* Print statistics about the named context and all its descendants.

src/include/commands/explain.h

+3-1
Original file line numberDiff line numberDiff line change
@@ -45,6 +45,7 @@ typedef struct ExplainState
4545
bool wal; /* print WAL usage */
4646
bool timing; /* print detailed node timing */
4747
bool summary; /* print total planning and execution timing */
48+
bool memory; /* print planner's memory usage information */
4849
bool settings; /* print modified settings */
4950
bool generic; /* generate a generic plan */
5051
ExplainFormat format; /* output format */
@@ -92,7 +93,8 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
9293
ExplainState *es, const char *queryString,
9394
ParamListInfo params, QueryEnvironment *queryEnv,
9495
const instr_time *planduration,
95-
const BufferUsage *bufusage);
96+
const BufferUsage *bufusage,
97+
const MemoryContextCounters *mem_counters);
9698

9799
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
98100
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);

src/include/utils/memutils.h

+2
Original file line numberDiff line numberDiff line change
@@ -84,6 +84,8 @@ extern Size GetMemoryChunkSpace(void *pointer);
8484
extern MemoryContext MemoryContextGetParent(MemoryContext context);
8585
extern bool MemoryContextIsEmpty(MemoryContext context);
8686
extern Size MemoryContextMemAllocated(MemoryContext context, bool recurse);
87+
extern void MemoryContextMemConsumed(MemoryContext context,
88+
MemoryContextCounters *consumed);
8789
extern void MemoryContextStats(MemoryContext context);
8890
extern void MemoryContextStatsDetail(MemoryContext context, int max_children,
8991
bool print_to_stderr);

0 commit comments

Comments
 (0)