On Fri, Dec 11, 2009 at 11:36 AM, Euler Taveira de Oliveira
<[email protected]> wrote:
> Robert Haas escreveu:
>> On Thu, Dec 10, 2009 at 9:35 PM, Takahiro Itagaki
>> <[email protected]> wrote:
>>> Anyway, a revised patch according to the comments is attached.
>>> The new text format is:
>>> Buffers: shared hit=675 read=968, temp read=1443 written=1443
>>> * Zero values are omitted. (Non-text formats could have zero values.)
>>> * Rename "Blocks:" to "Buffers:".
>>> * Remove parentheses and add a comma between shared, local and temp.
>>
>> I did a bit of copy-editing of your doc changes to make the English a
>> bit more correct and idiomatic. Slightly revised patch attached for
>> your consideration. The output format looks really nice (thanks for
>> bearing with me), and the functionality is great.
>>
> Please, document that zero values are omitted in the text format. It seems
> intuitive but could be surprise because zero values are in non-text formats.
OK, done, see attached. I also noticed when looking through this that
the documentation says that auto_explain.log_buffers is ignored unless
auto_explain.log_analyze is set. That is true and seems right to me,
but for some reason explain_ExecutorEnd() had been changed to set
es.analyze if either log_analyze or log_buffers was set. It actually
didn't have any effect unless log_analyze was set, but only because
explain_ExecutorStart doesn't set queryDesc->doInstrument in that
case. So I've reverted that here for clarity.
...Robert
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index f0d907d..491f479 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -22,6 +22,7 @@ PG_MODULE_MAGIC;
static int auto_explain_log_min_duration = -1; /* msec or -1 */
static bool auto_explain_log_analyze = false;
static bool auto_explain_log_verbose = false;
+static bool auto_explain_log_buffers = false;
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
static bool auto_explain_log_nested_statements = false;
@@ -93,6 +94,16 @@ _PG_init(void)
NULL,
NULL);
+ DefineCustomBoolVariable("auto_explain.log_buffers",
+ "Log buffers usage.",
+ NULL,
+ &auto_explain_log_buffers,
+ false,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL);
+
DefineCustomEnumVariable("auto_explain.log_format",
"EXPLAIN format to be used for plan logging.",
NULL,
@@ -221,6 +232,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
ExplainInitState(&es);
es.analyze = (queryDesc->doInstrument && auto_explain_log_analyze);
es.verbose = auto_explain_log_verbose;
+ es.buffers = (es.analyze && auto_explain_log_buffers);
es.format = auto_explain_log_format;
ExplainBeginOutput(&es);
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
index dd3f3fd..1b9d4d9 100644
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -104,6 +104,25 @@ LOAD 'auto_explain';
<varlistentry>
<term>
+ <varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
+ </term>
+ <indexterm>
+ <primary><varname>auto_explain.log_buffers</> configuration parameter</primary>
+ </indexterm>
+ <listitem>
+ <para>
+ <varname>auto_explain.log_buffers</varname> causes <command>EXPLAIN
+ (ANALYZE, BUFFERS)</> output, rather than just <command>EXPLAIN</>
+ output, to be printed when an execution plan is logged. This parameter is
+ off by default. Only superusers can change this setting. This
+ parameter has no effect unless <varname>auto_explain.log_analyze</>
+ parameter is set.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry>
+ <term>
<varname>auto_explain.log_format</varname> (<type>enum</type>)
</term>
<indexterm>
diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index 0d03469..6c68afd 100644
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -31,7 +31,7 @@ PostgreSQL documentation
<refsynopsisdiv>
<synopsis>
-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>
+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>
EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="parameter">statement</replaceable>
</synopsis>
</refsynopsisdiv>
@@ -140,6 +140,24 @@ ROLLBACK;
</varlistentry>
<varlistentry>
+ <term><literal>BUFFERS</literal></term>
+ <listitem>
+ <para>
+ Include information on buffer usage. Specifically, include the number of
+ shared blocks hits, reads, and writes, the number of local blocks hits,
+ reads, and writes, and the number of temp blocks reads and writes.
+ Shared blocks, local blocks, and temp blocks contain tables and indexes,
+ temporary tables and temporary indexes, and disk blocks used in sort and
+ materialized plans, respectively. The number of blocks shown for an
+ upper-level node includes those used by all its child nodes. In text
+ format, only non-zero values are printed. This parameter may only be
+ used with <literal>ANALYZE</literal> parameter. It defaults to
+ <literal>FALSE</literal>.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry>
<term><literal>FORMAT</literal></term>
<listitem>
<para>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 2067636..03a39c1 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -125,6 +125,8 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
es.verbose = defGetBoolean(opt);
else if (strcmp(opt->defname, "costs") == 0)
es.costs = defGetBoolean(opt);
+ else if (strcmp(opt->defname, "buffers") == 0)
+ es.buffers = defGetBoolean(opt);
else if (strcmp(opt->defname, "format") == 0)
{
char *p = defGetString(opt);
@@ -150,6 +152,11 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
opt->defname)));
}
+ if (es.buffers && !es.analyze)
+ ereport(ERROR,
+ (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+ errmsg("EXPLAIN option BUFFERS requires ANALYZE")));
+
/*
* Run parse analysis and rewrite. Note this also acquires sufficient
* locks on the source table(s).
@@ -1042,6 +1049,84 @@ ExplainNode(Plan *plan, PlanState *planstate,
break;
}
+ /* Show buffer usage */
+ if (es->buffers)
+ {
+ const BufferUsage *usage = &planstate->instrument->bufusage;
+
+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ {
+ bool has_shared = (usage->shared_blks_hit > 0 ||
+ usage->shared_blks_read > 0 ||
+ usage->shared_blks_written);
+ bool has_local = (usage->local_blks_hit > 0 ||
+ usage->local_blks_read > 0 ||
+ usage->local_blks_written);
+ bool has_temp = (usage->temp_blks_read > 0 ||
+ usage->temp_blks_written);
+
+ /* Show only positive counter values. */
+ if (has_shared || has_local || has_temp)
+ {
+ appendStringInfoSpaces(es->str, es->indent * 2);
+ appendStringInfoString(es->str, "Buffers:");
+
+ if (has_shared)
+ {
+ appendStringInfoString(es->str, " shared");
+ if (usage->shared_blks_hit > 0)
+ appendStringInfo(es->str, " hit=%ld",
+ usage->shared_blks_hit);
+ if (usage->shared_blks_read > 0)
+ appendStringInfo(es->str, " read=%ld",
+ usage->shared_blks_read);
+ if (usage->shared_blks_written > 0)
+ appendStringInfo(es->str, " written=%ld",
+ usage->shared_blks_written);
+ if (has_local || has_temp)
+ appendStringInfoChar(es->str, ',');
+ }
+ if (has_local)
+ {
+ appendStringInfoString(es->str, " local");
+ if (usage->local_blks_hit > 0)
+ appendStringInfo(es->str, " hit=%ld",
+ usage->local_blks_hit);
+ if (usage->local_blks_read > 0)
+ appendStringInfo(es->str, " read=%ld",
+ usage->local_blks_read);
+ if (usage->local_blks_written > 0)
+ appendStringInfo(es->str, " written=%ld",
+ usage->local_blks_written);
+ if (has_temp)
+ appendStringInfoChar(es->str, ',');
+ }
+ if (has_temp)
+ {
+ appendStringInfoString(es->str, " temp");
+ if (usage->temp_blks_read > 0)
+ appendStringInfo(es->str, " read=%ld",
+ usage->temp_blks_read);
+ if (usage->temp_blks_written > 0)
+ appendStringInfo(es->str, " written=%ld",
+ usage->temp_blks_written);
+ }
+ appendStringInfoChar(es->str, '\n');
+ }
+ }
+ else
+ {
+ ExplainPropertyLong("Shared Hit Blocks", usage->shared_blks_hit, es);
+ ExplainPropertyLong("Shared Read Blocks", usage->shared_blks_read, es);
+ ExplainPropertyLong("Shared Written Blocks", usage->shared_blks_written, es);
+ ExplainPropertyLong("Local Hit Blocks", usage->local_blks_hit, es);
+ ExplainPropertyLong("Local Read Blocks", usage->local_blks_read, es);
+ ExplainPropertyLong("Local Written Blocks", usage->local_blks_written, es);
+ ExplainPropertyLong("Temp Read Blocks", usage->temp_blks_read, es);
+ ExplainPropertyLong("Temp Written Blocks", usage->temp_blks_written, es);
+ }
+ }
+
/* Get ready to display the child plans */
haschildren = plan->initPlan ||
outerPlan(plan) ||
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index d8d7039..8690581 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -17,6 +17,10 @@
#include "executor/instrument.h"
+BufferUsage pgBufferUsage;
+
+static void BufferUsageAccumDiff(BufferUsage *dst,
+ const BufferUsage *add, const BufferUsage *sub);
/* Allocate new instrumentation structure(s) */
Instrumentation *
@@ -37,6 +41,9 @@ InstrStartNode(Instrumentation *instr)
INSTR_TIME_SET_CURRENT(instr->starttime);
else
elog(DEBUG2, "InstrStartNode called twice in a row");
+
+ /* initialize buffer usage per plan node */
+ instr->bufusage_start = pgBufferUsage;
}
/* Exit from a plan node */
@@ -59,6 +66,13 @@ InstrStopNode(Instrumentation *instr, double nTuples)
INSTR_TIME_SET_ZERO(instr->starttime);
+ /*
+ * Adds delta of buffer usage to node's count and resets counter to start
+ * so that the counters are not double counted by parent nodes.
+ */
+ BufferUsageAccumDiff(&instr->bufusage,
+ &pgBufferUsage, &instr->bufusage_start);
+
/* Is this the first tuple of this cycle? */
if (!instr->running)
{
@@ -95,3 +109,19 @@ InstrEndLoop(Instrumentation *instr)
instr->firsttuple = 0;
instr->tuplecount = 0;
}
+
+static void
+BufferUsageAccumDiff(BufferUsage *dst,
+ const BufferUsage *add,
+ const BufferUsage *sub)
+{
+ /* dst += add - sub */
+ dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
+ dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
+ dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
+ dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit;
+ dst->local_blks_read += add->local_blks_read - sub->local_blks_read;
+ dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
+ dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
+ dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
+}
diff --git a/src/backend/storage/buffer/buf_init.c b/src/backend/storage/buffer/buf_init.c
index e0211f5..cc434c3 100644
--- a/src/backend/storage/buffer/buf_init.c
+++ b/src/backend/storage/buffer/buf_init.c
@@ -22,16 +22,6 @@ BufferDesc *BufferDescriptors;
char *BufferBlocks;
int32 *PrivateRefCount;
-/* statistics counters */
-long int ReadBufferCount;
-long int ReadLocalBufferCount;
-long int BufferHitCount;
-long int LocalBufferHitCount;
-long int BufferFlushCount;
-long int LocalBufferFlushCount;
-long int BufFileReadCount;
-long int BufFileWriteCount;
-
/*
* Data Structures:
diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
index de28374..276723d 100644
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -34,6 +34,7 @@
#include <unistd.h>
#include "catalog/catalog.h"
+#include "executor/instrument.h"
#include "miscadmin.h"
#include "pg_trace.h"
#include "pgstat.h"
@@ -300,22 +301,23 @@ ReadBuffer_common(SMgrRelation smgr, bool isLocalBuf, ForkNumber forkNum,
if (isLocalBuf)
{
- ReadLocalBufferCount++;
bufHdr = LocalBufferAlloc(smgr, forkNum, blockNum, &found);
if (found)
- LocalBufferHitCount++;
+ pgBufferUsage.local_blks_hit++;
+ else
+ pgBufferUsage.local_blks_read++;
}
else
{
- ReadBufferCount++;
-
/*
* lookup the buffer. IO_IN_PROGRESS is set if the requested block is
* not currently in memory.
*/
bufHdr = BufferAlloc(smgr, forkNum, blockNum, strategy, &found);
if (found)
- BufferHitCount++;
+ pgBufferUsage.shared_blks_hit++;
+ else
+ pgBufferUsage.shared_blks_read++;
}
/* At this point we do NOT hold any locks. */
@@ -1611,54 +1613,6 @@ SyncOneBuffer(int buf_id, bool skip_recently_used)
/*
- * Return a palloc'd string containing buffer usage statistics.
- */
-char *
-ShowBufferUsage(void)
-{
- StringInfoData str;
- float hitrate;
- float localhitrate;
-
- initStringInfo(&str);
-
- if (ReadBufferCount == 0)
- hitrate = 0.0;
- else
- hitrate = (float) BufferHitCount *100.0 / ReadBufferCount;
-
- if (ReadLocalBufferCount == 0)
- localhitrate = 0.0;
- else
- localhitrate = (float) LocalBufferHitCount *100.0 / ReadLocalBufferCount;
-
- appendStringInfo(&str,
- "!\tShared blocks: %10ld read, %10ld written, buffer hit rate = %.2f%%\n",
- ReadBufferCount - BufferHitCount, BufferFlushCount, hitrate);
- appendStringInfo(&str,
- "!\tLocal blocks: %10ld read, %10ld written, buffer hit rate = %.2f%%\n",
- ReadLocalBufferCount - LocalBufferHitCount, LocalBufferFlushCount, localhitrate);
- appendStringInfo(&str,
- "!\tDirect blocks: %10ld read, %10ld written\n",
- BufFileReadCount, BufFileWriteCount);
-
- return str.data;
-}
-
-void
-ResetBufferUsage(void)
-{
- BufferHitCount = 0;
- ReadBufferCount = 0;
- BufferFlushCount = 0;
- LocalBufferHitCount = 0;
- ReadLocalBufferCount = 0;
- LocalBufferFlushCount = 0;
- BufFileReadCount = 0;
- BufFileWriteCount = 0;
-}
-
-/*
* AtEOXact_Buffers - clean up at end of transaction.
*
* As of PostgreSQL 8.0, buffer pins should get released by the
@@ -1916,7 +1870,7 @@ FlushBuffer(volatile BufferDesc *buf, SMgrRelation reln)
(char *) BufHdrGetBlock(buf),
false);
- BufferFlushCount++;
+ pgBufferUsage.shared_blks_written++;
/*
* Mark the buffer as clean (unless BM_JUST_DIRTIED has become set) and
diff --git a/src/backend/storage/buffer/localbuf.c b/src/backend/storage/buffer/localbuf.c
index 641f8e9..c7d25b9 100644
--- a/src/backend/storage/buffer/localbuf.c
+++ b/src/backend/storage/buffer/localbuf.c
@@ -16,6 +16,7 @@
#include "postgres.h"
#include "catalog/catalog.h"
+#include "executor/instrument.h"
#include "storage/buf_internals.h"
#include "storage/bufmgr.h"
#include "storage/smgr.h"
@@ -209,7 +210,7 @@ LocalBufferAlloc(SMgrRelation smgr, ForkNumber forkNum, BlockNumber blockNum,
/* Mark not-dirty now in case we error out below */
bufHdr->flags &= ~BM_DIRTY;
- LocalBufferFlushCount++;
+ pgBufferUsage.local_blks_written++;
}
/*
diff --git a/src/backend/storage/file/buffile.c b/src/backend/storage/file/buffile.c
index 436a82b..ebe77ff 100644
--- a/src/backend/storage/file/buffile.c
+++ b/src/backend/storage/file/buffile.c
@@ -34,6 +34,7 @@
#include "postgres.h"
+#include "executor/instrument.h"
#include "storage/fd.h"
#include "storage/buffile.h"
#include "storage/buf_internals.h"
@@ -240,7 +241,7 @@ BufFileLoadBuffer(BufFile *file)
file->offsets[file->curFile] += file->nbytes;
/* we choose not to advance curOffset here */
- BufFileReadCount++;
+ pgBufferUsage.temp_blks_read++;
}
/*
@@ -304,7 +305,7 @@ BufFileDumpBuffer(BufFile *file)
file->curOffset += bytestowrite;
wpos += bytestowrite;
- BufFileWriteCount++;
+ pgBufferUsage.temp_blks_written++;
}
file->dirty = false;
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 0672652..c985478 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -3901,7 +3901,6 @@ ResetUsage(void)
{
getrusage(RUSAGE_SELF, &Save_r);
gettimeofday(&Save_t, NULL);
- ResetBufferUsage();
}
void
@@ -3912,7 +3911,6 @@ ShowUsage(const char *title)
sys;
struct timeval elapse_t;
struct rusage r;
- char *bufusage;
getrusage(RUSAGE_SELF, &r);
gettimeofday(&elapse_t, NULL);
@@ -3986,10 +3984,6 @@ ShowUsage(const char *title)
r.ru_nvcsw, r.ru_nivcsw);
#endif /* HAVE_GETRUSAGE */
- bufusage = ShowBufferUsage();
- appendStringInfo(&str, "! buffer usage stats:\n%s", bufusage);
- pfree(bufusage);
-
/* remove trailing newline */
if (str.data[str.len - 1] == '\n')
str.data[--str.len] = '\0';
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index ba2ba08..648b2be 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -30,6 +30,7 @@ typedef struct ExplainState
bool verbose; /* be verbose */
bool analyze; /* print actual times */
bool costs; /* print costs */
+ bool buffers; /* print buffer usage */
ExplainFormat format; /* output format */
/* other states */
PlannedStmt *pstmt; /* top of plan */
diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 9846f6f..4bb6f91 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -16,6 +16,18 @@
#include "portability/instr_time.h"
+typedef struct BufferUsage
+{
+ long shared_blks_hit; /* # of shared buffer hits */
+ long shared_blks_read; /* # of shared disk blocks read */
+ long shared_blks_written; /* # of shared disk blocks written */
+ long local_blks_hit; /* # of local buffer hits */
+ long local_blks_read; /* # of local disk blocks read */
+ long local_blks_written; /* # of local disk blocks written */
+ long temp_blks_read; /* # of temp blocks read */
+ long temp_blks_written; /* # of temp blocks written */
+} BufferUsage;
+
typedef struct Instrumentation
{
/* Info about current plan cycle: */
@@ -24,13 +36,17 @@ typedef struct Instrumentation
instr_time counter; /* Accumulated runtime for this node */
double firsttuple; /* Time for first tuple of this cycle */
double tuplecount; /* Tuples emitted so far this cycle */
+ BufferUsage bufusage_start; /* Buffer usage at start */
/* Accumulated statistics across all completed cycles: */
double startup; /* Total startup time (in seconds) */
double total; /* Total total time (in seconds) */
double ntuples; /* Total tuples produced */
double nloops; /* # of run cycles for this node */
+ BufferUsage bufusage; /* Total buffer usage */
} Instrumentation;
+extern BufferUsage pgBufferUsage;
+
extern Instrumentation *InstrAlloc(int n);
extern void InstrStartNode(Instrumentation *instr);
extern void InstrStopNode(Instrumentation *instr, double nTuples);
diff --git a/src/include/storage/buf_internals.h b/src/include/storage/buf_internals.h
index 841cf09..42ed94e 100644
--- a/src/include/storage/buf_internals.h
+++ b/src/include/storage/buf_internals.h
@@ -173,16 +173,6 @@ extern PGDLLIMPORT BufferDesc *BufferDescriptors;
/* in localbuf.c */
extern BufferDesc *LocalBufferDescriptors;
-/* event counters in buf_init.c */
-extern long int ReadBufferCount;
-extern long int ReadLocalBufferCount;
-extern long int BufferHitCount;
-extern long int LocalBufferHitCount;
-extern long int BufferFlushCount;
-extern long int LocalBufferFlushCount;
-extern long int BufFileReadCount;
-extern long int BufFileWriteCount;
-
/*
* Internal routines: only called by bufmgr
diff --git a/src/include/storage/bufmgr.h b/src/include/storage/bufmgr.h
index d06eb77..f8d685c 100644
--- a/src/include/storage/bufmgr.h
+++ b/src/include/storage/bufmgr.h
@@ -173,8 +173,6 @@ extern Buffer ReleaseAndReadBuffer(Buffer buffer, Relation relation,
extern void InitBufferPool(void);
extern void InitBufferPoolAccess(void);
extern void InitBufferPoolBackend(void);
-extern char *ShowBufferUsage(void);
-extern void ResetBufferUsage(void);
extern void AtEOXact_Buffers(bool isCommit);
extern void PrintBufferLeakWarning(Buffer buffer);
extern void CheckPointBuffers(int flags);
--
Sent via pgsql-hackers mailing list ([email protected])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
