On Thu, Dec 10, 2009 at 9:35 PM, Takahiro Itagaki <itagaki.takah...@oss.ntt.co.jp> wrote: > Anyway, a revised patch according to the comments is attached. > The new text format is: > Buffers: shared hit=675 read=968, temp read=1443 written=1443 > * Zero values are omitted. (Non-text formats could have zero values.) > * Rename "Blocks:" to "Buffers:". > * Remove parentheses and add a comma between shared, local and temp.
I did a bit of copy-editing of your doc changes to make the English a bit more correct and idiomatic. Slightly revised patch attached for your consideration. The output format looks really nice (thanks for bearing with me), and the functionality is great. ...Robert
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 75ac9ca..88c33c0 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -22,6 +22,7 @@ PG_MODULE_MAGIC; 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; @@ -93,6 +94,16 @@ _PG_init(void) 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, @@ -219,8 +230,10 @@ explain_ExecutorEnd(QueryDesc *queryDesc) ExplainState es; ExplainInitState(&es); - es.analyze = (queryDesc->doInstrument && auto_explain_log_analyze); + 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 --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml index dd3f3fd..1b9d4d9 100644 --- a/doc/src/sgml/auto-explain.sgml +++ b/doc/src/sgml/auto-explain.sgml @@ -104,6 +104,25 @@ LOAD 'auto_explain'; <varlistentry> <term> + <varname>auto_explain.log_buffers</varname> (<type>boolean</type>) + </term> + <indexterm> + <primary><varname>auto_explain.log_buffers</> configuration parameter</primary> + </indexterm> + <listitem> + <para> + <varname>auto_explain.log_buffers</varname> causes <command>EXPLAIN + (ANALYZE, BUFFERS)</> output, rather than just <command>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 <varname>auto_explain.log_analyze</> + parameter is set. + </para> + </listitem> + </varlistentry> + + <varlistentry> + <term> <varname>auto_explain.log_format</varname> (<type>enum</type>) </term> <indexterm> diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index 0d03469..c90a028 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -31,7 +31,7 @@ PostgreSQL documentation <refsynopsisdiv> <synopsis> -EXPLAIN [ ( { ANALYZE <replaceable class="parameter">boolean</replaceable> | VERBOSE <replaceable class="parameter">boolean</replaceable> | COSTS <replaceable class="parameter">boolean</replaceable> | FORMAT { TEXT | XML | JSON | YAML } } [, ...] ) ] <replaceable class="parameter">statement</replaceable> +EXPLAIN [ ( { ANALYZE <replaceable class="parameter">boolean</replaceable> | VERBOSE <replaceable class="parameter">boolean</replaceable> | COSTS <replaceable class="parameter">boolean</replaceable> | BUFFERS <replaceable class="parameter">boolean</replaceable> | FORMAT { TEXT | XML | JSON | YAML } } [, ...] ) ] <replaceable class="parameter">statement</replaceable> EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="parameter">statement</replaceable> </synopsis> </refsynopsisdiv> @@ -140,6 +140,23 @@ ROLLBACK; </varlistentry> <varlistentry> + <term><literal>BUFFERS</literal></term> + <listitem> + <para> + 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. This + parameter may only be used with <literal>ANALYZE</literal> parameter. + It defaults to <literal>FALSE</literal>. + </para> + </listitem> + </varlistentry> + + <varlistentry> <term><literal>FORMAT</literal></term> <listitem> <para> diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 0437ffa..0aba2a7 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -127,6 +127,8 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString, 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); @@ -152,6 +154,11 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString, 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). @@ -1044,6 +1051,84 @@ ExplainNode(Plan *plan, PlanState *planstate, 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 --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index d8d7039..8690581 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -17,6 +17,10 @@ #include "executor/instrument.h" +BufferUsage pgBufferUsage; + +static void BufferUsageAccumDiff(BufferUsage *dst, + const BufferUsage *add, const BufferUsage *sub); /* Allocate new instrumentation structure(s) */ Instrumentation * @@ -37,6 +41,9 @@ InstrStartNode(Instrumentation *instr) 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 */ @@ -59,6 +66,13 @@ InstrStopNode(Instrumentation *instr, double nTuples) 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) { @@ -95,3 +109,19 @@ InstrEndLoop(Instrumentation *instr) 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 --git a/src/backend/storage/buffer/buf_init.c b/src/backend/storage/buffer/buf_init.c index e0211f5..cc434c3 100644 --- a/src/backend/storage/buffer/buf_init.c +++ b/src/backend/storage/buffer/buf_init.c @@ -22,16 +22,6 @@ BufferDesc *BufferDescriptors; 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: diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c index de28374..276723d 100644 --- a/src/backend/storage/buffer/bufmgr.c +++ b/src/backend/storage/buffer/bufmgr.c @@ -34,6 +34,7 @@ #include <unistd.h> #include "catalog/catalog.h" +#include "executor/instrument.h" #include "miscadmin.h" #include "pg_trace.h" #include "pgstat.h" @@ -300,22 +301,23 @@ ReadBuffer_common(SMgrRelation smgr, bool isLocalBuf, ForkNumber forkNum, if (isLocalBuf) { - ReadLocalBufferCount++; bufHdr = LocalBufferAlloc(smgr, forkNum, blockNum, &found); if (found) - LocalBufferHitCount++; + pgBufferUsage.local_blks_hit++; + else + pgBufferUsage.local_blks_read++; } 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++; + pgBufferUsage.shared_blks_hit++; + else + pgBufferUsage.shared_blks_read++; } /* At this point we do NOT hold any locks. */ @@ -1611,54 +1613,6 @@ SyncOneBuffer(int buf_id, bool skip_recently_used) /* - * 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 @@ -1916,7 +1870,7 @@ FlushBuffer(volatile BufferDesc *buf, SMgrRelation reln) (char *) BufHdrGetBlock(buf), false); - BufferFlushCount++; + pgBufferUsage.shared_blks_written++; /* * Mark the buffer as clean (unless BM_JUST_DIRTIED has become set) and diff --git a/src/backend/storage/buffer/localbuf.c b/src/backend/storage/buffer/localbuf.c index 641f8e9..c7d25b9 100644 --- a/src/backend/storage/buffer/localbuf.c +++ b/src/backend/storage/buffer/localbuf.c @@ -16,6 +16,7 @@ #include "postgres.h" #include "catalog/catalog.h" +#include "executor/instrument.h" #include "storage/buf_internals.h" #include "storage/bufmgr.h" #include "storage/smgr.h" @@ -209,7 +210,7 @@ LocalBufferAlloc(SMgrRelation smgr, ForkNumber forkNum, BlockNumber blockNum, /* Mark not-dirty now in case we error out below */ bufHdr->flags &= ~BM_DIRTY; - LocalBufferFlushCount++; + pgBufferUsage.local_blks_written++; } /* diff --git a/src/backend/storage/file/buffile.c b/src/backend/storage/file/buffile.c index 436a82b..ebe77ff 100644 --- a/src/backend/storage/file/buffile.c +++ b/src/backend/storage/file/buffile.c @@ -34,6 +34,7 @@ #include "postgres.h" +#include "executor/instrument.h" #include "storage/fd.h" #include "storage/buffile.h" #include "storage/buf_internals.h" @@ -240,7 +241,7 @@ BufFileLoadBuffer(BufFile *file) file->offsets[file->curFile] += file->nbytes; /* we choose not to advance curOffset here */ - BufFileReadCount++; + pgBufferUsage.temp_blks_read++; } /* @@ -304,7 +305,7 @@ BufFileDumpBuffer(BufFile *file) file->curOffset += bytestowrite; wpos += bytestowrite; - BufFileWriteCount++; + pgBufferUsage.temp_blks_written++; } file->dirty = false; diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 0672652..c985478 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -3901,7 +3901,6 @@ ResetUsage(void) { getrusage(RUSAGE_SELF, &Save_r); gettimeofday(&Save_t, NULL); - ResetBufferUsage(); } void @@ -3912,7 +3911,6 @@ ShowUsage(const char *title) sys; struct timeval elapse_t; struct rusage r; - char *bufusage; getrusage(RUSAGE_SELF, &r); gettimeofday(&elapse_t, NULL); @@ -3986,10 +3984,6 @@ ShowUsage(const char *title) 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'; diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index ab48825..f97c0ee 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -30,6 +30,7 @@ typedef struct ExplainState 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 --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 9846f6f..4bb6f91 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -16,6 +16,18 @@ #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: */ @@ -24,13 +36,17 @@ typedef struct Instrumentation 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 --git a/src/include/storage/buf_internals.h b/src/include/storage/buf_internals.h index 841cf09..42ed94e 100644 --- a/src/include/storage/buf_internals.h +++ b/src/include/storage/buf_internals.h @@ -173,16 +173,6 @@ extern PGDLLIMPORT BufferDesc *BufferDescriptors; /* 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 diff --git a/src/include/storage/bufmgr.h b/src/include/storage/bufmgr.h index d06eb77..f8d685c 100644 --- a/src/include/storage/bufmgr.h +++ b/src/include/storage/bufmgr.h @@ -173,8 +173,6 @@ extern Buffer ReleaseAndReadBuffer(Buffer buffer, Relation relation, 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);
-- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers