Buffer usage in EXPLAIN and pg_stat_statements

diff -cpr head/contrib/auto_explain/auto_explain.c buffer_usage/contrib/auto_explain/auto_explain.c
*** head/contrib/auto_explain/auto_explain.c	2009-08-10 14:46:49.000000000 +0900
--- buffer_usage/contrib/auto_explain/auto_explain.c	2009-08-17 15:46:39.936395391 +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_buffer = 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_buffer",
+ 							 "EXPLAIN buffer usage for plan logging.",
+ 							 NULL,
+ 							 &auto_explain_log_buffer,
+ 							 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.buffer = auto_explain_log_buffer;
  			es.format = auto_explain_log_format;
  
  			ExplainPrintPlan(&es, queryDesc);
diff -cpr head/contrib/pg_stat_statements/pg_stat_statements.c buffer_usage/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
--- buffer_usage/contrib/pg_stat_statements/pg_stat_statements.c	2009-08-17 15:28:33.614089715 +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 = 0x20090817;
  
  /* 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		gets;			/* total # of buffer pool access */
+ 	int64		reads;			/* total # of data file access */
+ 	int64		temp;			/* total # of temp file access (sort) */
  	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.gets += instr->buffer_gets;
+ 		e->counters.reads += instr->buffer_reads;
+ 		e->counters.temp += instr->buffer_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.gets);
+ 		values[i++] = Int64GetDatumFast(tmp.reads);
+ 		values[i++] = Int64GetDatumFast(tmp.temp);
  
  		Assert(i == PG_STAT_STATEMENTS_COLS);
  
diff -cpr head/contrib/pg_stat_statements/pg_stat_statements.sql.in buffer_usage/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
--- buffer_usage/contrib/pg_stat_statements/pg_stat_statements.sql.in	2009-08-17 13:30:04.064102927 +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 gets int8,
!     OUT reads int8,
!     OUT temp int8
  )
  RETURNS SETOF record
  AS 'MODULE_PATHNAME'
diff -cpr head/src/backend/commands/explain.c buffer_usage/src/backend/commands/explain.c
*** head/src/backend/commands/explain.c	2009-08-10 14:46:50.000000000 +0900
--- buffer_usage/src/backend/commands/explain.c	2009-08-17 15:28:24.841134191 +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, "buffer") == 0)
+ 			es.buffer = 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.buffer && !es.analyze)
+ 		ereport(ERROR,
+ 			(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+ 			 errmsg("EXPLAIN option BUFFER requires ANALYZE")));
+ 
  	/* Convert parameter type data to the form parser wants */
  	getParamListTypes(params, &param_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->buffer)
