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-10-01 11:17:24.503897062 +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 *** 220,225 **** --- 231,237 ---- 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; ExplainPrintPlan(&es, queryDesc); 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-07-27 13:09:55.000000000 +0900 --- work/contrib/pg_stat_statements/pg_stat_statements.c 2009-10-01 11:17:24.504906936 +0900 *************** *** 26,31 **** --- 26,32 ---- #include "catalog/pg_type.h" #include "executor/executor.h" #include "executor/instrument.h" + #include "funcapi.h" #include "mb/pg_wchar.h" #include "miscadmin.h" #include "pgstat.h" *************** PG_MODULE_MAGIC; *** 43,49 **** #define PGSS_DUMP_FILE "global/pg_stat_statements.stat" /* This constant defines the magic number in the stats file header */ ! static const uint32 PGSS_FILE_HEADER = 0x20081202; /* XXX: Should USAGE_EXEC reflect execution time and/or buffer usage? */ #define USAGE_EXEC(duration) (1.0) --- 44,50 ---- #define PGSS_DUMP_FILE "global/pg_stat_statements.stat" /* This constant defines the magic number in the stats file header */ ! static const uint32 PGSS_FILE_HEADER = 0x20090928; /* XXX: Should USAGE_EXEC reflect execution time and/or buffer usage? */ #define USAGE_EXEC(duration) (1.0) *************** typedef struct Counters *** 77,82 **** --- 78,86 ---- int64 calls; /* # of times executed */ double total_time; /* total execution time in seconds */ int64 rows; /* total # of retrieved or affected rows */ + int64 hit; /* total # of buffer hits */ + int64 read; /* total # of disk blocks read */ + int64 temp; /* total # of local buffer read */ double usage; /* usage factor */ } Counters; *************** pgss_store(const char *query, const Inst *** 633,638 **** --- 637,645 ---- e->counters.calls += 1; e->counters.total_time += instr->total; e->counters.rows += rows; + e->counters.hit += instr->buffers_hit; + e->counters.read += instr->buffers_read; + e->counters.temp += instr->buffers_temp; e->counters.usage += usage; SpinLockRelease(&e->mutex); } *************** pg_stat_statements_reset(PG_FUNCTION_ARG *** 654,660 **** PG_RETURN_VOID(); } ! #define PG_STAT_STATEMENTS_COLS 6 /* * Retrieve statement statistics. --- 661,667 ---- PG_RETURN_VOID(); } ! #define PG_STAT_STATEMENTS_COLS 9 /* * Retrieve statement statistics. *************** pg_stat_statements(PG_FUNCTION_ARGS) *** 688,709 **** errmsg("materialize mode required, but it is not " \ "allowed in this context"))); per_query_ctx = rsinfo->econtext->ecxt_per_query_memory; oldcontext = MemoryContextSwitchTo(per_query_ctx); ! tupdesc = CreateTemplateTupleDesc(PG_STAT_STATEMENTS_COLS, false); ! TupleDescInitEntry(tupdesc, (AttrNumber) 1, "userid", ! OIDOID, -1, 0); ! TupleDescInitEntry(tupdesc, (AttrNumber) 2, "dbid", ! OIDOID, -1, 0); ! TupleDescInitEntry(tupdesc, (AttrNumber) 3, "query", ! TEXTOID, -1, 0); ! TupleDescInitEntry(tupdesc, (AttrNumber) 4, "calls", ! INT8OID, -1, 0); ! TupleDescInitEntry(tupdesc, (AttrNumber) 5, "total_time", ! FLOAT8OID, -1, 0); ! TupleDescInitEntry(tupdesc, (AttrNumber) 6, "rows", ! INT8OID, -1, 0); tupstore = tuplestore_begin_heap(true, false, work_mem); rsinfo->returnMode = SFRM_Materialize; --- 695,708 ---- errmsg("materialize mode required, but it is not " \ "allowed in this context"))); + /* Build a tuple descriptor for our result type */ + if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE) + elog(ERROR, "return type must be a row type"); + per_query_ctx = rsinfo->econtext->ecxt_per_query_memory; oldcontext = MemoryContextSwitchTo(per_query_ctx); ! tupdesc = CreateTupleDescCopy(tupdesc); tupstore = tuplestore_begin_heap(true, false, work_mem); rsinfo->returnMode = SFRM_Materialize; *************** pg_stat_statements(PG_FUNCTION_ARGS) *** 757,762 **** --- 756,764 ---- values[i++] = Int64GetDatumFast(tmp.calls); values[i++] = Float8GetDatumFast(tmp.total_time); values[i++] = Int64GetDatumFast(tmp.rows); + values[i++] = Int64GetDatumFast(tmp.hit); + values[i++] = Int64GetDatumFast(tmp.read); + values[i++] = Int64GetDatumFast(tmp.temp); Assert(i == PG_STAT_STATEMENTS_COLS); diff -cprN head/contrib/pg_stat_statements/pg_stat_statements.sql.in work/contrib/pg_stat_statements/pg_stat_statements.sql.in *** head/contrib/pg_stat_statements/pg_stat_statements.sql.in 2009-01-05 07:19:59.000000000 +0900 --- work/contrib/pg_stat_statements/pg_stat_statements.sql.in 2009-10-01 11:17:24.504906936 +0900 *************** CREATE FUNCTION pg_stat_statements( *** 15,21 **** OUT query text, OUT calls int8, OUT total_time float8, ! OUT rows int8 ) RETURNS SETOF record AS 'MODULE_PATHNAME' --- 15,24 ---- OUT query text, OUT calls int8, OUT total_time float8, ! OUT rows int8, ! OUT bufs_hit int8, ! OUT bufs_read int8, ! OUT bufs_temp int8 ) RETURNS SETOF record AS 'MODULE_PATHNAME' 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-10-01 11:17:24.505661275 +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/pgstatstatements.sgml work/doc/src/sgml/pgstatstatements.sgml *** head/doc/src/sgml/pgstatstatements.sgml 2009-05-18 20:08:24.000000000 +0900 --- work/doc/src/sgml/pgstatstatements.sgml 2009-10-01 11:17:24.505661275 +0900 *************** *** 85,90 **** --- 85,111 ---- Total number of rows retrieved or affected by the statement + + bufs_hit + bigint + + Total number of buffer hits by the statement + + + + bufs_read + bigint + + Total number of disk blocks read by the statement + + + + bufs_temp + bigint + + Total number of local buffer read by the statement + + 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-10-01 11:17:24.505661275 +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 disc 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-08-22 11:06:32.000000000 +0900 --- work/src/backend/commands/explain.c 2009-10-01 11:17:24.506655332 +0900 *************** ExplainQuery(ExplainStmt *stmt, const ch *** 127,132 **** --- 127,134 ---- 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"))); + /* Convert parameter type data to the form parser wants */ getParamListTypes(params, ¶m_types, &num_params); *************** ExplainNode(Plan *plan, PlanState *plans *** 923,928 **** --- 930,954 ---- ExplainPropertyFloat("Actual Rows", rows, 0, es); ExplainPropertyFloat("Actual Loops", nloops, 0, es); } + + if (es->buffers) + { + long num_hit = planstate->instrument->buffers_hit; + long num_read = planstate->instrument->buffers_read; + long num_temp = planstate->instrument->buffers_temp; + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + appendStringInfo(es->str, " (hit=%ld read=%ld temp=%ld)", + num_hit, num_read, num_temp); + } + else + { + ExplainPropertyLong("Hit Buffers", num_hit, es); + ExplainPropertyLong("Read Buffers", num_read, es); + ExplainPropertyLong("Temp Buffers", num_temp, es); + } + } } else if (es->analyze) { diff -cprN head/src/backend/executor/execMain.c work/src/backend/executor/execMain.c *** head/src/backend/executor/execMain.c 2009-09-28 05:09:57.000000000 +0900 --- work/src/backend/executor/execMain.c 2009-10-01 11:17:24.507627637 +0900 *************** standard_ExecutorRun(QueryDesc *queryDes *** 267,272 **** --- 267,273 ---- DestReceiver *dest; bool sendTuples; MemoryContext oldcontext; + Instrumentation *save_TopInstrument = NULL; /* sanity checks */ Assert(queryDesc != NULL); *************** standard_ExecutorRun(QueryDesc *queryDes *** 282,288 **** --- 283,293 ---- /* Allow instrumentation of ExecutorRun overall runtime */ if (queryDesc->totaltime) + { InstrStartNode(queryDesc->totaltime); + save_TopInstrument = TopInstrument; + TopInstrument = queryDesc->totaltime; + } /* * extract information from the query descriptor and the query feature. *************** standard_ExecutorRun(QueryDesc *queryDes *** 320,326 **** --- 325,340 ---- (*dest->rShutdown) (dest); if (queryDesc->totaltime) + { InstrStopNode(queryDesc->totaltime, estate->es_processed); + if (save_TopInstrument) + { + save_TopInstrument->buffers_hit += queryDesc->totaltime->buffers_hit; + save_TopInstrument->buffers_read += queryDesc->totaltime->buffers_read; + save_TopInstrument->buffers_temp += queryDesc->totaltime->buffers_temp; + } + TopInstrument = save_TopInstrument; + } MemoryContextSwitchTo(oldcontext); } 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-10-01 11:19:17.666239902 +0900 *************** *** 16,22 **** --- 16,26 ---- #include #include "executor/instrument.h" + #include "storage/buf_internals.h" + #include "storage/bufmgr.h" + Instrumentation *CurrentInstrument = NULL; + Instrumentation *TopInstrument = NULL; /* Allocate new instrumentation structure(s) */ Instrumentation * *************** InstrStartNode(Instrumentation *instr) *** 37,42 **** --- 41,50 ---- INSTR_TIME_SET_CURRENT(instr->starttime); else elog(DEBUG2, "InstrStartNode called twice in a row"); + + /* push stack */ + instr->prev = CurrentInstrument; + CurrentInstrument = instr; } /* Exit from a plan node */ *************** InstrStopNode(Instrumentation *instr, do *** 45,50 **** --- 53,88 ---- { instr_time endtime; + if (instr == CurrentInstrument) + { + long num_get = ReadBufferCount + ReadLocalBufferCount; + long num_hit = BufferHitCount + LocalBufferHitCount; + long num_read = num_get - num_hit; + long num_temp = BufFileReadCount; + + /* count buffer usage per plan node */ + instr->buffers_hit += num_hit; + instr->buffers_read += num_read; + instr->buffers_temp += num_temp; + + /* accumulate per-node buffer statistics into top node */ + if (TopInstrument && TopInstrument != CurrentInstrument) + { + TopInstrument->buffers_hit += num_hit; + TopInstrument->buffers_read += num_read; + TopInstrument->buffers_temp += num_temp; + } + + /* reset buffer usage and pop stack */ + ResetLocalBufferUsage(); + CurrentInstrument = instr->prev; + } + else + { + elog(DEBUG2, "Instrumentation stack is broken"); + return; + } + /* count the returned tuples */ instr->tuplecount += nTuples; 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-10-01 11:17:24.508671491 +0900 *************** static bool IsForInput; *** 79,84 **** --- 79,94 ---- /* local state for LockBufferForCleanup */ static volatile BufferDesc *PinCountWaitBuf = NULL; + /* statistics counters for log_[parser|planner|executor|statement]_stats */ + static long GlobalReadBufferCount; + static long GlobalReadLocalBufferCount; + static long GlobalBufferHitCount; + static long GlobalLocalBufferHitCount; + static long GlobalBufferFlushCount; + static long GlobalLocalBufferFlushCount; + static long GlobalBufFileReadCount; + static long GlobalBufFileWriteCount; + static Buffer ReadBuffer_common(SMgrRelation reln, bool isLocalBuf, ForkNumber forkNum, BlockNumber blockNum, *************** ShowBufferUsage(void) *** 1620,1646 **** 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; } --- 1630,1658 ---- float hitrate; float localhitrate; + ResetLocalBufferUsage(); + initStringInfo(&str); ! if (GlobalReadBufferCount == 0) hitrate = 0.0; else ! hitrate = (float) GlobalBufferHitCount *100.0 / GlobalReadBufferCount; ! if (GlobalReadLocalBufferCount == 0) localhitrate = 0.0; else ! localhitrate = (float) GlobalLocalBufferHitCount *100.0 / GlobalReadLocalBufferCount; appendStringInfo(&str, "!\tShared blocks: %10ld read, %10ld written, buffer hit rate = %.2f%%\n", ! GlobalReadBufferCount - GlobalBufferHitCount, GlobalBufferFlushCount, hitrate); appendStringInfo(&str, "!\tLocal blocks: %10ld read, %10ld written, buffer hit rate = %.2f%%\n", ! GlobalReadLocalBufferCount - GlobalLocalBufferHitCount, GlobalLocalBufferFlushCount, localhitrate); appendStringInfo(&str, "!\tDirect blocks: %10ld read, %10ld written\n", ! GlobalBufFileReadCount, GlobalBufFileWriteCount); return str.data; } *************** ResetBufferUsage(void) *** 1656,1661 **** --- 1668,1704 ---- LocalBufferFlushCount = 0; BufFileReadCount = 0; BufFileWriteCount = 0; + + GlobalBufferHitCount = 0; + GlobalReadBufferCount = 0; + GlobalBufferFlushCount = 0; + GlobalLocalBufferHitCount = 0; + GlobalReadLocalBufferCount = 0; + GlobalLocalBufferFlushCount = 0; + GlobalBufFileReadCount = 0; + GlobalBufFileWriteCount = 0; + } + + void + ResetLocalBufferUsage(void) + { + BufferHitCount = 0; + ReadBufferCount = 0; + BufferFlushCount = 0; + LocalBufferHitCount = 0; + ReadLocalBufferCount = 0; + LocalBufferFlushCount = 0; + BufFileReadCount = 0; + BufFileWriteCount = 0; + + GlobalReadBufferCount += ReadBufferCount; + GlobalReadLocalBufferCount += ReadLocalBufferCount; + GlobalBufferHitCount += BufferHitCount; + GlobalLocalBufferHitCount += LocalBufferHitCount; + GlobalBufferFlushCount += BufferFlushCount; + GlobalLocalBufferFlushCount += LocalBufferFlushCount; + GlobalBufFileReadCount += BufFileReadCount; + GlobalBufFileWriteCount += BufFileWriteCount; } /* diff -cprN head/src/backend/tcop/postgres.c work/src/backend/tcop/postgres.c *** head/src/backend/tcop/postgres.c 2009-09-01 11:54:51.000000000 +0900 --- work/src/backend/tcop/postgres.c 2009-10-01 11:17:24.510655527 +0900 *************** *** 44,49 **** --- 44,50 ---- #include "catalog/pg_type.h" #include "commands/async.h" #include "commands/prepare.h" + #include "executor/instrument.h" #include "libpq/libpq.h" #include "libpq/pqformat.h" #include "libpq/pqsignal.h" *************** PostgresMain(int argc, char *argv[], con *** 3482,3487 **** --- 3483,3492 ---- */ doing_extended_query_message = false; + /* Reset buffer usage counters */ + CurrentInstrument = TopInstrument = NULL; + ResetLocalBufferUsage(); + /* * Release storage left over from prior query cycle, and create a new * query input buffer in the cleared MessageContext. 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-10-01 11:17:24.510655527 +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-10-01 11:17:24.510655527 +0900 *************** typedef struct Instrumentation *** 29,36 **** --- 29,45 ---- double total; /* Total total time (in seconds) */ double ntuples; /* Total tuples produced */ double nloops; /* # of run cycles for this node */ + /* Buffer usage */ + long buffers_hit; /* # of buffer hits */ + long buffers_read; /* # of disk blocks read */ + long buffers_temp; /* # of local buffer read */ + /* previous node in stack */ + struct Instrumentation *prev; } Instrumentation; + extern Instrumentation *CurrentInstrument; + extern Instrumentation *TopInstrument; + extern Instrumentation *InstrAlloc(int n); extern void InstrStartNode(Instrumentation *instr); extern void InstrStopNode(Instrumentation *instr, double nTuples); 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-10-01 11:17:24.511663344 +0900 *************** extern void InitBufferPoolAccess(void); *** 175,180 **** --- 175,181 ---- extern void InitBufferPoolBackend(void); extern char *ShowBufferUsage(void); extern void ResetBufferUsage(void); + extern void ResetLocalBufferUsage(void); extern void AtEOXact_Buffers(bool isCommit); extern void PrintBufferLeakWarning(Buffer buffer); extern void CheckPointBuffers(int flags);