Add an EXPLAIN (BUFFERS) option to show buffer-usage statistics.

This patch also removes buffer-usage statistics from the track_counts
output, since this (or the global server statistics) is deemed to be a better
interface to this information.

Itagaki Takahiro, reviewed by Euler Taveira de Oliveira.

contrib/auto_explain/auto_explain.c

@@ -6,7 +6,7 @@
  * Copyright (c) 2008-2009, PostgreSQL Global Development Group
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/contrib/auto_explain/auto_explain.c,v 1.9 2009/12/12 00:35:33 rhaas Exp $
+ *	  $PostgreSQL: pgsql/contrib/auto_explain/auto_explain.c,v 1.10 2009/12/15 04:57:46 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -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,
@@ -147,7 +158,11 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
 	{
 		/* Enable per-node instrumentation iff log_analyze is required. */
 		if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
-			queryDesc->doInstrument = true;
+		{
+			queryDesc->instrument_options |= INSTRUMENT_TIMER;
+			if (auto_explain_log_buffers)
+				queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
+		}
 	}
 
 	if (prev_ExecutorStart)
@@ -167,7 +182,7 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
 			MemoryContext oldcxt;
 
 			oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
-			queryDesc->totaltime = InstrAlloc(1);
+			queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
 			MemoryContextSwitchTo(oldcxt);
 		}
 	}
@@ -219,8 +234,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
 			ExplainState	es;
 
 			ExplainInitState(&es);
-			es.analyze = (queryDesc->doInstrument && auto_explain_log_analyze);
+			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);

contrib/pg_stat_statements/pg_stat_statements.c

@@ -14,7 +14,7 @@
  * Copyright (c) 2008-2009, PostgreSQL Global Development Group
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/contrib/pg_stat_statements/pg_stat_statements.c,v 1.7 2009/12/01 02:31:11 momjian Exp $
+ *	  $PostgreSQL: pgsql/contrib/pg_stat_statements/pg_stat_statements.c,v 1.8 2009/12/15 04:57:46 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -495,7 +495,7 @@ pgss_ExecutorStart(QueryDesc *queryDesc, int eflags)
 			MemoryContext oldcxt;
 
 			oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
-			queryDesc->totaltime = InstrAlloc(1);
+			queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
 			MemoryContextSwitchTo(oldcxt);
 		}
 	}

doc/src/sgml/auto-explain.sgml

@@ -1,4 +1,4 @@
-<!-- $PostgreSQL: pgsql/doc/src/sgml/auto-explain.sgml,v 1.5 2009/12/11 01:33:35 adunstan Exp $ -->
+<!-- $PostgreSQL: pgsql/doc/src/sgml/auto-explain.sgml,v 1.6 2009/12/15 04:57:47 rhaas Exp $ -->
 
 <sect1 id="auto-explain">
  <title>auto_explain</title>
@@ -102,6 +102,25 @@ LOAD 'auto_explain';
     </listitem>
    </varlistentry>
 
+   <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>)

doc/src/sgml/ref/explain.sgml

@@ -1,5 +1,5 @@
 <!--
-$PostgreSQL: pgsql/doc/src/sgml/ref/explain.sgml,v 1.47 2009/12/11 01:33:35 adunstan Exp $
+$PostgreSQL: pgsql/doc/src/sgml/ref/explain.sgml,v 1.48 2009/12/15 04:57:47 rhaas Exp $
 PostgreSQL documentation
 -->
 
@@ -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>
@@ -139,6 +139,24 @@ ROLLBACK;
     </listitem>
    </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.  In text
+      format, only non-zero values are printed.  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>

