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-12-09 13:54:40.292404947 +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-12-09 13:54:40.293421709 +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-12-09 13:59:44.985468000 +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,162 ---- + BUFFERS + + + Include information on the buffers. 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 of an upper-level + node includes the blocks of all its child nodes. This parameter should + be used with ANALYZE parameter. It 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-12-09 14:19:50.048388685 +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 *** 148,153 **** --- 150,160 ---- 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). *************** ExplainNode(Plan *plan, PlanState *plans *** 1040,1045 **** --- 1047,1083 ---- 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: (shared hit=%ld read=%ld written=%ld) " + "(local hit=%ld read=%ld written=%ld) " + "(temp read=%ld written=%ld)\n", + usage->shared_blks_hit, usage->shared_blks_read, + usage->shared_blks_written, + usage->local_blks_hit, usage->local_blks_read, + usage->local_blks_written, + usage->temp_blks_read, usage->temp_blks_written); + } + 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/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-12-09 13:54:40.294422165 +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,78 ---- INSTR_TIME_SET_ZERO(instr->starttime); + /* + * Adds delta of buffer usage to node's count and resets counter to start + * so that the counters are not double counted by parent nodes. + */ + BufferUsageAccumDiff(&instr->bufusage, + &pgBufferUsage, &instr->bufusage_start); + /* Is this the first tuple of this cycle? */ if (!instr->running) { *************** InstrEndLoop(Instrumentation *instr) *** 95,97 **** --- 109,127 ---- 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/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-12-09 13:54:40.295553562 +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-12-09 13:54:40.296426875 +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-11 23:49:01.000000000 +0900 --- work/src/backend/storage/buffer/localbuf.c 2009-12-09 13:54:40.296426875 +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-12-09 13:54:40.296426875 +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-12-09 13:54:40.297410363 +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-12-09 13:54:40.298406797 +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-12-09 13:54:40.298406797 +0900 *************** *** 16,21 **** --- 16,33 ---- #include "portability/instr_time.h" + typedef struct BufferUsage + { + long shared_blks_hit; /* # of shared buffer hits */ + long shared_blks_read; /* # of shared disk blocks read */ + long shared_blks_written; /* # of shared disk blocks written */ + long local_blks_hit; /* # of local buffer hits */ + long local_blks_read; /* # of local disk blocks read */ + long local_blks_written; /* # of local disk blocks written */ + long temp_blks_read; /* # of temp blocks read */ + long temp_blks_written; /* # of temp blocks written */ + } BufferUsage; + typedef struct Instrumentation { /* Info about current plan cycle: */ *************** 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-12-09 13:54:40.298406797 +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-12-09 13:54:40.299427251 +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 ----