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 ----