src/backend/commands/copy.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/commands/copy.c,v 1.318 2009/11/20 20:38:10 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/commands/copy.c,v 1.319 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -1094,7 +1094,7 @@ DoCopy(const CopyStmt *stmt, const char *queryString)
 		cstate->queryDesc = CreateQueryDesc(plan, queryString,
 											GetActiveSnapshot(),
 											InvalidSnapshot,
-											dest, NULL, false);
+											dest, NULL, 0);
 
 		/*
 		 * Call ExecutorStart to prepare the plan for execution.

src/backend/commands/explain.c

@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1994-5, Regents of the University of California
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.195 2009/12/12 00:35:33 rhaas Exp $
+ *	  $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.196 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -125,6 +125,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);
@@ -150,6 +152,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).
@@ -339,6 +346,12 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es,
 	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
@@ -349,7 +362,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es,
 	/* Create a QueryDesc requesting no output */
 	queryDesc = CreateQueryDesc(plannedstmt, queryString,
 								GetActiveSnapshot(), InvalidSnapshot,
-								None_Receiver, params, es->analyze);
+								None_Receiver, params, instrument_option);
 
 	INSTR_TIME_SET_CURRENT(starttime);
 
@@ -1042,6 +1055,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) ||

src/backend/commands/tablecmds.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/commands/tablecmds.c,v 1.309 2009/12/11 03:34:55 itagaki Exp $
+ *	  $PostgreSQL: pgsql/src/backend/commands/tablecmds.c,v 1.310 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -936,7 +936,7 @@ ExecuteTruncate(TruncateStmt *stmt)
 						  rel,
 						  0,	/* dummy rangetable index */
 						  CMD_DELETE,	/* don't need any index info */
-						  false);
+						  0);
 		resultRelInfo++;
 	}
 	estate->es_result_relations = resultRelInfos;

src/backend/executor/execMain.c

@@ -26,7 +26,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/executor/execMain.c,v 1.337 2009/12/11 18:14:43 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/executor/execMain.c,v 1.338 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -180,7 +180,7 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags)
 	 */
 	estate->es_snapshot = RegisterSnapshot(queryDesc->snapshot);
 	estate->es_crosscheck_snapshot = RegisterSnapshot(queryDesc->crosscheck_snapshot);
-	estate->es_instrument = queryDesc->doInstrument;
+	estate->es_instrument = queryDesc->instrument_options;
 
 	/*
 	 * Initialize the plan state tree
@@ -859,7 +859,7 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo,
 				  Relation resultRelationDesc,
 				  Index resultRelationIndex,
 				  CmdType operation,
-				  bool doInstrument)
+				  int instrument_options)
 {
 	/*
 	 * Check valid relkind ... parser and/or planner should have noticed this
@@ -914,10 +914,8 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo,
 			palloc0(n * sizeof(FmgrInfo));
 		resultRelInfo->ri_TrigWhenExprs = (List **)
 			palloc0(n * sizeof(List *));
-		if (doInstrument)
+		if (instrument_options)
-			resultRelInfo->ri_TrigInstrument = InstrAlloc(n);
+			resultRelInfo->ri_TrigInstrument = InstrAlloc(n, instrument_options);
-		else
-			resultRelInfo->ri_TrigInstrument = NULL;
 	}
 	else
 	{

src/backend/executor/execProcnode.c

@@ -12,7 +12,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/executor/execProcnode.c,v 1.68 2009/10/12 18:10:41 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/executor/execProcnode.c,v 1.69 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -321,7 +321,7 @@ ExecInitNode(Plan *node, EState *estate, int eflags)
 
 	/* Set up instrumentation for this node if requested */
 	if (estate->es_instrument)
-		result->instrument = InstrAlloc(1);
+		result->instrument = InstrAlloc(1, estate->es_instrument);
 
 	return result;
 }

src/backend/executor/functions.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/executor/functions.c,v 1.137 2009/12/14 02:15:51 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/executor/functions.c,v 1.138 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -414,7 +414,7 @@ postquel_start(execution_state *es, SQLFunctionCachePtr fcache)
 								 fcache->src,
 								 snapshot, InvalidSnapshot,
 								 dest,
