Skip to content

Commit cddca5e

Browse files
robertmhaasrobertmhaas
committed
Add an EXPLAIN (BUFFERS) option to show buffer-usage statistics.
This patch also removes buffer-usage statistics from the track_counts output, since this (or the global server statistics) is deemed to be a better interface to this information. Itagaki Takahiro, reviewed by Euler Taveira de Oliveira.
1 parent 6f1bf75 commit cddca5e

File tree

25 files changed

+274
-140
lines changed

25 files changed

+274
-140
lines changed

‎contrib/auto_explain/auto_explain.c

Lines changed: 20 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@
66
* Copyright (c) 2008-2009, PostgreSQL Global Development Group
77
*
88
* IDENTIFICATION
9-
* $PostgreSQL: pgsql/contrib/auto_explain/auto_explain.c,v 1.9 2009/12/12 00:35:33 rhaas Exp $
9+
* $PostgreSQL: pgsql/contrib/auto_explain/auto_explain.c,v 1.10 2009/12/15 04:57:46 rhaas Exp $
1010
*
1111
*-------------------------------------------------------------------------
1212
*/
@@ -22,6 +22,7 @@ PG_MODULE_MAGIC;
2222
static int auto_explain_log_min_duration = -1; /* msec or -1 */
2323
static bool auto_explain_log_analyze = false;
2424
static bool auto_explain_log_verbose = false;
25+
static bool auto_explain_log_buffers = false;
2526
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
2627
static bool auto_explain_log_nested_statements = false;
2728

@@ -93,6 +94,16 @@ _PG_init(void)
9394
NULL,
9495
NULL);
9596

97+
DefineCustomBoolVariable("auto_explain.log_buffers",
98+
"Log buffers usage.",
99+
NULL,
100+
&auto_explain_log_buffers,
101+
false,
102+
PGC_SUSET,
103+
0,
104+
NULL,
105+
NULL);
106+
96107
DefineCustomEnumVariable("auto_explain.log_format",
97108
"EXPLAIN format to be used for plan logging.",
98109
NULL,
@@ -147,7 +158,11 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
147158
{
148159
/* Enable per-node instrumentation iff log_analyze is required. */
149160
if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
150-
queryDesc->doInstrument = true;
161+
{
162+
queryDesc->instrument_options |= INSTRUMENT_TIMER;
163+
if (auto_explain_log_buffers)
164+
queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
165+
}
151166
}
152167

153168
if (prev_ExecutorStart)
@@ -167,7 +182,7 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
167182
MemoryContext oldcxt;
168183

169184
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
170-
queryDesc->totaltime = InstrAlloc(1);
185+
queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
171186
MemoryContextSwitchTo(oldcxt);
172187
}
173188
}
@@ -219,8 +234,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
219234
ExplainState es;
220235

221236
ExplainInitState(&es);
222-
es.analyze = (queryDesc->doInstrument && auto_explain_log_analyze);
237+
es.analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
223238
es.verbose = auto_explain_log_verbose;
239+
es.buffers = (es.analyze && auto_explain_log_buffers);
224240
es.format = auto_explain_log_format;
225241

226242
ExplainBeginOutput(&es);

‎contrib/pg_stat_statements/pg_stat_statements.c

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@
1414
* Copyright (c) 2008-2009, PostgreSQL Global Development Group
1515
*
1616
* IDENTIFICATION
17-
* $PostgreSQL: pgsql/contrib/pg_stat_statements/pg_stat_statements.c,v 1.7 2009/12/01 02:31:11 momjian Exp $
17+
* $PostgreSQL: pgsql/contrib/pg_stat_statements/pg_stat_statements.c,v 1.8 2009/12/15 04:57:46 rhaas Exp $
1818
*
1919
*-------------------------------------------------------------------------
2020
*/
@@ -495,7 +495,7 @@ pgss_ExecutorStart(QueryDesc *queryDesc, int eflags)
495495
MemoryContext oldcxt;
496496

497497
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
498-
queryDesc->totaltime = InstrAlloc(1);
498+
queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
499499
MemoryContextSwitchTo(oldcxt);
500500
}
501501
}

‎doc/src/sgml/auto-explain.sgml

Lines changed: 20 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
<!-- $PostgreSQL: pgsql/doc/src/sgml/auto-explain.sgml,v 1.5 2009/12/11 01:33:35 adunstan Exp $ -->
1+
<!-- $PostgreSQL: pgsql/doc/src/sgml/auto-explain.sgml,v 1.6 2009/12/15 04:57:47 rhaas Exp $ -->
22

33
<sect1 id="auto-explain">
44
<title>auto_explain</title>
@@ -102,6 +102,25 @@ LOAD 'auto_explain';
102102
</listitem>
103103
</varlistentry>
104104

105+
<varlistentry>
106+
<term>
107+
<varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
108+
</term>
109+
<indexterm>
110+
<primary><varname>auto_explain.log_buffers</> configuration parameter</primary>
111+
</indexterm>
112+
<listitem>
113+
<para>
114+
<varname>auto_explain.log_buffers</varname> causes <command>EXPLAIN
115+
(ANALYZE, BUFFERS)</> output, rather than just <command>EXPLAIN</>
116+
output, to be printed when an execution plan is logged. This parameter is
117+
off by default. Only superusers can change this setting. This
118+
parameter has no effect unless <varname>auto_explain.log_analyze</>
119+
parameter is set.
120+
</para>
121+
</listitem>
122+
</varlistentry>
123+
105124
<varlistentry>
106125
<term>
107126
<varname>auto_explain.log_format</varname> (<type>enum</type>)

‎doc/src/sgml/ref/explain.sgml

Lines changed: 20 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
<!--
2-
$PostgreSQL: pgsql/doc/src/sgml/ref/explain.sgml,v 1.47 2009/12/11 01:33:35 adunstan Exp $
2+
$PostgreSQL: pgsql/doc/src/sgml/ref/explain.sgml,v 1.48 2009/12/15 04:57:47 rhaas Exp $
33
PostgreSQL documentation
44
-->
55

@@ -31,7 +31,7 @@ PostgreSQL documentation
3131

3232
<refsynopsisdiv>
3333
<synopsis>
34-
EXPLAIN [ ( { ANALYZE <replaceable class="parameter">boolean</replaceable> | VERBOSE <replaceable class="parameter">boolean</replaceable> | COSTS <replaceable class="parameter">boolean</replaceable> | FORMAT { TEXT | XML | JSON | YAML } } [, ...] ) ] <replaceable class="parameter">statement</replaceable>
34+
EXPLAIN [ ( { ANALYZE <replaceable class="parameter">boolean</replaceable> | VERBOSE <replaceable class="parameter">boolean</replaceable> | COSTS <replaceable class="parameter">boolean</replaceable> | BUFFERS <replaceable class="parameter">boolean</replaceable> | FORMAT { TEXT | XML | JSON | YAML } } [, ...] ) ] <replaceable class="parameter">statement</replaceable>
3535
EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="parameter">statement</replaceable>
3636
</synopsis>
3737
</refsynopsisdiv>
@@ -139,6 +139,24 @@ ROLLBACK;
139139
</listitem>
140140
</varlistentry>
141141

142+
<varlistentry>
143+
<term><literal>BUFFERS</literal></term>
144+
<listitem>
145+
<para>
146+
Include information on buffer usage. Specifically, include the number of
147+
shared blocks hits, reads, and writes, the number of local blocks hits,
148+
reads, and writes, and the number of temp blocks reads and writes.
149+
Shared blocks, local blocks, and temp blocks contain tables and indexes,
150+
temporary tables and temporary indexes, and disk blocks used in sort and
151+
materialized plans, respectively. The number of blocks shown for an
152+
upper-level node includes those used by all its child nodes. In text
153+
format, only non-zero values are printed. This parameter may only be
154+
used with <literal>ANALYZE</literal> parameter. It defaults to
155+
<literal>FALSE</literal>.
156+
</para>
157+
</listitem>
158+
</varlistentry>
159+
142160
<varlistentry>
143161
<term><literal>FORMAT</literal></term>
144162
<listitem>

‎src/backend/commands/copy.c

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
*
99
*
1010
* IDENTIFICATION
11-
* $PostgreSQL: pgsql/src/backend/commands/copy.c,v 1.318 2009/11/20 20:38:10 tgl Exp $
11+
* $PostgreSQL: pgsql/src/backend/commands/copy.c,v 1.319 2009/12/15 04:57:47 rhaas Exp $
1212
*
1313
*-------------------------------------------------------------------------
1414
*/
@@ -1094,7 +1094,7 @@ DoCopy(const CopyStmt *stmt, const char *queryString)
10941094
cstate->queryDesc = CreateQueryDesc(plan, queryString,
10951095
GetActiveSnapshot(),
10961096
InvalidSnapshot,
1097-
dest, NULL, false);
1097+
dest, NULL, 0);
10981098

