EXPLAIN ANALYZE feature to measure and show actual runtimes and tuple

counts alongside the planner's estimates.  By Martijn van Oosterhout,
with some further work by Tom Lane.

16 files changed, 313 insertions, 68 deletions

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 672ec54cb02..91282ffc3f6 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -5,18 +5,20 @@
  * Portions Copyright (c) 1996-2001, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994-5, Regents of the University of California
  *
- * $Header: /cvsroot/pgsql/src/backend/commands/explain.c,v 1.65 2001/03/22 03:59:22 momjian Exp $
+ * $Header: /cvsroot/pgsql/src/backend/commands/explain.c,v 1.66 2001/09/18 01:59:06 tgl Exp $
  *
  */
 
 #include "postgres.h"
 
 #include "commands/explain.h"
+#include "executor/instrument.h"
 #include "lib/stringinfo.h"
 #include "nodes/print.h"
 #include "optimizer/planner.h"
 #include "parser/parsetree.h"
 #include "rewrite/rewriteHandler.h"
+#include "tcop/pquery.h"
 #include "utils/relcache.h"
 
 typedef struct ExplainState
@@ -28,8 +30,8 @@ typedef struct ExplainState
 	List	   *rtable;			/* range table */
 } ExplainState;
 
-static char *Explain_PlanToString(Plan *plan, ExplainState *es);
-static void ExplainOneQuery(Query *query, bool verbose, CommandDest dest);
+static StringInfo Explain_PlanToString(Plan *plan, ExplainState *es);
+static void ExplainOneQuery(Query *query, bool verbose, bool analyze, CommandDest dest);
 
 /* Convert a null string pointer into "<>" */
 #define stringStringInfo(s) (((s) == NULL) ? "<>" : (s))
@@ -41,7 +43,7 @@ static void ExplainOneQuery(Query *query, bool verbose, CommandDest dest);
  *
  */
 void
-ExplainQuery(Query *query, bool verbose, CommandDest dest)
+ExplainQuery(Query *query, bool verbose, bool analyze, CommandDest dest)
 {
 	List	   *rewritten;
 	List	   *l;
@@ -73,7 +75,7 @@ ExplainQuery(Query *query, bool verbose, CommandDest dest)
 
 	/* Explain every plan */
 	foreach(l, rewritten)
-		ExplainOneQuery(lfirst(l), verbose, dest);
+		ExplainOneQuery(lfirst(l), verbose, analyze, dest);
 }
 
 /*
@@ -82,11 +84,11 @@ ExplainQuery(Query *query, bool verbose, CommandDest dest)
  *
  */
 static void
