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.

7 files changed, 176 insertions, 40 deletions

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;
 }