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/07/20 14:01:33 @@ -29,7 +29,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 +42,7 @@ * */ void -ExplainQuery(Query *query, bool verbose, CommandDest dest) +ExplainQuery(Query *query, bool verbose, bool analyze, CommandDest dest) { List *rewritten; List *l; @@ -73,7 +74,7 @@ /* Explain every plan */ foreach(l, rewritten) - ExplainOneQuery(lfirst(l), verbose, dest); + ExplainOneQuery(lfirst(l), verbose, analyze, dest); } /* @@ -82,7 +83,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 +106,11 @@ 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 ) + ProcessQuery( query, plan, None ); + es = (ExplainState *) palloc(sizeof(ExplainState)); MemSet(es, 0, sizeof(ExplainState)); @@ -292,6 +298,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/07/20 14:01:33 @@ -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/07/20 14:01:34 @@ -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/07/20 14:01:34 @@ -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" @@ -130,6 +131,8 @@ return FALSE; } + node->instrument = InstrAlloc(); + switch (nodeTag(node)) { @@ -257,6 +260,8 @@ if (node->chgParam != NULL) /* something changed */ ExecReScan(node, NULL, parent); /* let ReScan handle this */ + InstrStartNode( node->instrument ); + switch (nodeTag(node)) { @@ -346,6 +351,11 @@ result = NULL; } + InstrStopNode( node->instrument ); + + if( TupIsNull(result) ) + InstrEndLoop( node->instrument ); + return result; } @@ -450,6 +460,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.238 diff -u -r2.238 gram.y --- src/backend/parser/gram.y 2001/07/16 19:07:40 2.238 +++ src/backend/parser/gram.y 2001/07/20 14:01:35 @@ -3154,6 +3154,7 @@ * * QUERY: * EXPLAIN query + * EXPLAIN ANALYZE [select statement] * *****************************************************************************/ @@ -3161,7 +3162,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.115 diff -u -r1.115 utility.c --- src/backend/tcop/utility.c 2001/07/16 05:06:58 1.115 +++ src/backend/tcop/utility.c 2001/07/20 14:01:36 @@ -714,7 +714,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/07/20 14:01:36 @@ -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.136 diff -u -r1.136 parsenodes.h --- src/include/nodes/parsenodes.h 2001/07/16 19:07:40 1.136 +++ src/include/nodes/parsenodes.h 2001/07/20 14:01:36 @@ -708,6 +708,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/07/20 14:01:36 @@ -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/include/executor/instrument.h Thu Jul 6 03:49:51 2000 +++ src/include/executor/instrument.h Thu Jul 19 22:18:56 2001 @@ -0,0 +1,41 @@ +/*------------------------------------------------------------------------- + * + * instrument.h + * Declares instrumentation for plan execution + * + * Initially By Martijn van Oosterhout 2001 + */ + +#ifndef INSTRUMENT_H +#define INSTRUMENT_H + +#include + +enum InstrState { + INSTR_STATE_START = 0, + 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 InstrStartNode( Instrumentation *i ); /* When we enter the node */ +void InstrStopNode( Instrumentation *i ); /* When we exit a node */ +void InstrEndLoop( Instrumentation * ); /* Done with this loop (node is finished) */ +void InstrDealloc( Instrumentation * ); /* Deallocate structure */ + +#endif --- src/backend/executor/instrument.c Thu Jul 6 03:49:51 2000 +++ src/backend/executor/instrument.c Fri Jul 20 23:20:59 2001 @@ -0,0 +1,111 @@ +/*------------------------------------------------------------------------- + * + * 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" + +Instrumentation * +InstrAlloc(void) /* Allocate new instrumentation structure */ +{ + Instrumentation *i = palloc( sizeof(Instrumentation) ); + bzero( i, sizeof(Instrumentation) ); + + i->state = INSTR_STATE_FIRSTTUPLE; + + return i; +} + +void +InstrStartNode( Instrumentation *i ) /* When we enter the node */ +{ + if( !i ) + return; + + if( timerisset( &i->starttime ) ) + elog(DEBUG, "InstrStartTimer called twice in a row"); + else + gettimeofday( &i->starttime, NULL ); +} + +void +InstrStopNode( Instrumentation *i ) /* When we exit a node */ +{ + struct timeval endtime; + + if( !i ) + return; + + if( !timerisset( &i->starttime ) ) + { + elog(DEBUG, "InstrStopNode without start"); + return; + } + + gettimeofday( &endtime, NULL ); + + i->counter.tv_sec += endtime.tv_sec - i->starttime.tv_sec; + i->counter.tv_usec += endtime.tv_usec - i->starttime.tv_usec; + + while( i->counter.tv_usec < 0 ) + { + i->counter.tv_usec += 1000000; + i->counter.tv_sec--; + } + + timerclear( &i->starttime ); + + if( i->state == INSTR_STATE_FIRSTTUPLE ) + i->firsttuple = (float)i->counter.tv_sec + (float)i->counter.tv_usec/1000000.0; + + i->tuplecount++; + i->state = INSTR_STATE_RUNNING; +} + +void +InstrEndLoop( Instrumentation *i ) /* Done with this loop */ +{ + float totaltime; + + if( !i ) + return; + + if( !timerisset( &i->counter ) ) /* Skip if nothing has happend */ + return; + + if( i->state != INSTR_STATE_FIRSTTUPLE && i->state != INSTR_STATE_RUNNING ) + { + elog(DEBUG, "InstrEndLoop called in strange state (%d)", i->state); + return; + } + + totaltime = (float)i->counter.tv_sec + (float)i->counter.tv_usec / 1000000.0; + + i->nloops++; + i->ntuples += i->tuplecount - 1; /* Subtract one because NULL tuple included */ + i->startup += i->firsttuple; + i->total += totaltime; + + i->state = INSTR_STATE_FIRSTTUPLE; + i->firsttuple = 0; + i->tuplecount = 0; + timerclear( &i->counter ); + timerclear( &i->starttime ); +} + +void +InstrDealloc( Instrumentation *i ) /* Deallocate structure */ +{ + if( !i ) + return; + + pfree( i ); +}