10991099
/*
11001100
* Call ExecutorStart to prepare the plan for execution.

‎src/backend/commands/explain.c

Lines changed: 93 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,7 @@
77
* Portions Copyright (c) 1994-5, Regents of the University of California
88
*
99
* IDENTIFICATION
10-
* $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.195 2009/12/12 00:35:33 rhaas Exp $
10+
* $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.196 2009/12/15 04:57:47 rhaas Exp $
1111
*
1212
*-------------------------------------------------------------------------
1313
*/
@@ -125,6 +125,8 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
125125
es.verbose = defGetBoolean(opt);
126126
else if (strcmp(opt->defname, "costs") == 0)
127127
es.costs = defGetBoolean(opt);
128+
else if (strcmp(opt->defname, "buffers") == 0)
129+
es.buffers = defGetBoolean(opt);
128130
else if (strcmp(opt->defname, "format") == 0)
129131
{
130132
char *p = defGetString(opt);
@@ -150,6 +152,11 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
150152
opt->defname)));
151153
}
152154

155+
if (es.buffers && !es.analyze)
156+
ereport(ERROR,
157+
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
158+
errmsg("EXPLAIN option BUFFERS requires ANALYZE")));
159+
153160
/*
154161
* Run parse analysis and rewrite. Note this also acquires sufficient
155162
* locks on the source table(s).
@@ -339,6 +346,12 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es,
339346
instr_time starttime;
340347
double totaltime = 0;
341348
int eflags;
349+
int instrument_option = 0;
350+
351+
if (es->analyze)
352+
instrument_option |= INSTRUMENT_TIMER;
353+
if (es->buffers)
354+
instrument_option |= INSTRUMENT_BUFFERS;
342355

343356
/*
344357
* Use a snapshot with an updated command ID to ensure this query sees
@@ -349,7 +362,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es,
349362
/* Create a QueryDesc requesting no output */
350363
queryDesc = CreateQueryDesc(plannedstmt, queryString,
351364
GetActiveSnapshot(), InvalidSnapshot,
352-
None_Receiver, params, es->analyze);
365+
None_Receiver, params, instrument_option);
353366

354367
INSTR_TIME_SET_CURRENT(starttime);
355368

@@ -1042,6 +1055,84 @@ ExplainNode(Plan *plan, PlanState *planstate,
10421055
break;
10431056
}
10441057

1058+
/* Show buffer usage */
1059+
if (es->buffers)
1060+
{
1061+
const BufferUsage *usage = &planstate->instrument->bufusage;
1062+
1063+
if (es->format == EXPLAIN_FORMAT_TEXT)
1064+
{
1065+
bool has_shared = (usage->shared_blks_hit > 0 ||
1066+
usage->shared_blks_read > 0 ||
1067+
usage->shared_blks_written);
1068+
bool has_local = (usage->local_blks_hit > 0 ||
1069+
usage->local_blks_read > 0 ||
1070+
usage->local_blks_written);
1071+
bool has_temp = (usage->temp_blks_read > 0 ||
1072+
usage->temp_blks_written);
1073+
1074+
/* Show only positive counter values. */
1075+
if (has_shared || has_local || has_temp)
1076+
{
1077+
appendStringInfoSpaces(es->str, es->indent * 2);
1078+
appendStringInfoString(es->str, "Buffers:");
1079+
1080+
if (has_shared)
1081+
{
1082+
appendStringInfoString(es->str, " shared");
1083+
if (usage->shared_blks_hit > 0)
1084+
appendStringInfo(es->str, " hit=%ld",
1085+
usage->shared_blks_hit);
1086+
if (usage->shared_blks_read > 0)
1087+
appendStringInfo(es->str, " read=%ld",
1088+
usage->shared_blks_read);
1089+
if (usage->shared_blks_written > 0)
1090+
appendStringInfo(es->str, " written=%ld",
1091+
usage->shared_blks_written);
1092+
if (has_local || has_temp)
1093+
appendStringInfoChar(es->str, ',');
1094+
}
1095+
if (has_local)
1096+
{
1097+
appendStringInfoString(es->str, " local");
1098+
if (usage->local_blks_hit > 0)
1099+
appendStringInfo(es->str, " hit=%ld",
1100+
usage->local_blks_hit);
1101+
if (usage->local_blks_read > 0)
1102+
appendStringInfo(es->str, " read=%ld",
1103+
usage->local_blks_read);
1104+
if (usage->local_blks_written > 0)
1105+
appendStringInfo(es->str, " written=%ld",
1106+
usage->local_blks_written);
1107+
if (has_temp)
1108+
appendStringInfoChar(es->str, ',');
1109+
}
1110+
if (has_temp)
1111+
{
1112+
appendStringInfoString(es->str, " temp");
1113+
if (usage->temp_blks_read > 0)
1114+
appendStringInfo(es->str, " read=%ld",
1115+
usage->temp_blks_read);
1116+
if (usage->temp_blks_written > 0)
1117+
appendStringInfo(es->str, " written=%ld",
1118+
usage->temp_blks_written);
1119+
}
1120+
appendStringInfoChar(es->str, '\n');
1121+
}
1122+
}
1123+
else
1124+
{
1125+
ExplainPropertyLong("Shared Hit Blocks", usage->shared_blks_hit, es);
1126+
ExplainPropertyLong("Shared Read Blocks", usage->shared_blks_read, es);
1127+
ExplainPropertyLong("Shared Written Blocks", usage->shared_blks_written, es);
1128+
ExplainPropertyLong("Local Hit Blocks", usage->local_blks_hit, es);
1129+
ExplainPropertyLong("Local Read Blocks", usage->local_blks_read, es);
1130+
ExplainPropertyLong("Local Written Blocks", usage->local_blks_written, es);
1131+
ExplainPropertyLong("Temp Read Blocks", usage->temp_blks_read, es);
1132+
ExplainPropertyLong("Temp Written Blocks", usage->temp_blks_written, es);
1133+
}
1134+
}
1135+
10451136
/* Get ready to display the child plans */
10461137
haschildren = plan->initPlan ||
10471138
outerPlan(plan) ||

‎src/backend/commands/tablecmds.c

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
*
99
*
1010
* IDENTIFICATION
11-
* $PostgreSQL: pgsql/src/backend/commands/tablecmds.c,v 1.309 2009/12/11 03:34:55 itagaki Exp $
11+
* $PostgreSQL: pgsql/src/backend/commands/tablecmds.c,v 1.310 2009/12/15 04:57:47 rhaas Exp $
1212
*
1313
*-------------------------------------------------------------------------
1414
*/
@@ -936,7 +936,7 @@ ExecuteTruncate(TruncateStmt *stmt)
936936
rel,
937937
0, /* dummy rangetable index */
938938
CMD_DELETE, /* don't need any index info */
939-
false);
939+
0);
940940
resultRelInfo++;
941941
}
942942
estate->es_result_relations = resultRelInfos;

‎src/backend/executor/execMain.c

Lines changed: 5 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -26,7 +26,7 @@
2626
*
2727
*
2828
* IDENTIFICATION
29-
* $PostgreSQL: pgsql/src/backend/executor/execMain.c,v 1.337 2009/12/11 18:14:43 tgl Exp $
29+
* $PostgreSQL: pgsql/src/backend/executor/execMain.c,v 1.338 2009/12/15 04:57:47 rhaas Exp $
3030
*
3131
*-------------------------------------------------------------------------
3232
*/
@@ -180,7 +180,7 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags)
180180
*/
181181
estate->es_snapshot = RegisterSnapshot(queryDesc->snapshot);
182182
estate->es_crosscheck_snapshot = RegisterSnapshot(queryDesc->crosscheck_snapshot);
183-
estate->es_instrument = queryDesc->doInstrument;
183+
estate->es_instrument = queryDesc->instrument_options;
184184

185185
/*
186186
* Initialize the plan state tree
@@ -859,7 +859,7 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo,
859859
Relation resultRelationDesc,
860860
Index resultRelationIndex,
861861
CmdType operation,
862-
bool doInstrument)
862+
int instrument_options)
863863
{
864864
/*
865865
* Check valid relkind ... parser and/or planner should have noticed this
@@ -914,10 +914,8 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo,
914914
palloc0(n * sizeof(FmgrInfo));
915915
resultRelInfo->ri_TrigWhenExprs = (List **)
916916
palloc0(n * sizeof(List *));
917-
if (doInstrument)
918-
resultRelInfo->ri_TrigInstrument = InstrAlloc(n);
919-
else
920-
resultRelInfo->ri_TrigInstrument = NULL;
917+
if (instrument_options)
918+
resultRelInfo->ri_TrigInstrument = InstrAlloc(n, instrument_options);
921919
}
922920
else
923921
{

‎src/backend/executor/execProcnode.c

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@
1212
*
1313
*
1414
* IDENTIFICATION
15-
* $PostgreSQL: pgsql/src/backend/executor/execProcnode.c,v 1.68 2009/10/12 18:10:41 tgl Exp $
15+
* $PostgreSQL: pgsql/src/backend/executor/execProcnode.c,v 1.69 2009/12/15 04:57:47 rhaas Exp $
1616
*
1717
*-------------------------------------------------------------------------
1818
*/
@@ -321,7 +321,7 @@ ExecInitNode(Plan *node, EState *estate, int eflags)
321321

322322
/* Set up instrumentation for this node if requested */
323323
if (estate->es_instrument)
324-
result->instrument = InstrAlloc(1);
324+
result->instrument = InstrAlloc(1, estate->es_instrument);
325325

326326
return result;
327327
}

0 commit comments

Comments
 (0)