Index: src/backend/commands/explain.c =================================================================== RCS file: /home/projects/pgsql/cvsroot/pgsql/src/backend/commands/explain.c,v retrieving revision 1.65 diff -u -r1.65 explain.c --- src/backend/commands/explain.c 2001/03/22 03:59:22 1.65 +++ src/backend/commands/explain.c 2001/08/28 10:21:13 @@ -18,6 +18,7 @@ #include "parser/parsetree.h" #include "rewrite/rewriteHandler.h" #include "utils/relcache.h" +#include "executor/instrument.h" typedef struct ExplainState { @@ -29,7 +30,8 @@ } ExplainState; static char *Explain_PlanToString(Plan *plan, ExplainState *es); -static void ExplainOneQuery(Query *query, bool verbose, CommandDest dest); +static void ExplainOneQuery(Query *query, bool verbose, bool analyze, CommandDest dest); +void ProcessQuery(Query *parsetree, Plan *plan, CommandDest dest); /* Convert a null string pointer into "<>" */ #define stringStringInfo(s) (((s) == NULL) ? "<>" : (s)) @@ -41,7 +43,7 @@ * */ 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 @@ /* Explain every plan */ foreach(l, rewritten) - ExplainOneQuery(lfirst(l), verbose, dest); + ExplainOneQuery(lfirst(l), verbose, analyze, dest); } /* @@ -82,7 +84,7 @@ * */ static void -ExplainOneQuery(Query *query, bool verbose, CommandDest dest) +ExplainOneQuery(Query *query, bool verbose, bool analyze, CommandDest dest) { char *s; Plan *plan; @@ -105,6 +107,15 @@ if (plan == NULL) return; + /* Execute the plan for statistics if asked for */ + /* Note that the grammer restricts the queries to select statements, so we should be safe */ + if( analyze ) + { + /* Setup the instrumentation for the top node. This will cascade in plan initialisation */ + plan->instrument = InstrAlloc(); + ProcessQuery( query, plan, None ); + } + es = (ExplainState *) palloc(sizeof(ExplainState)); MemSet(es, 0, sizeof(ExplainState)); @@ -292,6 +303,16 @@ 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 ) + { + appendStringInfo(str, " (actual time=%.2f..%.2f rows=%.0f loops=%d)", + 1000*plan->instrument->startup, + 1000*plan->instrument->total, + (float)plan->instrument->ntuples, + plan->instrument->nloops); + + } } appendStringInfo(str, "\n"); Index: src/backend/executor/Makefile =================================================================== RCS file: /home/projects/pgsql/cvsroot/pgsql/src/backend/executor/Makefile,v retrieving revision 1.16 diff -u -r1.16 Makefile --- src/backend/executor/Makefile 2000/10/26 21:35:15 1.16 +++ src/backend/executor/Makefile 2001/08/28 10:21:13 @@ -14,7 +14,7 @@ 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 \ Index: src/backend/executor/execAmi.c =================================================================== RCS file: /home/projects/pgsql/cvsroot/pgsql/src/backend/executor/execAmi.c,v retrieving revision 1.58 diff -u -r1.58 execAmi.c --- src/backend/executor/execAmi.c 2001/03/22 06:16:12 1.58 +++ src/backend/executor/execAmi.c 2001/08/28 10:21:14 @@ -48,6 +48,7 @@ #include "executor/nodeSubplan.h" #include "executor/nodeSubqueryscan.h" #include "executor/nodeUnique.h" +#include "executor/instrument.h" static Pointer ExecBeginScan(Relation relation, int nkeys, ScanKey skeys, bool isindex, ScanDirection dir, Snapshot snapshot); @@ -260,6 +261,7 @@ void ExecReScan(Plan *node, ExprContext *exprCtxt, Plan *parent) { + InstrEndLoop( node->instrument ); if (node->chgParam != NULL) /* Wow! */ { Index: src/backend/executor/execProcnode.c =================================================================== RCS file: /home/projects/pgsql/cvsroot/pgsql/src/backend/executor/execProcnode.c,v retrieving revision 1.26 diff -u -r1.26 execProcnode.c --- src/backend/executor/execProcnode.c 2001/03/22 06:16:12 1.26 +++ src/backend/executor/execProcnode.c 2001/08/28 10:21:14 @@ -96,6 +96,7 @@ #include "executor/nodeSubplan.h" #include "executor/nodeSubqueryscan.h" #include "executor/nodeUnique.h" +#include "executor/instrument.h" #include "miscadmin.h" #include "tcop/tcopprot.h" @@ -123,6 +124,10 @@ if (node == NULL) return FALSE; + /* Setup 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); @@ -257,6 +262,8 @@ if (node->chgParam != NULL) /* something changed */ ExecReScan(node, NULL, parent); /* let ReScan handle this */ + InstrStartNode( node->instrument ); + switch (nodeTag(node)) { @@ -346,6 +353,11 @@ result = NULL; } + InstrStopNode( node->instrument ); + + if( TupIsNull(result) ) + InstrEndLoop( node->instrument ); + return result; } @@ -450,6 +462,8 @@ */ if (node == NULL) return; + + InstrEndLoop( node->instrument ); foreach(subp, node->initPlan) ExecEndSubPlan((SubPlan *) lfirst(subp)); Index: src/backend/parser/gram.y =================================================================== RCS file: /home/projects/pgsql/cvsroot/pgsql/src/backend/parser/gram.y,v retrieving revision 2.249 diff -u -r2.249 gram.y --- src/backend/parser/gram.y 2001/08/26 16:55:59 2.249 +++ src/backend/parser/gram.y 2001/08/28 10:21:15 @@ -3168,6 +3168,7 @@ * * QUERY: * EXPLAIN query + * EXPLAIN ANALYZE [select statement] * *****************************************************************************/ @@ -3175,7 +3176,16 @@ { ExplainStmt *n = makeNode(ExplainStmt); n->verbose = $2; + n->analyze = FALSE; n->query = (Query*)$3; + $$ = (Node *)n; + } + | EXPLAIN analyze_keyword opt_verbose SelectStmt + { + ExplainStmt *n = makeNode(ExplainStmt); + n->verbose = $3; + n->analyze = TRUE; + n->query = (Query*)$4; $$ = (Node *)n; } ; Index: src/backend/tcop/utility.c =================================================================== RCS file: /home/projects/pgsql/cvsroot/pgsql/src/backend/tcop/utility.c,v retrieving revision 1.116 diff -u -r1.116 utility.c --- src/backend/tcop/utility.c 2001/08/21 16:36:04 1.116 +++ src/backend/tcop/utility.c 2001/08/28 10:21:16 @@ -713,7 +713,7 @@ set_ps_display(commandTag = "EXPLAIN"); - ExplainQuery(stmt->query, stmt->verbose, dest); + ExplainQuery(stmt->query, stmt->verbose, stmt->analyze, dest); } break; Index: src/include/commands/explain.h =================================================================== RCS file: /home/projects/pgsql/cvsroot/pgsql/src/include/commands/explain.h,v retrieving revision 1.11 diff -u -r1.11 explain.h --- src/include/commands/explain.h 2001/01/24 19:43:23 1.11 +++ src/include/commands/explain.h 2001/08/28 10:21:16 @@ -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 */ Index: src/include/nodes/parsenodes.h =================================================================== RCS file: /home/projects/pgsql/cvsroot/pgsql/src/include/nodes/parsenodes.h,v retrieving revision 1.143 diff -u -r1.143 parsenodes.h --- src/include/nodes/parsenodes.h 2001/08/26 16:56:02 1.143 +++ src/include/nodes/parsenodes.h 2001/08/28 10:21:16 @@ -709,6 +709,7 @@ NodeTag type; Query *query; /* the query */ bool verbose; /* print plan info */ + bool analyze; /* get statistics by executing plan */ } ExplainStmt; /* ---------------------- Index: src/include/nodes/plannodes.h =================================================================== RCS file: /home/projects/pgsql/cvsroot/pgsql/src/include/nodes/plannodes.h,v retrieving revision 1.49 diff -u -r1.49 plannodes.h --- src/include/nodes/plannodes.h 2001/03/22 04:00:52 1.49 +++ src/include/nodes/plannodes.h 2001/08/28 10:21:16 @@ -15,6 +15,7 @@ #define PLANNODES_H #include "nodes/execnodes.h" +#include "executor/instrument.h" /* ---------------------------------------------------------------- * Executor State types are used in the plannode structures @@ -73,6 +74,8 @@ * tuples */ Cost total_cost; /* total cost (assuming all tuples * fetched) */ + + Instrumentation *instrument; /* Refers to structure contain instrumentation info */ /* * planner's estimate of result size (note: LIMIT, if any, is not --- src/backend/executor/instrument.c Tue Aug 28 20:25:34 2001 +++ src/backend/executor/instrument.c Sat Jul 21 14:31:25 2001 @@ -0,0 +1,117 @@ +/*------------------------------------------------------------------------- + * + * instrument.c + * Defines the functions dealing with instrumentation of plan execution + * + * Initially By Martijn van Oosterhout 2001 + */ + +#include +#include +#include + +#include "postgres.h" +#include "executor/instrument.h" + +/* If not defined in system header files... */ +#ifndef timerisset +#define timerisset(tvp) ((tvp)->tv_sec || (tvp)->tv_usec) +#define timerclear(tvp) ((tvp)->tv_sec = (tvp)->tv_usec = 0) +#endif + +Instrumentation * +InstrAlloc(void) /* Allocate new instrumentation structure */ +{ + Instrumentation *instr = palloc( sizeof(Instrumentation) ); + memset( instr, 0, sizeof(Instrumentation) ); + + instr->state = INSTR_STATE_FIRSTTUPLE; + + return instr; +} + +void +_InstrStartNode( Instrumentation *instr ) /* When we enter the node */ +{ + if( !instr ) + return; + + if( timerisset( &instr->starttime ) ) + elog(DEBUG, "InstrStartTimer called twice in a row"); + else + gettimeofday( &instr->starttime, NULL ); +} + +void +_InstrStopNode( Instrumentation *instr ) /* When we exit a node */ +{ + struct timeval endtime; + + if( !instr ) + return; + + if( !timerisset( &instr->starttime ) ) + { + 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; + + while( instr->counter.tv_usec < 0 ) + { + instr->counter.tv_usec += 1000000; + instr->counter.tv_sec--; + } + + timerclear( &instr->starttime ); + + if( instr->state == INSTR_STATE_FIRSTTUPLE ) + instr->firsttuple = (float)instr->counter.tv_sec + (float)instr->counter.tv_usec/1000000.0; + + instr->tuplecount++; + instr->state = INSTR_STATE_RUNNING; +} + +void +_InstrEndLoop( Instrumentation *instr ) /* Done with this loop */ +{ + float totaltime; + + if( !instr ) + return; + + if( !timerisset( &instr->counter ) ) /* Skip if nothing has happend */ + return; + + if( instr->state != INSTR_STATE_FIRSTTUPLE && instr->state != INSTR_STATE_RUNNING ) + { + elog(DEBUG, "InstrEndLoop called in strange state (%d)", instr->state); + return; + } + + totaltime = (float)instr->counter.tv_sec + (float)instr->counter.tv_usec / 1000000.0; + + instr->nloops++; + instr->ntuples += instr->tuplecount - 1; /* Subtract one because NULL tuple included */ + instr->startup += instr->firsttuple; + instr->total += totaltime; + + instr->state = INSTR_STATE_FIRSTTUPLE; + instr->firsttuple = 0; + instr->tuplecount = 0; + timerclear( &instr->counter ); + timerclear( &instr->starttime ); +} + +void +InstrDealloc( Instrumentation *instr ) /* Deallocate structure */ +{ + if( !instr ) + return; + + pfree( instr ); +} --- src/include/executor/instrument.h Tue Aug 28 20:25:54 2001 +++ src/include/executor/instrument.h Sat Jul 21 14:30:41 2001 @@ -0,0 +1,46 @@ +/*------------------------------------------------------------------------- + * + * instrument.h + * Declares instrumentation for plan execution + * + * Initially By Martijn van Oosterhout 2001 + */ + +#ifndef INSTRUMENT_H +#define INSTRUMENT_H + +#include + +enum InstrState { + INSTR_STATE_FIRSTTUPLE, + INSTR_STATE_RUNNING, + INSTR_STATE_FINISHED +}; + +typedef struct +{ + struct timeval starttime; /* Start time of this interation of this loop */ + struct timeval counter; /* Count of time for current tuple */ + enum InstrState state; /* State of loop */ + float firsttuple; /* Time for first tuple for this loop */ + int tuplecount; /* Tuples so far this loop */ + + int nloops; /* Total number of times this loop has been executed */ + float startup; /* Total startup time */ + float total; /* Total total time */ + int ntuples; /* Total tuples produced */ +} Instrumentation; + +Instrumentation *InstrAlloc(void); /* Allocate new instrumentation structure */ +void InstrDealloc( Instrumentation * ); /* Deallocate structure */ + +/* #defines to minimize cost when not measuring */ +#define InstrStartNode(x) if(x) { _InstrStartNode(x); } +#define InstrStopNode(x) if(x) { _InstrStopNode(x); } +#define InstrEndLoop(x) if(x) { _InstrEndLoop(x); } + +void _InstrStartNode( Instrumentation * ); /* When we enter the node */ +void _InstrStopNode( Instrumentation * ); /* When we exit a node */ +void _InstrEndLoop( Instrumentation * ); /* Done with this loop (node is finished) */ + +#endif