-ExplainOneQuery(Query *query, bool verbose, CommandDest dest)
+ExplainOneQuery(Query *query, bool verbose, bool analyze, CommandDest dest)
 {
-	char	   *s;
 	Plan	   *plan;
 	ExplainState *es;
+	double		totaltime = 0;
 
 	/* planner will not cope with utility statements */
 	if (query->commandType == CMD_UTILITY)
@@ -105,6 +107,34 @@ ExplainOneQuery(Query *query, bool verbose, CommandDest dest)
 	if (plan == NULL)
 		return;
 
+	/* Execute the plan for statistics if asked for */
+	if (analyze)
+	{
+		struct timeval starttime;
+		struct timeval endtime;
+
+		/*
+		 * Set up the instrumentation for the top node.
+		 * This will cascade during plan initialisation
+		 */
+		plan->instrument = InstrAlloc();
+
+		gettimeofday(&starttime, NULL);
+		ProcessQuery(query, plan, None);
+		CommandCounterIncrement();
+		gettimeofday(&endtime, NULL);
+
+		endtime.tv_sec  -= starttime.tv_sec;
+		endtime.tv_usec -= starttime.tv_usec;
+		while (endtime.tv_usec < 0)
+		{
+			endtime.tv_usec += 1000000;
+			endtime.tv_sec--;
+		}
+		totaltime = (double) endtime.tv_sec +
+			(double) endtime.tv_usec / 1000000.0;
+	}
+
 	es = (ExplainState *) palloc(sizeof(ExplainState));
 	MemSet(es, 0, sizeof(ExplainState));
 
@@ -117,6 +147,8 @@ ExplainOneQuery(Query *query, bool verbose, CommandDest dest)
 
 	if (es->printNodes)
 	{
+		char	   *s;
+
 		s = nodeToString(plan);
 		if (s)
 		{
@@ -127,12 +159,15 @@ ExplainOneQuery(Query *query, bool verbose, CommandDest dest)
 
 	if (es->printCost)
 	{
-		s = Explain_PlanToString(plan, es);
-		if (s)
-		{
-			elog(NOTICE, "QUERY PLAN:\n\n%s", s);
-			pfree(s);
-		}
+		StringInfo	str;
+
+		str = Explain_PlanToString(plan, es);
+		if (analyze)
+			appendStringInfo(str, "Total runtime: %.2f msec\n",
+							 1000.0 * totaltime);
+		elog(NOTICE, "QUERY PLAN:\n\n%s", str->data);
+		pfree(str->data);
+		pfree(str);
 	}
 
 	if (es->printNodes)
@@ -292,6 +327,17 @@ explain_outNode(StringInfo str, Plan *plan, int indent, ExplainState *es)
 		appendStringInfo(str, "  (cost=%.2f..%.2f rows=%.0f width=%d)",
 						 plan->startup_cost, plan->total_cost,
 						 plan->plan_rows, plan->plan_width);
+
+		if ( plan->instrument && plan->instrument->nloops > 0 )
+		{
+			double nloops = plan->instrument->nloops;
+
+			appendStringInfo(str, " (actual time=%.2f..%.2f rows=%.0f loops=%.0f)",
+							 1000.0 * plan->instrument->startup / nloops,
+							 1000.0 * plan->instrument->total / nloops,
+							 plan->instrument->ntuples / nloops,
+							 plan->instrument->nloops);
+		}
 	}
 	appendStringInfo(str, "\n");
 
@@ -393,14 +439,12 @@ explain_outNode(StringInfo str, Plan *plan, int indent, ExplainState *es)
 	}
 }
 
-static char *
+static StringInfo
 Explain_PlanToString(Plan *plan, ExplainState *es)
 {
-	StringInfoData str;
+	StringInfo str = makeStringInfo();
 
-	/* see stringinfo.h for an explanation of this maneuver */
-	initStringInfo(&str);
 	if (plan != NULL)
-		explain_outNode(&str, plan, 0, es);
-	return str.data;
+		explain_outNode(str, plan, 0, es);
+	return str;
 }
diff --git a/src/backend/executor/Makefile b/src/backend/executor/Makefile
index 7d57beb59f2..363ea342e9f 100644
--- a/src/backend/executor/Makefile
+++ b/src/backend/executor/Makefile
@@ -4,7 +4,7 @@
 #    Makefile for executor
 #
 # IDENTIFICATION
-#    $Header: /cvsroot/pgsql/src/backend/executor/Makefile,v 1.16 2000/10/26 21:35:15 tgl Exp $
+#    $Header: /cvsroot/pgsql/src/backend/executor/Makefile,v 1.17 2001/09/18 01:59:06 tgl Exp $
 #
 #-------------------------------------------------------------------------
 
@@ -14,7 +14,7 @@ include $(top_builddir)/src/Makefile.global
 
 OBJS = execAmi.o execFlatten.o execJunk.o execMain.o \
        execProcnode.o execQual.o execScan.o execTuples.o \
-       execUtils.o functions.o nodeAppend.o nodeAgg.o nodeHash.o \
+       execUtils.o functions.o instrument.o nodeAppend.o nodeAgg.o nodeHash.o \
        nodeHashjoin.o nodeIndexscan.o nodeMaterial.o nodeMergejoin.o \
        nodeNestloop.o nodeResult.o nodeSeqscan.o nodeSetOp.o nodeSort.o \
        nodeUnique.o nodeLimit.o nodeGroup.o nodeSubplan.o \
diff --git a/src/backend/executor/execAmi.c b/src/backend/executor/execAmi.c
index 3c0e029fd3c..6303613faa9 100644
--- a/src/backend/executor/execAmi.c
+++ b/src/backend/executor/execAmi.c
@@ -6,7 +6,7 @@
  * Portions Copyright (c) 1996-2001, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- *	$Id: execAmi.c,v 1.58 2001/03/22 06:16:12 momjian Exp $
+ *	$Id: execAmi.c,v 1.59 2001/09/18 01:59:06 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -29,6 +29,7 @@
 #include "access/heapam.h"
 #include "catalog/heap.h"
 #include "executor/execdebug.h"