+ 		{
+ 			long	num_gets = planstate->instrument->buffer_gets;
+ 			long	num_reads = planstate->instrument->buffer_reads;
+ 			long	num_temp = planstate->instrument->buffer_temp;
+ 
+ 			if (es->format == EXPLAIN_FORMAT_TEXT)
+ 			{
+ 				appendStringInfo(es->str, " (gets=%ld reads=%ld temp=%ld)",
+ 					num_gets, num_reads, num_temp);
+ 			}
+ 			else
+ 			{
+ 				ExplainPropertyLong("Buffer Gets", num_gets, es);
+ 				ExplainPropertyLong("Buffer Reads", num_reads, es);
+ 				ExplainPropertyLong("Buffer Temp", num_temp, es);
+ 			}
+ 		}
  	}
  	else if (es->analyze)
  	{
diff -cpr head/src/backend/executor/execMain.c buffer_usage/src/backend/executor/execMain.c
*** head/src/backend/executor/execMain.c	2009-07-30 05:56:18.000000000 +0900
--- buffer_usage/src/backend/executor/execMain.c	2009-08-17 15:33:00.323123722 +0900
***************
*** 50,55 ****
--- 50,56 ----
  #include "optimizer/clauses.h"
  #include "parser/parse_clause.h"
  #include "parser/parsetree.h"
+ #include "storage/buf_internals.h"
  #include "storage/bufmgr.h"
  #include "storage/lmgr.h"
  #include "storage/smgr.h"
*************** standard_ExecutorRun(QueryDesc *queryDes
*** 267,272 ****
--- 268,274 ----
  	DestReceiver *dest;
  	bool		sendTuples;
  	MemoryContext oldcontext;
+ 	Instrumentation *save_TopInstrument = NULL;
  
  	/* sanity checks */
  	Assert(queryDesc != NULL);
*************** standard_ExecutorRun(QueryDesc *queryDes
*** 282,288 ****
--- 284,294 ----
  
  	/* 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 ****
--- 326,341 ----
  		(*dest->rShutdown) (dest);
  
  	if (queryDesc->totaltime)
+ 	{
  		InstrStopNode(queryDesc->totaltime, estate->es_processed);
+ 		if (save_TopInstrument)
+ 		{
+ 			save_TopInstrument->buffer_gets += queryDesc->totaltime->buffer_gets;
+ 			save_TopInstrument->buffer_reads += queryDesc->totaltime->buffer_reads;
+ 			save_TopInstrument->buffer_temp += queryDesc->totaltime->buffer_temp;
+ 		}
+ 		TopInstrument = save_TopInstrument;
+ 	}
  
  	MemoryContextSwitchTo(oldcontext);
  }
diff -cpr head/src/backend/executor/instrument.c buffer_usage/src/backend/executor/instrument.c
*** head/src/backend/executor/instrument.c	2009-01-02 02:23:41.000000000 +0900
--- buffer_usage/src/backend/executor/instrument.c	2009-08-17 15:36:17.857108838 +0900
***************
*** 16,22 ****
--- 16,26 ----
  #include <unistd.h>
  
  #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,84 ----
  {
  	instr_time	endtime;
  
+ 	if (instr == CurrentInstrument)
+ 	{
+ 		long	num_gets = ReadBufferCount + ReadLocalBufferCount;
+ 		long	num_reads = num_gets - BufferHitCount - LocalBufferHitCount;
+ 		long	num_temp = BufFileReadCount;
+ 
+ 		/* add to current instrucments */
+ 		instr->buffer_gets += num_gets;
+ 		instr->buffer_reads += num_reads;
+ 		instr->buffer_temp += num_temp;
+ 
+ 		/* add to top instrucments, too */
+ 		if (TopInstrument && TopInstrument != CurrentInstrument)
+ 		{
+ 			TopInstrument->buffer_gets += num_gets;
+ 			TopInstrument->buffer_reads += num_reads;
+ 			TopInstrument->buffer_temp += num_temp;
+ 		}
+ 
+ 		/* reset buffer usage and pop stack */
+ 		ResetLocalBufferUsage();
+ 		CurrentInstrument = instr->prev;
+ 	}
+ 	else
+ 		elog(WARNING, "Instrumentation stack is broken");
+ 
  	/* count the returned tuples */
  	instr->tuplecount += nTuples;
  
diff -cpr head/src/backend/storage/buffer/bufmgr.c buffer_usage/src/backend/storage/buffer/bufmgr.c
*** head/src/backend/storage/buffer/bufmgr.c	2009-06-11 23:49:01.000000000 +0900
--- buffer_usage/src/backend/storage/buffer/bufmgr.c	2009-08-17 15:14:10.747096730 +0900
*************** static bool IsForInput;
*** 79,84 ****
--- 79,94 ----
  /* local state for LockBufferForCleanup */
  static volatile BufferDesc *PinCountWaitBuf = NULL;
  
+ /* 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)
+ {
+ 	GlobalReadBufferCount += ReadBufferCount;
+ 	GlobalReadLocalBufferCount += ReadLocalBufferCount;
+ 	GlobalBufferHitCount += BufferHitCount;
+ 	GlobalLocalBufferHitCount += LocalBufferHitCount;
+ 	GlobalBufferFlushCount += BufferFlushCount;
+ 	GlobalLocalBufferFlushCount += LocalBufferFlushCount;
+ 	GlobalBufFileReadCount += BufFileReadCount;
+ 	GlobalBufFileWriteCount += BufFileWriteCount;
+ 
+ 	BufferHitCount = 0;
+ 	ReadBufferCount = 0;
+ 	BufferFlushCount = 0;
+ 	LocalBufferHitCount = 0;
+ 	ReadLocalBufferCount = 0;
+ 	LocalBufferFlushCount = 0;
+ 	BufFileReadCount = 0;
+ 	BufFileWriteCount = 0;
  }
  
  /*
diff -cpr head/src/backend/tcop/postgres.c buffer_usage/src/backend/tcop/postgres.c
*** head/src/backend/tcop/postgres.c	2009-08-01 05:26:23.000000000 +0900
--- buffer_usage/src/backend/tcop/postgres.c	2009-08-17 15:32:25.347164961 +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
*** 3524,3529 ****
--- 3525,3534 ----
  		 */
  		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 -cpr head/src/include/commands/explain.h buffer_usage/src/include/commands/explain.h
*** head/src/include/commands/explain.h	2009-08-10 14:46:50.000000000 +0900
--- buffer_usage/src/include/commands/explain.h	2009-08-17 12:05:08.156395775 +0900
*************** typedef struct ExplainState
*** 29,34 ****
--- 29,35 ----
  	bool		verbose;		/* be verbose */
  	bool		analyze;		/* print actual times */
  	bool		costs;			/* print costs */
+ 	bool		buffer;			/* print buffer stats */
  	ExplainFormat format;		/* output format */
  	/* other states */
  	PlannedStmt *pstmt;			/* top of plan */
diff -cpr head/src/include/executor/instrument.h buffer_usage/src/include/executor/instrument.h
*** head/src/include/executor/instrument.h	2009-01-02 02:23:59.000000000 +0900
--- buffer_usage/src/include/executor/instrument.h	2009-08-17 15:44:54.821438586 +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		buffer_gets;	/* # of buffer reads */
+ 	long		buffer_reads;	/* # of disk reads */
+ 	long		buffer_temp;	/* # of temp file reads */
+ 	/* 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 -cpr head/src/include/storage/bufmgr.h buffer_usage/src/include/storage/bufmgr.h
*** head/src/include/storage/bufmgr.h	2009-06-11 23:49:12.000000000 +0900
--- buffer_usage/src/include/storage/bufmgr.h	2009-08-17 15:28:59.853135890 +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);