diff -cprN head/contrib/auto_explain/auto_explain.c work/contrib/auto_explain/auto_explain.c
*** head/contrib/auto_explain/auto_explain.c 2009-12-14 09:21:34.822978000 +0900
--- work/contrib/auto_explain/auto_explain.c 2009-12-14 13:28:35.935089826 +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)
*** 93,98 ****
--- 94,109 ----
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_ExecutorStart(QueryDesc *queryDe
*** 147,153 ****
{
/* Enable per-node instrumentation iff log_analyze is required. */
if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
! queryDesc->doInstrument = true;
}
if (prev_ExecutorStart)
--- 158,168 ----
{
/* Enable per-node instrumentation iff log_analyze is required. */
if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
! {
! queryDesc->instrument_options |= INSTRUMENT_TIMER;
! if (auto_explain_log_buffers)
! queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
! }
}
if (prev_ExecutorStart)
*************** explain_ExecutorStart(QueryDesc *queryDe
*** 167,173 ****
MemoryContext oldcxt;
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
! queryDesc->totaltime = InstrAlloc(1);
MemoryContextSwitchTo(oldcxt);
}
}
--- 182,188 ----
MemoryContext oldcxt;
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
! queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
MemoryContextSwitchTo(oldcxt);
}
}
*************** explain_ExecutorEnd(QueryDesc *queryDesc
*** 219,226 ****
ExplainState es;
ExplainInitState(&es);
! es.analyze = (queryDesc->doInstrument && auto_explain_log_analyze);
es.verbose = auto_explain_log_verbose;
es.format = auto_explain_log_format;
ExplainBeginOutput(&es);
--- 234,242 ----
ExplainState es;
ExplainInitState(&es);
! es.analyze = (queryDesc->instrument_options && 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 -cprN head/contrib/pg_stat_statements/pg_stat_statements.c work/contrib/pg_stat_statements/pg_stat_statements.c
*** head/contrib/pg_stat_statements/pg_stat_statements.c 2009-12-03 13:12:47.180551000 +0900
--- work/contrib/pg_stat_statements/pg_stat_statements.c 2009-12-14 13:16:42.859766691 +0900
*************** pgss_ExecutorStart(QueryDesc *queryDesc,
*** 495,501 ****
MemoryContext oldcxt;
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
! queryDesc->totaltime = InstrAlloc(1);
MemoryContextSwitchTo(oldcxt);
}
}
--- 495,501 ----
MemoryContext oldcxt;
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
! queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
MemoryContextSwitchTo(oldcxt);
}
}
diff -cprN head/doc/src/sgml/auto-explain.sgml work/doc/src/sgml/auto-explain.sgml
*** head/doc/src/sgml/auto-explain.sgml 2009-12-11 10:47:06.949855000 +0900
--- work/doc/src/sgml/auto-explain.sgml 2009-12-14 11:32:38.419722226 +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. This
+ parameter has no effect unless 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-12-11 10:47:06.949855000 +0900
--- work/doc/src/sgml/ref/explain.sgml 2009-12-14 11:32:38.419722226 +0900
*************** PostgreSQL documentation
*** 31,37 ****
! EXPLAIN [ ( { ANALYZE boolean | VERBOSE boolean | COSTS boolean | FORMAT { TEXT | XML | JSON | YAML } } [, ...] ) ] statement
EXPLAIN [ ANALYZE ] [ VERBOSE ] statement
--- 31,37 ----
! EXPLAIN [ ( { ANALYZE boolean | VERBOSE boolean | COSTS boolean | BUFFERS boolean | FORMAT { TEXT | XML | JSON | YAML } } [, ...] ) ] statement
EXPLAIN [ ANALYZE ] [ VERBOSE ] statement
*************** ROLLBACK;
*** 140,145 ****
--- 140,163 ----
+ BUFFERS
+
+
+ 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 ANALYZE parameter. It defaults to
+ FALSE.
+
+
+
+
+
FORMAT
diff -cprN head/src/backend/commands/copy.c work/src/backend/commands/copy.c
*** head/src/backend/commands/copy.c 2009-11-24 10:04:57.883822000 +0900
--- work/src/backend/commands/copy.c 2009-12-14 13:21:28.588811970 +0900
*************** DoCopy(const CopyStmt *stmt, const char
*** 1094,1100 ****
cstate->queryDesc = CreateQueryDesc(plan, queryString,
GetActiveSnapshot(),
InvalidSnapshot,
! dest, NULL, false);
/*
* Call ExecutorStart to prepare the plan for execution.
--- 1094,1100 ----
cstate->queryDesc = CreateQueryDesc(plan, queryString,
GetActiveSnapshot(),
InvalidSnapshot,
! dest, NULL, 0);
/*
* Call ExecutorStart to prepare the plan for execution.
diff -cprN head/src/backend/commands/explain.c work/src/backend/commands/explain.c
*** head/src/backend/commands/explain.c 2009-12-14 09:21:34.822978000 +0900
--- work/src/backend/commands/explain.c 2009-12-14 13:20:19.415713632 +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
*** 150,155 ****
--- 152,162 ----
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).
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 339,344 ****
--- 346,357 ----
instr_time starttime;
double totaltime = 0;
int eflags;
+ int instrument_option = 0;
+
+ if (es->analyze)
+ instrument_option |= INSTRUMENT_TIMER;
+ if (es->buffers)
+ instrument_option |= INSTRUMENT_BUFFERS;
/*
* Use a snapshot with an updated command ID to ensure this query sees
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 349,355 ****
/* Create a QueryDesc requesting no output */
queryDesc = CreateQueryDesc(plannedstmt, queryString,
GetActiveSnapshot(), InvalidSnapshot,
! None_Receiver, params, es->analyze);
INSTR_TIME_SET_CURRENT(starttime);
--- 362,368 ----
/* Create a QueryDesc requesting no output */
queryDesc = CreateQueryDesc(plannedstmt, queryString,
GetActiveSnapshot(), InvalidSnapshot,
! None_Receiver, params, instrument_option);
INSTR_TIME_SET_CURRENT(starttime);
*************** ExplainNode(Plan *plan, PlanState *plans
*** 1042,1047 ****
--- 1055,1138 ----
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 -cprN head/src/backend/commands/tablecmds.c work/src/backend/commands/tablecmds.c
*** head/src/backend/commands/tablecmds.c 2009-12-11 12:39:49.829461000 +0900
--- work/src/backend/commands/tablecmds.c 2009-12-14 13:21:28.546723185 +0900
*************** ExecuteTruncate(TruncateStmt *stmt)
*** 936,942 ****
rel,
0, /* dummy rangetable index */
CMD_DELETE, /* don't need any index info */
! false);
resultRelInfo++;
}
estate->es_result_relations = resultRelInfos;
--- 936,942 ----
rel,
0, /* dummy rangetable index */
CMD_DELETE, /* don't need any index info */
! 0);
resultRelInfo++;
}
estate->es_result_relations = resultRelInfos;
diff -cprN head/src/backend/executor/execMain.c work/src/backend/executor/execMain.c
*** head/src/backend/executor/execMain.c 2009-12-14 09:21:34.822978000 +0900
--- work/src/backend/executor/execMain.c 2009-12-14 13:10:49.340796341 +0900
*************** standard_ExecutorStart(QueryDesc *queryD
*** 180,186 ****
*/
estate->es_snapshot = RegisterSnapshot(queryDesc->snapshot);
estate->es_crosscheck_snapshot = RegisterSnapshot(queryDesc->crosscheck_snapshot);
! estate->es_instrument = queryDesc->doInstrument;
/*
* Initialize the plan state tree
--- 180,186 ----
*/
estate->es_snapshot = RegisterSnapshot(queryDesc->snapshot);
estate->es_crosscheck_snapshot = RegisterSnapshot(queryDesc->crosscheck_snapshot);
! estate->es_instrument = queryDesc->instrument_options;
/*
* Initialize the plan state tree
*************** InitResultRelInfo(ResultRelInfo *resultR
*** 859,865 ****
Relation resultRelationDesc,
Index resultRelationIndex,
CmdType operation,
! bool doInstrument)
{
/*
* Check valid relkind ... parser and/or planner should have noticed this
--- 859,865 ----
Relation resultRelationDesc,
Index resultRelationIndex,
CmdType operation,
! int instrument_options)
{
/*
* Check valid relkind ... parser and/or planner should have noticed this
*************** InitResultRelInfo(ResultRelInfo *resultR
*** 914,923 ****
palloc0(n * sizeof(FmgrInfo));
resultRelInfo->ri_TrigWhenExprs = (List **)
palloc0(n * sizeof(List *));
! if (doInstrument)
! resultRelInfo->ri_TrigInstrument = InstrAlloc(n);
! else
! resultRelInfo->ri_TrigInstrument = NULL;
}
else
{
--- 914,921 ----
palloc0(n * sizeof(FmgrInfo));
resultRelInfo->ri_TrigWhenExprs = (List **)
palloc0(n * sizeof(List *));
! if (instrument_options)
! resultRelInfo->ri_TrigInstrument = InstrAlloc(n, instrument_options);
}
else
{
diff -cprN head/src/backend/executor/execProcnode.c work/src/backend/executor/execProcnode.c
*** head/src/backend/executor/execProcnode.c 2009-10-13 09:24:03.097662000 +0900
--- work/src/backend/executor/execProcnode.c 2009-12-14 13:10:30.437752389 +0900
*************** ExecInitNode(Plan *node, EState *estate,
*** 321,327 ****
/* Set up instrumentation for this node if requested */
if (estate->es_instrument)
! result->instrument = InstrAlloc(1);
return result;
}
--- 321,327 ----
/* Set up instrumentation for this node if requested */
if (estate->es_instrument)
! result->instrument = InstrAlloc(1, estate->es_instrument);
return result;
}
diff -cprN head/src/backend/executor/functions.c work/src/backend/executor/functions.c
*** head/src/backend/executor/functions.c 2009-11-06 09:53:35.834256000 +0900
--- work/src/backend/executor/functions.c 2009-12-14 13:21:28.623763373 +0900
*************** postquel_start(execution_state *es, SQLF
*** 414,420 ****
fcache->src,
snapshot, InvalidSnapshot,
dest,
! fcache->paramLI, false);
else
es->qd = CreateUtilityQueryDesc(es->stmt,
fcache->src,
--- 414,420 ----
fcache->src,
snapshot, InvalidSnapshot,
dest,
! fcache->paramLI, 0);
else
es->qd = CreateUtilityQueryDesc(es->stmt,
fcache->src,
diff -cprN head/src/backend/executor/instrument.c work/src/backend/executor/instrument.c
*** head/src/backend/executor/instrument.c 2009-01-05 00:22:25.168790000 +0900
--- work/src/backend/executor/instrument.c 2009-12-14 13:17:59.739739775 +0900
***************
*** 17,30 ****
#include "executor/instrument.h"
/* Allocate new instrumentation structure(s) */
Instrumentation *
! InstrAlloc(int n)
{
! Instrumentation *instr = palloc0(n * sizeof(Instrumentation));
! /* we don't need to do any initialization except zero 'em */
return instr;
}
--- 17,44 ----
#include "executor/instrument.h"
+ BufferUsage pgBufferUsage;
+
+ static void BufferUsageAccumDiff(BufferUsage *dst,
+ const BufferUsage *add, const BufferUsage *sub);
/* Allocate new instrumentation structure(s) */
Instrumentation *
! InstrAlloc(int n, int instrument_options)
{
! Instrumentation *instr;
!
! /* timer is always required for now */
! Assert(instrument_options & INSTRUMENT_TIMER);
! instr = palloc0(n * sizeof(Instrumentation));
! if (instrument_options & INSTRUMENT_BUFFERS)
! {
! int i;
!
! for (i = 0; i < n; i++)
! instr[i].needs_bufusage = true;
! }
return instr;
}
*************** InstrStartNode(Instrumentation *instr)
*** 37,42 ****
--- 51,60 ----
INSTR_TIME_SET_CURRENT(instr->starttime);
else
elog(DEBUG2, "InstrStartNode called twice in a row");
+
+ /* initialize buffer usage per plan node */
+ if (instr->needs_bufusage)
+ instr->bufusage_start = pgBufferUsage;
}
/* Exit from a plan node */
*************** InstrStopNode(Instrumentation *instr, do
*** 59,64 ****
--- 77,87 ----
INSTR_TIME_SET_ZERO(instr->starttime);
+ /* Adds delta of buffer usage to node's count. */
+ if (instr->needs_bufusage)
+ BufferUsageAccumDiff(&instr->bufusage,
+ &pgBufferUsage, &instr->bufusage_start);
+
/* Is this the first tuple of this cycle? */
if (!instr->running)
{
*************** InstrEndLoop(Instrumentation *instr)
*** 95,97 ****
--- 118,136 ----
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 -cprN head/src/backend/executor/spi.c work/src/backend/executor/spi.c
*** head/src/backend/executor/spi.c 2009-11-06 09:53:35.834256000 +0900
--- work/src/backend/executor/spi.c 2009-12-14 13:21:28.660753362 +0900
*************** _SPI_execute_plan(SPIPlanPtr plan, Param
*** 1908,1914 ****
plansource->query_string,
snap, crosscheck_snapshot,
dest,
! paramLI, false);
res = _SPI_pquery(qdesc, fire_triggers,
canSetTag ? tcount : 0);
FreeQueryDesc(qdesc);
--- 1908,1914 ----
plansource->query_string,
snap, crosscheck_snapshot,
dest,
! paramLI, 0);
res = _SPI_pquery(qdesc, fire_triggers,
canSetTag ? tcount : 0);
FreeQueryDesc(qdesc);
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-05 00:22:25.168790000 +0900
--- work/src/backend/storage/buffer/buf_init.c 2009-12-14 11:32:38.421721964 +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-12 09:52:43.356212000 +0900
--- work/src/backend/storage/buffer/bufmgr.c 2009-12-14 11:32:38.422722048 +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.shared_blks_hit++;
! else
! pgBufferUsage.shared_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.shared_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-12 09:52:43.356212000 +0900
--- work/src/backend/storage/buffer/localbuf.c 2009-12-14 11:32:38.422722048 +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-12 09:52:43.356212000 +0900
--- work/src/backend/storage/file/buffile.c 2009-12-14 11:32:38.422722048 +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-06 09:53:35.834256000 +0900
--- work/src/backend/tcop/postgres.c 2009-12-14 11:32:38.423855423 +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/backend/tcop/pquery.c work/src/backend/tcop/pquery.c
*** head/src/backend/tcop/pquery.c 2009-10-13 09:24:03.097662000 +0900
--- work/src/backend/tcop/pquery.c 2009-12-14 13:21:28.483752760 +0900
*************** CreateQueryDesc(PlannedStmt *plannedstmt
*** 67,73 ****
Snapshot crosscheck_snapshot,
DestReceiver *dest,
ParamListInfo params,
! bool doInstrument)
{
QueryDesc *qd = (QueryDesc *) palloc(sizeof(QueryDesc));
--- 67,73 ----
Snapshot crosscheck_snapshot,
DestReceiver *dest,
ParamListInfo params,
! int instrument_options)
{
QueryDesc *qd = (QueryDesc *) palloc(sizeof(QueryDesc));
*************** CreateQueryDesc(PlannedStmt *plannedstmt
*** 80,86 ****
qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot);
qd->dest = dest; /* output dest */
qd->params = params; /* parameter values passed into query */
! qd->doInstrument = doInstrument; /* instrumentation wanted? */
/* null these fields until set by ExecutorStart */
qd->tupDesc = NULL;
--- 80,86 ----
qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot);
qd->dest = dest; /* output dest */
qd->params = params; /* parameter values passed into query */
! qd->instrument_options = instrument_options; /* instrumentation wanted? */
/* null these fields until set by ExecutorStart */
qd->tupDesc = NULL;
*************** CreateUtilityQueryDesc(Node *utilitystmt
*** 111,117 ****
qd->crosscheck_snapshot = InvalidSnapshot; /* RI check snapshot */
qd->dest = dest; /* output dest */
qd->params = params; /* parameter values passed into query */
! qd->doInstrument = false; /* uninteresting for utilities */
/* null these fields until set by ExecutorStart */
qd->tupDesc = NULL;
--- 111,117 ----
qd->crosscheck_snapshot = InvalidSnapshot; /* RI check snapshot */
qd->dest = dest; /* output dest */
qd->params = params; /* parameter values passed into query */
! qd->instrument_options = false; /* uninteresting for utilities */
/* null these fields until set by ExecutorStart */
qd->tupDesc = NULL;
*************** ProcessQuery(PlannedStmt *plan,
*** 178,184 ****
*/
queryDesc = CreateQueryDesc(plan, sourceText,
GetActiveSnapshot(), InvalidSnapshot,
! dest, params, false);
/*
* Set up to collect AFTER triggers
--- 178,184 ----
*/
queryDesc = CreateQueryDesc(plan, sourceText,
GetActiveSnapshot(), InvalidSnapshot,
! dest, params, 0);
/*
* Set up to collect AFTER triggers
*************** PortalStart(Portal portal, ParamListInfo
*** 515,521 ****
InvalidSnapshot,
None_Receiver,
params,
! false);
/*
* We do *not* call AfterTriggerBeginQuery() here. We assume
--- 515,521 ----
InvalidSnapshot,
None_Receiver,
params,
! 0);
/*
* We do *not* call AfterTriggerBeginQuery() here. We assume
diff -cprN head/src/include/commands/explain.h work/src/include/commands/explain.h
*** head/src/include/commands/explain.h 2009-12-14 09:21:34.822978000 +0900
--- work/src/include/commands/explain.h 2009-12-14 11:32:38.424717292 +0900
*************** typedef struct ExplainState
*** 30,35 ****
--- 30,36 ----
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/execdesc.h work/src/include/executor/execdesc.h
*** head/src/include/executor/execdesc.h 2009-01-05 00:22:25.168790000 +0900
--- work/src/include/executor/execdesc.h 2009-12-14 13:16:23.718736978 +0900
*************** typedef struct QueryDesc
*** 42,48 ****
Snapshot crosscheck_snapshot; /* crosscheck for RI update/delete */
DestReceiver *dest; /* the destination for tuple output */
ParamListInfo params; /* param values being passed in */
! bool doInstrument; /* TRUE requests runtime instrumentation */
/* These fields are set by ExecutorStart */
TupleDesc tupDesc; /* descriptor for result tuples */
--- 42,48 ----
Snapshot crosscheck_snapshot; /* crosscheck for RI update/delete */
DestReceiver *dest; /* the destination for tuple output */
ParamListInfo params; /* param values being passed in */
! int instrument_options; /* OR of InstrumentOption flags */
/* These fields are set by ExecutorStart */
TupleDesc tupDesc; /* descriptor for result tuples */
*************** extern QueryDesc *CreateQueryDesc(Planne
*** 60,66 ****
Snapshot crosscheck_snapshot,
DestReceiver *dest,
ParamListInfo params,
! bool doInstrument);
extern QueryDesc *CreateUtilityQueryDesc(Node *utilitystmt,
const char *sourceText,
--- 60,66 ----
Snapshot crosscheck_snapshot,
DestReceiver *dest,
ParamListInfo params,
! int instrument_options);
extern QueryDesc *CreateUtilityQueryDesc(Node *utilitystmt,
const char *sourceText,
diff -cprN head/src/include/executor/executor.h work/src/include/executor/executor.h
*** head/src/include/executor/executor.h 2009-12-09 13:45:22.745455000 +0900
--- work/src/include/executor/executor.h 2009-12-14 13:09:03.597764161 +0900
*************** extern void InitResultRelInfo(ResultRelI
*** 161,167 ****
Relation resultRelationDesc,
Index resultRelationIndex,
CmdType operation,
! bool doInstrument);
extern ResultRelInfo *ExecGetTriggerResultRel(EState *estate, Oid relid);
extern bool ExecContextForcesOids(PlanState *planstate, bool *hasoids);
extern void ExecConstraints(ResultRelInfo *resultRelInfo,
--- 161,167 ----
Relation resultRelationDesc,
Index resultRelationIndex,
CmdType operation,
! int instrument_options);
extern ResultRelInfo *ExecGetTriggerResultRel(EState *estate, Oid relid);
extern bool ExecContextForcesOids(PlanState *planstate, bool *hasoids);
extern void ExecConstraints(ResultRelInfo *resultRelInfo,
diff -cprN head/src/include/executor/instrument.h work/src/include/executor/instrument.h
*** head/src/include/executor/instrument.h 2009-01-05 00:22:25.168790000 +0900
--- work/src/include/executor/instrument.h 2009-12-14 13:17:12.753756326 +0900
***************
*** 16,37 ****
#include "portability/instr_time.h"
typedef struct Instrumentation
{
/* Info about current plan cycle: */
bool running; /* TRUE if we've completed first tuple */
instr_time starttime; /* Start time of current iteration of node */
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 */
/* 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 */
} Instrumentation;
! extern Instrumentation *InstrAlloc(int n);
extern void InstrStartNode(Instrumentation *instr);
extern void InstrStopNode(Instrumentation *instr, double nTuples);
extern void InstrEndLoop(Instrumentation *instr);
--- 16,61 ----
#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 enum InstrumentOption
+ {
+ INSTRUMENT_TIMER = 1 << 0, /* needs timer */
+ INSTRUMENT_BUFFERS = 1 << 1, /* needs buffer usage */
+ INSTRUMENT_ALL = 0x7FFFFFFF
+ } InstrumentOption;
+
typedef struct Instrumentation
{
/* Info about current plan cycle: */
bool running; /* TRUE if we've completed first tuple */
+ bool needs_bufusage; /* TRUE if we need buffer usage */
instr_time starttime; /* Start time of current iteration of node */
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, int instrument_options);
extern void InstrStartNode(Instrumentation *instr);
extern void InstrStopNode(Instrumentation *instr, double nTuples);
extern void InstrEndLoop(Instrumentation *instr);
diff -cprN head/src/include/nodes/execnodes.h work/src/include/nodes/execnodes.h
*** head/src/include/nodes/execnodes.h 2009-12-09 13:45:22.745455000 +0900
--- work/src/include/nodes/execnodes.h 2009-12-14 13:09:42.846822263 +0900
*************** typedef struct EState
*** 370,376 ****
uint32 es_processed; /* # of tuples processed */
Oid es_lastoid; /* last oid processed (by INSERT) */
! bool es_instrument; /* true requests runtime instrumentation */
bool es_select_into; /* true if doing SELECT INTO */
bool es_into_oids; /* true to generate OIDs in SELECT INTO */
--- 370,376 ----
uint32 es_processed; /* # of tuples processed */
Oid es_lastoid; /* last oid processed (by INSERT) */
! int es_instrument; /* OR of InstrumentOption flags */
bool es_select_into; /* true if doing SELECT INTO */
bool es_into_oids; /* true to generate OIDs in SELECT INTO */
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-12 09:52:43.356212000 +0900
--- work/src/include/storage/buf_internals.h 2009-12-14 11:32:38.424717292 +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-12 09:52:43.356212000 +0900
--- work/src/include/storage/bufmgr.h 2009-12-14 11:32:38.424717292 +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 ----