+#include "executor/instrument.h"
 #include "executor/nodeAgg.h"
 #include "executor/nodeAppend.h"
 #include "executor/nodeGroup.h"
@@ -260,6 +261,8 @@ ExecCloseR(Plan *node)
 void
 ExecReScan(Plan *node, ExprContext *exprCtxt, Plan *parent)
 {
+	if (node->instrument)
+		InstrEndLoop(node->instrument);
 
 	if (node->chgParam != NULL) /* Wow! */
 	{
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 4061478427d..6b1db391eeb 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -27,7 +27,7 @@
  *
  *
  * IDENTIFICATION
- *	  $Header: /cvsroot/pgsql/src/backend/executor/execMain.c,v 1.147 2001/09/17 00:29:10 tgl Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/executor/execMain.c,v 1.148 2001/09/18 01:59:06 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -868,7 +868,7 @@ EndPlan(Plan *plan, EState *estate)
 	/*
 	 * shut down the node-type-specific query processing
 	 */
-	ExecEndNode(plan, plan);
+	ExecEndNode(plan, NULL);
 
 	/*
 	 * destroy the executor "tuple" table.
@@ -973,16 +973,15 @@ ExecutePlan(EState *estate,
 		/*
 		 * Execute the plan and obtain a tuple
 		 */
-		/* at the top level, the parent of a plan (2nd arg) is itself */
 lnext:	;
 		if (estate->es_useEvalPlan)
 		{
 			slot = EvalPlanQualNext(estate);
 			if (TupIsNull(slot))
-				slot = ExecProcNode(plan, plan);
+				slot = ExecProcNode(plan, NULL);
 		}
 		else
-			slot = ExecProcNode(plan, plan);
+			slot = ExecProcNode(plan, NULL);
 
 		/*
 		 * if the tuple is null, then we assume there is nothing more to
@@ -1758,7 +1757,7 @@ EvalPlanQual(EState *estate, Index rti, ItemPointer tid)
 			oldepq = (evalPlanQual *) epqstate->es_evalPlanQual;
 			Assert(oldepq->rti != 0);
 			/* stop execution */
-			ExecEndNode(epq->plan, epq->plan);
+			ExecEndNode(epq->plan, NULL);
 			ExecDropTupleTable(epqstate->es_tupleTable, true);
 			epqstate->es_tupleTable = NULL;
 			heap_freetuple(epqstate->es_evTuple[epq->rti - 1]);
@@ -1853,7 +1852,7 @@ EvalPlanQual(EState *estate, Index rti, ItemPointer tid)
 	if (endNode)
 	{
 		/* stop execution */
-		ExecEndNode(epq->plan, epq->plan);
+		ExecEndNode(epq->plan, NULL);
 		ExecDropTupleTable(epqstate->es_tupleTable, true);
 		epqstate->es_tupleTable = NULL;
 	}
@@ -1897,7 +1896,7 @@ EvalPlanQualNext(EState *estate)
 	Assert(epq->rti != 0);
 
 lpqnext:;
-	slot = ExecProcNode(epq->plan, epq->plan);
+	slot = ExecProcNode(epq->plan, NULL);
 
 	/*
 	 * No more tuples for this PQ. Continue previous one.
@@ -1905,7 +1904,7 @@ lpqnext:;
 	if (TupIsNull(slot))
 	{
 		/* stop execution */
-		ExecEndNode(epq->plan, epq->plan);
+		ExecEndNode(epq->plan, NULL);
 		ExecDropTupleTable(epqstate->es_tupleTable, true);
 		epqstate->es_tupleTable = NULL;
 		heap_freetuple(epqstate->es_evTuple[epq->rti - 1]);
@@ -1946,7 +1945,7 @@ EndEvalPlanQual(EState *estate)
 	for (;;)
 	{
 		/* stop execution */
-		ExecEndNode(epq->plan, epq->plan);
+		ExecEndNode(epq->plan, NULL);
 		ExecDropTupleTable(epqstate->es_tupleTable, true);
 		epqstate->es_tupleTable = NULL;
 		if (epqstate->es_evTuple[epq->rti - 1] != NULL)
diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c
index 79308ba4efb..0d66cd76c19 100644
--- a/src/backend/executor/execProcnode.c
+++ b/src/backend/executor/execProcnode.c
@@ -12,7 +12,7 @@
  *
  *
  * IDENTIFICATION
- *	  $Header: /cvsroot/pgsql/src/backend/executor/execProcnode.c,v 1.26 2001/03/22 06:16:12 momjian Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/executor/execProcnode.c,v 1.27 2001/09/18 01:59:06 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -78,6 +78,7 @@
 #include "postgres.h"
 
 #include "executor/executor.h"
+#include "executor/instrument.h"
 #include "executor/nodeAgg.h"
 #include "executor/nodeAppend.h"
 #include "executor/nodeGroup.h"
@@ -123,6 +124,10 @@ ExecInitNode(Plan *node, EState *estate, Plan *parent)
 	if (node == NULL)
 		return FALSE;
 
+	/* Set up instrumentation for this node if the parent has it */
+	if (!node->instrument && parent && parent->instrument)
+		node->instrument = InstrAlloc();
+
 	foreach(subp, node->initPlan)
 	{
 		result = ExecInitSubPlan((SubPlan *) lfirst(subp), estate, node);
@@ -132,7 +137,6 @@ ExecInitNode(Plan *node, EState *estate, Plan *parent)
 
 	switch (nodeTag(node))
 	{
-
 			/*
 			 * control nodes
 			 */
@@ -218,6 +222,7 @@ ExecInitNode(Plan *node, EState *estate, Plan *parent)
 			elog(ERROR, "ExecInitNode: node type %d unsupported",
 				 (int) nodeTag(node));
 			result = FALSE;
+			break;
 	}
 
 	if (result != FALSE)
@@ -257,12 +262,14 @@ ExecProcNode(Plan *node, Plan *parent)
 	if (node->chgParam != NULL) /* something changed */
 		ExecReScan(node, NULL, parent); /* let ReScan handle this */
 
+	if (node->instrument)
+		InstrStartNode(node->instrument);
+
 	switch (nodeTag(node))
 	{
-
-			/*
-			 * control nodes
-			 */
+		/*
+		 * control nodes
+		 */
 		case T_Result:
 			result = ExecResult((Result *) node);
 			break;
@@ -344,8 +351,12 @@ ExecProcNode(Plan *node, Plan *parent)
 			elog(ERROR, "ExecProcNode: node type %d unsupported",
 				 (int) nodeTag(node));
 			result = NULL;
+			break;
 	}
 
+	if (node->instrument)
+		InstrStopNode(node->instrument, !TupIsNull(result));
+
 	return result;
 }
 
@@ -357,7 +368,6 @@ ExecCountSlotsNode(Plan *node)
 
 	switch (nodeTag(node))
 	{
-
 			/*
 			 * control nodes
 			 */
@@ -463,10 +473,9 @@ ExecEndNode(Plan *node, Plan *parent)
 
 	switch (nodeTag(node))
 	{
-
-			/*
-			 * control nodes
-			 */
+		/*
+		 * control nodes
+		 */
 		case T_Result:
 			ExecEndResult((Result *) node);
 			break;
@@ -549,6 +558,9 @@ ExecEndNode(Plan *node, Plan *parent)
 				 (int) nodeTag(node));
 			break;
 	}
+
+	if (node->instrument)
+		InstrEndLoop(node->instrument);
 }
 
 
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
new file mode 100644
index 00000000000..753efbcee9a
--- /dev/null
+++ b/src/backend/executor/instrument.c
@@ -0,0 +1,122 @@
+/*-------------------------------------------------------------------------
+ *
+ * instrument.c
+ *	 functions for instrumentation of plan execution 
+ *
+ *
+ * Copyright (c) 2001, PostgreSQL Global Development Group
+ *
+ * IDENTIFICATION
+ *	  $Header: /cvsroot/pgsql/src/backend/executor/instrument.c,v 1.1 2001/09/18 01:59:06 tgl Exp $
+ *
+ *-------------------------------------------------------------------------
+ */
+#include "postgres.h"
+
+#include <unistd.h>
+
+#include "executor/instrument.h"
+
+
+/* Allocate new instrumentation structure */
+Instrumentation *
+InstrAlloc(void)
+{
+	Instrumentation *instr = palloc( sizeof(Instrumentation) );
+
+	memset( instr, 0, sizeof(Instrumentation) );
+
+	return instr;
+}
+
+/* Entry to a plan node */
+void
+InstrStartNode(Instrumentation *instr)
+{
+	if (!instr)
+		return;
+
+	if (instr->starttime.tv_sec != 0 || instr->starttime.tv_usec != 0)
+		elog(DEBUG, "InstrStartTimer called twice in a row");
+	else
+		gettimeofday(&instr->starttime, NULL);
+}
+
+/* Exit from a plan node */
+void
+InstrStopNode(Instrumentation *instr, bool returnedTuple)
+{
+	struct timeval endtime;
+  
+	if (!instr)
+		return;
+
+	if (instr->starttime.tv_sec == 0 && instr->starttime.tv_usec == 0)
+	{
+		elog(DEBUG, "InstrStopNode without start");
+		return;
+	}
+  
+	gettimeofday(&endtime, NULL);
+  
+	instr->counter.tv_sec  += endtime.tv_sec  - instr->starttime.tv_sec;
+	instr->counter.tv_usec += endtime.tv_usec - instr->starttime.tv_usec;
+
+	/* Normalize after each add to avoid overflow/underflow of tv_usec */
+	while (instr->counter.tv_usec < 0)
+	{
+		instr->counter.tv_usec += 1000000;
+		instr->counter.tv_sec--;
+	}
+	while (instr->counter.tv_usec >= 1000000)
+	{
+		instr->counter.tv_usec -= 1000000;
+		instr->counter.tv_sec++;
+	}
+
+	instr->starttime.tv_sec = 0;
+	instr->starttime.tv_usec = 0;
+
+	/* Is this the first tuple of this cycle? */
+	if (!instr->running)
+	{
+		instr->running = true;
+		instr->firsttuple = (double) instr->counter.tv_sec +
+			(double) instr->counter.tv_usec / 1000000.0;
+	}
+
+	if (returnedTuple)
+		instr->tuplecount += 1;
+}
+
+/* Finish a run cycle for a plan node */
+void 
+InstrEndLoop(Instrumentation *instr)
+{
+	double totaltime;
+
+	if (!instr)
+		return;
+
+	/* Skip if nothing has happened, or already shut down */
+	if (!instr->running)
+		return;
+
+	/* Accumulate statistics */
+	totaltime = (double) instr->counter.tv_sec +
+		(double) instr->counter.tv_usec / 1000000.0; 
+
+	instr->startup += instr->firsttuple;
+	instr->total   += totaltime;
+	instr->ntuples += instr->tuplecount;
+	instr->nloops += 1;
+
+	/* Reset for next cycle (if any) */
+	instr->running = false;
+	instr->starttime.tv_sec = 0;
+	instr->starttime.tv_usec = 0;
+	instr->counter.tv_sec = 0;
+	instr->counter.tv_usec = 0;
+	instr->firsttuple = 0;
+	instr->tuplecount = 0;
+}
diff --git a/src/backend/executor/nodeSubplan.c b/src/backend/executor/nodeSubplan.c
index a8df4940ae4..6719df94e7a 100644
--- a/src/backend/executor/nodeSubplan.c
+++ b/src/backend/executor/nodeSubplan.c
@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1994, Regents of the University of California
  *
  * IDENTIFICATION
- *	  $Header: /cvsroot/pgsql/src/backend/executor/nodeSubplan.c,v 1.30 2001/03/22 03:59:29 momjian Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/executor/nodeSubplan.c,v 1.31 2001/09/18 01:59:06 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -73,7 +73,7 @@ ExecSubPlan(SubPlan *node, List *pvar, ExprContext *econtext, bool *isNull)
 	}
 	Assert(pvar == NIL);
 
-	ExecReScan(plan, (ExprContext *) NULL, plan);
+	ExecReScan(plan, NULL, NULL);
 
 	/*
 	 * For all sublink types except EXPR_SUBLINK, the result is boolean as
@@ -96,9 +96,9 @@ ExecSubPlan(SubPlan *node, List *pvar, ExprContext *econtext, bool *isNull)
 	result = BoolGetDatum(subLinkType == ALL_SUBLINK);
 	*isNull = false;
 
-	for (slot = ExecProcNode(plan, plan);
+	for (slot = ExecProcNode(plan, NULL);
 		 !TupIsNull(slot);
-		 slot = ExecProcNode(plan, plan))
+		 slot = ExecProcNode(plan, NULL))
 	{
 		HeapTuple	tup = slot->val;
 		TupleDesc	tdesc = slot->ttc_tupleDescriptor;
@@ -295,7 +295,7 @@ ExecInitSubPlan(SubPlan *node, EState *estate, Plan *parent)
 	node->needShutdown = false;
 	node->curTuple = NULL;
 
-	if (!ExecInitNode(node->plan, sp_estate, NULL))
+	if (!ExecInitNode(node->plan, sp_estate, parent))
 		return false;
 
 	node->needShutdown = true;	/* now we need to shutdown the subplan */
@@ -359,11 +359,11 @@ ExecSetParamPlan(SubPlan *node, ExprContext *econtext)
 		elog(ERROR, "ExecSetParamPlan: ANY/ALL subselect unsupported");
 
 	if (plan->chgParam != NULL)
-		ExecReScan(plan, (ExprContext *) NULL, plan);
+		ExecReScan(plan, NULL, NULL);
 
-	for (slot = ExecProcNode(plan, plan);
+	for (slot = ExecProcNode(plan, NULL);
 		 !TupIsNull(slot);
-		 slot = ExecProcNode(plan, plan))
+		 slot = ExecProcNode(plan, NULL))
 	{
 		HeapTuple	tup = slot->val;
 		TupleDesc	tdesc = slot->ttc_tupleDescriptor;
@@ -433,7 +433,7 @@ ExecSetParamPlan(SubPlan *node, ExprContext *econtext)
 
 	if (plan->extParam == NULL) /* un-correlated ... */
 	{
-		ExecEndNode(plan, plan);
+		ExecEndNode(plan, NULL);
 		node->needShutdown = false;
 	}
 
@@ -449,7 +449,7 @@ ExecEndSubPlan(SubPlan *node)
 {
 	if (node->needShutdown)
 	{
-		ExecEndNode(node->plan, node->plan);
+		ExecEndNode(node->plan, NULL);
 		node->needShutdown = false;
 	}
 	if (node->curTuple)
@@ -474,7 +474,7 @@ ExecReScanSetParamPlan(SubPlan *node, Plan *parent)
 
 	/*
 	 * Don't actual re-scan: ExecSetParamPlan does re-scan if
-	 * node->plan->chgParam is not NULL... ExecReScan (plan, NULL, plan);
+	 * node->plan->chgParam is not NULL... ExecReScan (plan, NULL, NULL);
 	 */
 
 	/*
diff --git a/src/backend/executor/nodeSubqueryscan.c b/src/backend/executor/nodeSubqueryscan.c
index af2b878165b..8c178ad0aa4 100644
--- a/src/backend/executor/nodeSubqueryscan.c
+++ b/src/backend/executor/nodeSubqueryscan.c
@@ -12,7 +12,7 @@
  *
  *
  * IDENTIFICATION
- *	  $Header: /cvsroot/pgsql/src/backend/executor/nodeSubqueryscan.c,v 1.9 2001/05/27 20:42:20 tgl Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/executor/nodeSubqueryscan.c,v 1.10 2001/09/18 01:59:06 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -72,7 +72,7 @@ SubqueryNext(SubqueryScan *node)
 	 */
 	subquerystate->sss_SubEState->es_direction = direction;
 
-	slot = ExecProcNode(node->subplan, node->subplan);
+	slot = ExecProcNode(node->subplan, (Plan *) node);
 
 	subquerystate->csstate.css_ScanTupleSlot = slot;
 
@@ -159,7 +159,7 @@ ExecInitSubqueryScan(SubqueryScan *node, EState *estate, Plan *parent)
 		ExecCreateTupleTable(ExecCountSlotsNode(node->subplan) + 10);
 	sp_estate->es_snapshot = estate->es_snapshot;
 
-	if (!ExecInitNode(node->subplan, sp_estate, NULL))
+	if (!ExecInitNode(node->subplan, sp_estate, (Plan *) node))
 		return false;
 
 	subquerystate->csstate.css_ScanTupleSlot = NULL;
@@ -214,7 +214,7 @@ ExecEndSubqueryScan(SubqueryScan *node)
 	/*
 	 * close down subquery
 	 */
-	ExecEndNode(node->subplan, node->subplan);
+	ExecEndNode(node->subplan, (Plan *) node);
 
 	/*
 	 * clean up subquery's tuple table
@@ -256,7 +256,7 @@ ExecSubqueryReScan(SubqueryScan *node, ExprContext *exprCtxt, Plan *parent)
 	 * first ExecProcNode.
 	 */
 	if (node->subplan->chgParam == NULL)
-		ExecReScan(node->subplan, NULL, node->subplan);
+		ExecReScan(node->subplan, NULL, (Plan *) node);
 
 	subquerystate->csstate.css_ScanTupleSlot = NULL;
 }
diff --git a/src/backend/nodes/copyfuncs.c b/src/backend/nodes/copyfuncs.c
index cf9ad2e983c..1003bcf35d5 100644
--- a/src/backend/nodes/copyfuncs.c
+++ b/src/backend/nodes/copyfuncs.c
@@ -15,7 +15,7 @@
  * Portions Copyright (c) 1994, Regents of the University of California
  *
  * IDENTIFICATION
- *	  $Header: /cvsroot/pgsql/src/backend/nodes/copyfuncs.c,v 1.155 2001/08/26 16:55:59 tgl Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/nodes/copyfuncs.c,v 1.156 2001/09/18 01:59:06 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -2262,6 +2262,7 @@ _copyExplainStmt(ExplainStmt *from)
 
 	Node_Copy(from, newnode, query);
 	newnode->verbose = from->verbose;
+	newnode->analyze = from->analyze;
 
 	return newnode;
 }
diff --git a/src/backend/nodes/equalfuncs.c b/src/backend/nodes/equalfuncs.c
index 9dce1f61b46..437cd62ebdf 100644
--- a/src/backend/nodes/equalfuncs.c
+++ b/src/backend/nodes/equalfuncs.c
@@ -20,7 +20,7 @@
  * Portions Copyright (c) 1994, Regents of the University of California
  *
  * IDENTIFICATION
- *	  $Header: /cvsroot/pgsql/src/backend/nodes/equalfuncs.c,v 1.103 2001/08/26 16:55:59 tgl Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/nodes/equalfuncs.c,v 1.104 2001/09/18 01:59:06 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -1135,6 +1135,8 @@ _equalExplainStmt(ExplainStmt *a, ExplainStmt *b)
 		return false;
 	if (a->verbose != b->verbose)
 		return false;
+	if (a->analyze != b->analyze)
+		return false;
 
 	return true;
 }