-								 fcache->paramLI, false);
+								 fcache->paramLI, 0);
 	else
 		es->qd = CreateUtilityQueryDesc(es->stmt,
 										fcache->src,

src/backend/executor/instrument.c

@@ -7,7 +7,7 @@
  * Copyright (c) 2001-2009, PostgreSQL Global Development Group
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/executor/instrument.c,v 1.22 2009/01/01 17:23:41 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/executor/instrument.c,v 1.23 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -17,14 +17,28 @@
 
 #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)
+InstrAlloc(int n, int instrument_options)
 {
-	Instrumentation *instr = palloc0(n * sizeof(Instrumentation));
+	Instrumentation *instr;
 
-	/* we don't need to do any initialization except zero 'em */
+	/* 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;
 }
@@ -37,6 +51,10 @@ InstrStartNode(Instrumentation *instr)
 		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 */
@@ -59,6 +77,11 @@ InstrStopNode(Instrumentation *instr, double nTuples)
 
 	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)
 	{
@@ -95,3 +118,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;
+}

src/backend/executor/spi.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/executor/spi.c,v 1.211 2009/11/04 22:26:06 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/executor/spi.c,v 1.212 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -1908,7 +1908,7 @@ _SPI_execute_plan(SPIPlanPtr plan, ParamListInfo paramLI,
 										plansource->query_string,
 										snap, crosscheck_snapshot,
 										dest,
-										paramLI, false);
+										paramLI, 0);
 				res = _SPI_pquery(qdesc, fire_triggers,
 								  canSetTag ? tcount : 0);
 				FreeQueryDesc(qdesc);

src/backend/storage/buffer/buf_init.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/storage/buffer/buf_init.c,v 1.82 2009/01/01 17:23:47 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/storage/buffer/buf_init.c,v 1.83 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -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:

src/backend/storage/buffer/bufmgr.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/storage/buffer/bufmgr.c,v 1.252 2009/06/11 14:49:01 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/storage/buffer/bufmgr.c,v 1.253 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -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. */
@@ -1610,54 +1612,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.
  *
@@ -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

src/backend/storage/buffer/localbuf.c

@@ -9,13 +9,14 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/storage/buffer/localbuf.c,v 1.87 2009/06/11 14:49:01 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/storage/buffer/localbuf.c,v 1.88 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
 #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++;
 	}
 
 	/*

src/backend/storage/file/buffile.c

@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1994, Regents of the University of California
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/storage/file/buffile.c,v 1.34 2009/06/11 14:49:01 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/storage/file/buffile.c,v 1.35 2009/12/15 04:57:47 rhaas Exp $
  *
  * NOTES:
  *
@@ -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;
 

src/backend/tcop/postgres.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.575 2009/11/04 22:26:06 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.576 2009/12/15 04:57:47 rhaas Exp $
  *
  * NOTES
  *	  this is the "main" module of the postgres backend and
@@ -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';

src/backend/tcop/pquery.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/tcop/pquery.c,v 1.132 2009/10/10 01:43:49 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/tcop/pquery.c,v 1.133 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -67,7 +67,7 @@ CreateQueryDesc(PlannedStmt *plannedstmt,
 				Snapshot crosscheck_snapshot,
 				DestReceiver *dest,
 				ParamListInfo params,
-				bool doInstrument)
+				int instrument_options)
 {
 	QueryDesc  *qd = (QueryDesc *) palloc(sizeof(QueryDesc));
 
@@ -80,7 +80,7 @@ CreateQueryDesc(PlannedStmt *plannedstmt,
 	qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot);
 	qd->dest = dest;			/* output dest */
 	qd->params = params;		/* parameter values passed into query */
-	qd->doInstrument = doInstrument;	/* instrumentation wanted? */
+	qd->instrument_options = instrument_options;	/* instrumentation wanted? */
 
 	/* null these fields until set by ExecutorStart */
 	qd->tupDesc = NULL;
