diff -cprN head/contrib/auto_explain/auto_explain.c work/contrib/auto_explain/auto_explain.c
*** head/contrib/auto_explain/auto_explain.c 2009-08-10 14:46:49.000000000 +0900
--- work/contrib/auto_explain/auto_explain.c 2009-11-24 10:04:50.868963605 +0900
*************** PG_MODULE_MAGIC;
*** 22,27 ****
--- 22,28 ----
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;
*************** _PG_init(void)
*** 92,97 ****
--- 93,108 ----
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,
*************** explain_ExecutorEnd(QueryDesc *queryDesc
*** 218,225 ****
ExplainState es;
ExplainInitState(&es);
! es.analyze = (queryDesc->doInstrument && auto_explain_log_analyze);
es.verbose = auto_explain_log_verbose;
es.format = auto_explain_log_format;
ExplainPrintPlan(&es, queryDesc);
--- 229,238 ----
ExplainState es;
ExplainInitState(&es);
! es.analyze = (queryDesc->doInstrument &&
! (auto_explain_log_analyze || auto_explain_log_buffers));
es.verbose = auto_explain_log_verbose;
+ es.buffers = (es.analyze && auto_explain_log_buffers);
es.format = auto_explain_log_format;
ExplainPrintPlan(&es, queryDesc);
diff -cprN head/doc/src/sgml/auto-explain.sgml work/doc/src/sgml/auto-explain.sgml
*** head/doc/src/sgml/auto-explain.sgml 2009-08-10 14:46:50.000000000 +0900
--- work/doc/src/sgml/auto-explain.sgml 2009-11-24 10:04:50.868963605 +0900
*************** LOAD 'auto_explain';
*** 104,109 ****
--- 104,128 ----
+ auto_explain.log_buffers (boolean)
+
+
+ auto_explain.log_buffers configuration parameter
+
+
+
+ auto_explain.log_buffers causes EXPLAIN
+ (ANALYZE, BUFFERS) output, rather than just EXPLAIN
+ output, to be printed when an execution plan is logged. This parameter is
+ off by default. Only superusers can change this setting. Also, this
+ parameter only has effect if auto_explain.log_analyze
+ parameter is set.
+
+
+
+
+
+
auto_explain.log_format (enum)
diff -cprN head/doc/src/sgml/ref/explain.sgml work/doc/src/sgml/ref/explain.sgml
*** head/doc/src/sgml/ref/explain.sgml 2009-08-10 14:46:50.000000000 +0900
--- work/doc/src/sgml/ref/explain.sgml 2009-11-24 10:04:50.870421302 +0900
*************** PostgreSQL documentation
*** 31,37 ****
! EXPLAIN [ ( { ANALYZE boolean | VERBOSE boolean | COSTS boolean | FORMAT { TEXT | XML | JSON } } [, ...] ) ] statement
EXPLAIN [ ANALYZE ] [ VERBOSE ] statement
--- 31,37 ----
! EXPLAIN [ ( { ANALYZE boolean | VERBOSE boolean | COSTS boolean | BUFFERS boolean | FORMAT { TEXT | XML | JSON } } [, ...] ) ] statement
EXPLAIN [ ANALYZE ] [ VERBOSE ] statement
*************** ROLLBACK;
*** 140,145 ****
--- 140,157 ----
+ BUFFERS
+
+
+ Include information on the buffers. Specifically, include the number of
+ buffer hits, number of disk blocks read, and number of local buffer read.
+ This parameter should be used with ANALYZE parameter.
+ Also, this parameter defaults to FALSE.
+
+
+
+
+
FORMAT
diff -cprN head/src/backend/commands/explain.c work/src/backend/commands/explain.c
*** head/src/backend/commands/explain.c 2009-11-05 07:26:04.000000000 +0900
--- work/src/backend/commands/explain.c 2009-11-24 10:06:53.073015629 +0900
*************** ExplainQuery(ExplainStmt *stmt, const ch
*** 125,130 ****
--- 125,132 ----
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);
*************** ExplainQuery(ExplainStmt *stmt, const ch
*** 147,152 ****
--- 149,159 ----
errmsg("unrecognized EXPLAIN option \"%s\"",
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
*************** ExplainNode(Plan *plan, PlanState *plans
*** 1040,1045 ****
--- 1047,1076 ----
break;
}
+ /* Show buffer usage */
+ if (es->buffers)
+ {
+ const BufferUsage *usage = &planstate->instrument->bufusage;
+
+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ {
+ appendStringInfoSpaces(es->str, es->indent * 2);
+ appendStringInfo(es->str, "Blocks Hit: %ld Read: %ld Temp Read: %ld\n",
+ usage->blks_hit, usage->blks_read, usage->temp_blks_read);
+ }
+ else
+ {
+ ExplainPropertyLong("Hit Blocks", usage->blks_hit, es);
+ ExplainPropertyLong("Read Blocks", usage->blks_read, es);
+ ExplainPropertyLong("Written Blocks", usage->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 -cprN head/src/backend/executor/instrument.c work/src/backend/executor/instrument.c
*** head/src/backend/executor/instrument.c 2009-01-02 02:23:41.000000000 +0900
--- work/src/backend/executor/instrument.c 2009-11-24 10:04:50.871436243 +0900
***************
*** 17,22 ****
--- 17,26 ----
#include "executor/instrument.h"
+ BufferUsage pgBufferUsage;
+
+ static void BufferUsageAccumDiff(BufferUsage *dst,
+ const BufferUsage *add, const BufferUsage *sub);
/* Allocate new instrumentation structure(s) */
Instrumentation *
*************** InstrStartNode(Instrumentation *instr)
*** 37,42 ****
--- 41,49 ----
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 */
*************** InstrStopNode(Instrumentation *instr, do
*** 59,64 ****
--- 66,79 ----
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);
+ pgBufferUsage = instr->bufusage_start;
+
/* Is this the first tuple of this cycle? */
if (!instr->running)
{
*************** InstrEndLoop(Instrumentation *instr)
*** 95,97 ****
--- 110,128 ----
instr->firsttuple = 0;
instr->tuplecount = 0;
}
+
+ static void
+ BufferUsageAccumDiff(BufferUsage *dst,
+ const BufferUsage *add,
+ const BufferUsage *sub)
+ {
+ /* dst += add - sub */
+ dst->blks_hit += add->blks_hit - sub->blks_hit;
+ dst->blks_read += add->blks_read - sub->blks_read;
+ dst->blks_written += add->blks_written - sub->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 -cprN head/src/backend/storage/buffer/buf_init.c work/src/backend/storage/buffer/buf_init.c
*** head/src/backend/storage/buffer/buf_init.c 2009-01-02 02:23:47.000000000 +0900
--- work/src/backend/storage/buffer/buf_init.c 2009-11-24 10:04:50.871436243 +0900
*************** BufferDesc *BufferDescriptors;
*** 22,37 ****
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:
--- 22,27 ----
diff -cprN head/src/backend/storage/buffer/bufmgr.c work/src/backend/storage/buffer/bufmgr.c
*** head/src/backend/storage/buffer/bufmgr.c 2009-06-11 23:49:01.000000000 +0900
--- work/src/backend/storage/buffer/bufmgr.c 2009-11-24 10:04:50.872386293 +0900
***************
*** 34,39 ****
--- 34,40 ----
#include
#include "catalog/catalog.h"
+ #include "executor/instrument.h"
#include "miscadmin.h"
#include "pg_trace.h"
#include "pgstat.h"
*************** ReadBuffer_common(SMgrRelation smgr, boo
*** 300,321 ****
if (isLocalBuf)
{
- ReadLocalBufferCount++;
bufHdr = LocalBufferAlloc(smgr, forkNum, blockNum, &found);
if (found)
! LocalBufferHitCount++;
}
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++;
}
/* At this point we do NOT hold any locks. */
--- 301,323 ----
if (isLocalBuf)
{
bufHdr = LocalBufferAlloc(smgr, forkNum, blockNum, &found);
if (found)
! pgBufferUsage.local_blks_hit++;
! else
! pgBufferUsage.local_blks_read++;
}
else
{
/*
* 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)
! pgBufferUsage.blks_hit++;
! else
! pgBufferUsage.blks_read++;
}
/* At this point we do NOT hold any locks. */
*************** SyncOneBuffer(int buf_id, bool skip_rece
*** 1611,1664 ****
/*
- * 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
--- 1613,1618 ----
*************** FlushBuffer(volatile BufferDesc *buf, SM
*** 1916,1922 ****
(char *) BufHdrGetBlock(buf),
false);
! BufferFlushCount++;
/*
* Mark the buffer as clean (unless BM_JUST_DIRTIED has become set) and
--- 1870,1876 ----
(char *) BufHdrGetBlock(buf),
false);
! pgBufferUsage.blks_written++;
/*
* Mark the buffer as clean (unless BM_JUST_DIRTIED has become set) and
diff -cprN head/src/backend/storage/buffer/localbuf.c work/src/backend/storage/buffer/localbuf.c
*** head/src/backend/storage/buffer/localbuf.c 2009-06-11 23:49:01.000000000 +0900
--- work/src/backend/storage/buffer/localbuf.c 2009-11-24 10:04:50.873458462 +0900
***************
*** 16,21 ****
--- 16,22 ----
#include "postgres.h"
#include "catalog/catalog.h"
+ #include "executor/instrument.h"
#include "storage/buf_internals.h"
#include "storage/bufmgr.h"
#include "storage/smgr.h"
*************** LocalBufferAlloc(SMgrRelation smgr, Fork
*** 209,215 ****
/* Mark not-dirty now in case we error out below */
bufHdr->flags &= ~BM_DIRTY;
! LocalBufferFlushCount++;
}
/*
--- 210,216 ----
/* Mark not-dirty now in case we error out below */
bufHdr->flags &= ~BM_DIRTY;
! pgBufferUsage.local_blks_written++;
}
/*
diff -cprN head/src/backend/storage/file/buffile.c work/src/backend/storage/file/buffile.c
*** head/src/backend/storage/file/buffile.c 2009-06-11 23:49:01.000000000 +0900
--- work/src/backend/storage/file/buffile.c 2009-11-24 10:04:50.873458462 +0900
***************
*** 34,39 ****
--- 34,40 ----
#include "postgres.h"
+ #include "executor/instrument.h"
#include "storage/fd.h"
#include "storage/buffile.h"
#include "storage/buf_internals.h"
*************** BufFileLoadBuffer(BufFile *file)
*** 240,246 ****
file->offsets[file->curFile] += file->nbytes;
/* we choose not to advance curOffset here */
! BufFileReadCount++;
}
/*
--- 241,247 ----
file->offsets[file->curFile] += file->nbytes;
/* we choose not to advance curOffset here */
! pgBufferUsage.temp_blks_read++;
}
/*
*************** BufFileDumpBuffer(BufFile *file)
*** 304,310 ****
file->curOffset += bytestowrite;
wpos += bytestowrite;
! BufFileWriteCount++;
}
file->dirty = false;
--- 305,311 ----
file->curOffset += bytestowrite;
wpos += bytestowrite;
! pgBufferUsage.temp_blks_written++;
}
file->dirty = false;
diff -cprN head/src/backend/tcop/postgres.c work/src/backend/tcop/postgres.c
*** head/src/backend/tcop/postgres.c 2009-11-05 07:26:06.000000000 +0900
--- work/src/backend/tcop/postgres.c 2009-11-24 10:04:50.874015639 +0900
*************** ResetUsage(void)
*** 3901,3907 ****
{
getrusage(RUSAGE_SELF, &Save_r);
gettimeofday(&Save_t, NULL);
- ResetBufferUsage();
}
void
--- 3901,3906 ----
*************** ShowUsage(const char *title)
*** 3912,3918 ****
sys;
struct timeval elapse_t;
struct rusage r;
- char *bufusage;
getrusage(RUSAGE_SELF, &r);
gettimeofday(&elapse_t, NULL);
--- 3911,3916 ----
*************** ShowUsage(const char *title)
*** 3986,3995 ****
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';
--- 3984,3989 ----
diff -cprN head/src/include/commands/explain.h work/src/include/commands/explain.h
*** head/src/include/commands/explain.h 2009-08-10 14:46:50.000000000 +0900
--- work/src/include/commands/explain.h 2009-11-24 10:04:50.875067601 +0900
*************** typedef struct ExplainState
*** 29,34 ****
--- 29,35 ----
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 -cprN head/src/include/executor/instrument.h work/src/include/executor/instrument.h
*** head/src/include/executor/instrument.h 2009-01-02 02:23:59.000000000 +0900
--- work/src/include/executor/instrument.h 2009-11-24 10:04:50.875067601 +0900
***************
*** 16,21 ****
--- 16,33 ----
#include "portability/instr_time.h"
+ typedef struct BufferUsage
+ {
+ long blks_hit; /* # of buffer hits at start */
+ long blks_read; /* # of disk blocks read at start */
+ long blks_written; /* # of disk blocks written at start */
+ long local_blks_hit; /* # of buffer hits at start */
+ long local_blks_read; /* # of disk blocks read at start */
+ long local_blks_written; /* # of disk blocks written at start */
+ long temp_blks_read; /* # of temp blocks read at start */
+ long temp_blks_written; /* # of temp blocks written at start */
+ } BufferUsage;
+
typedef struct Instrumentation
{
/* Info about current plan cycle: */
*************** typedef struct Instrumentation
*** 24,36 ****
--- 36,52 ----
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 -cprN head/src/include/storage/buf_internals.h work/src/include/storage/buf_internals.h
*** head/src/include/storage/buf_internals.h 2009-06-11 23:49:12.000000000 +0900
--- work/src/include/storage/buf_internals.h 2009-11-24 10:04:50.875067601 +0900
*************** extern PGDLLIMPORT BufferDesc *BufferDes
*** 173,188 ****
/* 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
--- 173,178 ----
diff -cprN head/src/include/storage/bufmgr.h work/src/include/storage/bufmgr.h
*** head/src/include/storage/bufmgr.h 2009-06-11 23:49:12.000000000 +0900
--- work/src/include/storage/bufmgr.h 2009-11-24 10:04:50.875067601 +0900
*************** extern Buffer ReleaseAndReadBuffer(Buffe
*** 173,180 ****
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);
--- 173,178 ----