diff --git a/src/backend/parser/gram.y b/src/backend/parser/gram.y
index f440e239a86..c1e331cf819 100644
--- a/src/backend/parser/gram.y
+++ b/src/backend/parser/gram.y
@@ -11,7 +11,7 @@
  *
  *
  * IDENTIFICATION
- *	  $Header: /cvsroot/pgsql/src/backend/parser/gram.y,v 2.250 2001/09/06 04:57:28 ishii Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/parser/gram.y,v 2.251 2001/09/18 01:59:06 tgl Exp $
  *
  * HISTORY
  *	  AUTHOR			DATE			MAJOR EVENT
@@ -3168,6 +3168,7 @@ opt_name_list:  '(' name_list ')'				{ $$ = $2; }
  *
  *		QUERY:
  *				EXPLAIN query
+ *				EXPLAIN ANALYZE query
  *
  *****************************************************************************/
 
@@ -3175,9 +3176,18 @@ ExplainStmt:  EXPLAIN opt_verbose OptimizableStmt
 				{
 					ExplainStmt *n = makeNode(ExplainStmt);
 					n->verbose = $2;
+					n->analyze = FALSE;
 					n->query = (Query*)$3;
 					$$ = (Node *)n;
 				}
+			| EXPLAIN analyze_keyword opt_verbose OptimizableStmt
+				{
+					ExplainStmt *n = makeNode(ExplainStmt);
+					n->verbose = $3;
+					n->analyze = TRUE;
+					n->query = (Query*)$4;
+					$$ = (Node *)n;
+				}
 		;
 
 
diff --git a/src/backend/tcop/utility.c b/src/backend/tcop/utility.c
index 18cf913470c..957c9199af1 100644
--- a/src/backend/tcop/utility.c
+++ b/src/backend/tcop/utility.c
@@ -10,7 +10,7 @@
  *
  *
  * IDENTIFICATION
- *	  $Header: /cvsroot/pgsql/src/backend/tcop/utility.c,v 1.117 2001/09/08 01:10:20 tgl Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/tcop/utility.c,v 1.118 2001/09/18 01:59:06 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -713,7 +713,7 @@ ProcessUtility(Node *parsetree,
 
 				set_ps_display(commandTag = "EXPLAIN");
 
-				ExplainQuery(stmt->query, stmt->verbose, dest);
+				ExplainQuery(stmt->query, stmt->verbose, stmt->analyze, dest);
 			}
 			break;
 
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 25bb0ecc490..d40bc896ac5 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -6,7 +6,7 @@
  * Portions Copyright (c) 1996-2001, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994-5, Regents of the University of California
  *
- * $Id: explain.h,v 1.11 2001/01/24 19:43:23 momjian Exp $
+ * $Id: explain.h,v 1.12 2001/09/18 01:59:06 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -16,6 +16,6 @@
 #include "nodes/parsenodes.h"
 #include "tcop/dest.h"
 
-extern void ExplainQuery(Query *query, bool verbose, CommandDest dest);
+extern void ExplainQuery(Query *query, bool verbose, bool analyze, CommandDest dest);
 
 #endif	 /* EXPLAIN_H */
diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
new file mode 100644
index 00000000000..ca6aa4208ab
--- /dev/null
+++ b/src/include/executor/instrument.h
@@ -0,0 +1,39 @@
+/*-------------------------------------------------------------------------
+ *
+ * instrument.h
+ *	  definitions for run-time statistics collection
+ *
+ *
+ * Copyright (c) 2001, PostgreSQL Global Development Group
+ *
+ * $Id: instrument.h,v 1.1 2001/09/18 01:59:06 tgl Exp $
+ *
+ *-------------------------------------------------------------------------
+ */
+#ifndef INSTRUMENT_H
+#define INSTRUMENT_H
+
+#include <sys/time.h>
+
+
+typedef struct Instrumentation
+{
+	/* Info about current plan cycle: */
+	bool running;				/* TRUE if we've completed first tuple */
+	struct timeval starttime;	/* Start time of current iteration of node */
+	struct timeval counter;		/* Accumulates runtime for this node */
+	double firsttuple;			/* Time for first tuple of this cycle */
+	double tuplecount;			/* Tuples so far this cycle */
+	/* 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 */
+} Instrumentation;
+
+extern Instrumentation *InstrAlloc(void);
+extern void InstrStartNode(Instrumentation *instr);
+extern void InstrStopNode(Instrumentation *instr, bool returnedTuple);
+extern void InstrEndLoop(Instrumentation *instr);
+
+#endif /* INSTRUMENT_H */
diff --git a/src/include/nodes/parsenodes.h b/src/include/nodes/parsenodes.h
index 315ad113ee7..c5a68ef7c90 100644
--- a/src/include/nodes/parsenodes.h
+++ b/src/include/nodes/parsenodes.h
@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1996-2001, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $Id: parsenodes.h,v 1.143 2001/08/26 16:56:02 tgl Exp $
+ * $Id: parsenodes.h,v 1.144 2001/09/18 01:59:06 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -709,6 +709,7 @@ typedef struct ExplainStmt
 	NodeTag		type;
 	Query	   *query;			/* the query */
 	bool		verbose;		/* print plan info */