@@ -111,7 +111,7 @@ CreateUtilityQueryDesc(Node *utilitystmt,
 	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 */
+	qd->instrument_options = false;	/* uninteresting for utilities */
 
 	/* null these fields until set by ExecutorStart */
 	qd->tupDesc = NULL;
@@ -178,7 +178,7 @@ ProcessQuery(PlannedStmt *plan,
 	 */
 	queryDesc = CreateQueryDesc(plan, sourceText,
 								GetActiveSnapshot(), InvalidSnapshot,
-								dest, params, false);
+								dest, params, 0);
 
 	/*
 	 * Set up to collect AFTER triggers
@@ -515,7 +515,7 @@ PortalStart(Portal portal, ParamListInfo params, Snapshot snapshot)
 											InvalidSnapshot,
 											None_Receiver,
 											params,
-											false);
+											0);
 
 				/*
 				 * We do *not* call AfterTriggerBeginQuery() here.	We assume

src/include/commands/explain.h

@@ -6,7 +6,7 @@
  * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994-5, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/commands/explain.h,v 1.43 2009/12/12 00:35:34 rhaas Exp $
+ * $PostgreSQL: pgsql/src/include/commands/explain.h,v 1.44 2009/12/15 04:57:47 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -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 */

src/include/executor/execdesc.h

@@ -8,7 +8,7 @@
  * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/executor/execdesc.h,v 1.40 2009/01/02 20:42:00 tgl Exp $
+ * $PostgreSQL: pgsql/src/include/executor/execdesc.h,v 1.41 2009/12/15 04:57:48 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -42,7 +42,7 @@ typedef struct QueryDesc
 	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 */
+	int			instrument_options;		/* OR of InstrumentOption flags */
 
 	/* These fields are set by ExecutorStart */
 	TupleDesc	tupDesc;		/* descriptor for result tuples */
@@ -60,7 +60,7 @@ extern QueryDesc *CreateQueryDesc(PlannedStmt *plannedstmt,
 				Snapshot crosscheck_snapshot,
 				DestReceiver *dest,
 				ParamListInfo params,
-				bool doInstrument);
+				int instrument_options);
 
 extern QueryDesc *CreateUtilityQueryDesc(Node *utilitystmt,
 					   const char *sourceText,

src/include/executor/executor.h

@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/executor/executor.h,v 1.164 2009/12/07 05:22:23 tgl Exp $
+ * $PostgreSQL: pgsql/src/include/executor/executor.h,v 1.165 2009/12/15 04:57:48 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -161,7 +161,7 @@ extern void InitResultRelInfo(ResultRelInfo *resultRelInfo,
 				  Relation resultRelationDesc,
 				  Index resultRelationIndex,
 				  CmdType operation,
-				  bool doInstrument);
+				  int instrument_options);
 extern ResultRelInfo *ExecGetTriggerResultRel(EState *estate, Oid relid);
 extern bool ExecContextForcesOids(PlanState *planstate, bool *hasoids);
 extern void ExecConstraints(ResultRelInfo *resultRelInfo,

src/include/executor/instrument.h

@@ -6,7 +6,7 @@
  *
  * Copyright (c) 2001-2009, PostgreSQL Global Development Group
  *
- * $PostgreSQL: pgsql/src/include/executor/instrument.h,v 1.20 2009/01/01 17:23:59 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/executor/instrument.h,v 1.21 2009/12/15 04:57:48 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -16,22 +16,46 @@
 #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 Instrumentation *InstrAlloc(int n);
+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);

src/include/nodes/execnodes.h

@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/nodes/execnodes.h,v 1.213 2009/12/07 05:22:23 tgl Exp $
+ * $PostgreSQL: pgsql/src/include/nodes/execnodes.h,v 1.214 2009/12/15 04:57:48 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -370,7 +370,7 @@ typedef struct EState
 	uint32		es_processed;	/* # of tuples processed */
 	Oid			es_lastoid;		/* last oid processed (by INSERT) */
 
-	bool		es_instrument;	/* true requests runtime instrumentation */
+	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 */
 

src/include/storage/buf_internals.h

@@ -8,7 +8,7 @@
  * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/storage/buf_internals.h,v 1.102 2009/06/11 14:49:12 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/storage/buf_internals.h,v 1.103 2009/12/15 04:57:48 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -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

src/include/storage/bufmgr.h

@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/storage/bufmgr.h,v 1.121 2009/06/11 14:49:12 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/storage/bufmgr.h,v 1.122 2009/12/15 04:57:48 rhaas Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -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);