+	bool		analyze;		/* get statistics by executing plan */
 } ExplainStmt;
 
 /* ----------------------
diff --git a/src/include/nodes/plannodes.h b/src/include/nodes/plannodes.h
index 1ee5e93cb49..eef16784327 100644
--- a/src/include/nodes/plannodes.h
+++ b/src/include/nodes/plannodes.h
@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1996-2001, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $Id: plannodes.h,v 1.49 2001/03/22 04:00:52 momjian Exp $
+ * $Id: plannodes.h,v 1.50 2001/09/18 01:59:07 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -81,9 +81,21 @@ typedef struct Plan
 	double		plan_rows;		/* number of rows plan is expected to emit */
 	int			plan_width;		/* average row width in bytes */
 
+	/*
+	 * execution state data.  Having Plan point to this, rather than the
+	 * other way round, is 100% bogus.
+	 */
 	EState	   *state;			/* at execution time, state's of
 								 * individual nodes point to one EState
 								 * for the whole top-level plan */
+
+	struct Instrumentation *instrument;  /* Optional runtime stats for this
+										  * plan node */
+
+	/*
+	 * Common structural data for all Plan types.  XXX chgParam is runtime
+	 * data and should be in the EState, not here.
+	 */
 	List	   *targetlist;
 	List	   *qual;			/* implicitly-ANDed qual conditions */
 	struct Plan *lefttree;