Index: include/executor/instrument.h =================================================================== RCS file: /projects/cvsroot/pgsql/src/include/executor/instrument.h,v retrieving revision 1.8 diff -c -r1.8 instrument.h *** include/executor/instrument.h 1 Jan 2005 05:43:09 -0000 1.8 --- include/executor/instrument.h 20 Mar 2005 18:12:45 -0000 *************** *** 15,27 **** #include 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: */ --- 15,53 ---- #include + /* + * gettimeofday() does not have sufficient resolution on win32, + * so we must use QueryPerformanceCounter() instead. + */ + #ifndef WIN32 + typedef struct timeval instr_time; + #define INSTR_TIME_IS_ZERO(t) (t.tv_sec == 0 && t.tv_usec == 0) + #define INSTR_TIME_GET_CURRENT(t) gettimeofday(&t, NULL) + #define INSTR_TIME_SET_ZERO(t) t.tv_sec=0;t.tv_usec=0; + #define INSTR_TIME_GET_DOUBLE(t) ((double)t.tv_sec + (double)t.tv_usec / 1000000.0) + #else + typedef LARGE_INTEGER instr_time; + #define INSTR_TIME_IS_ZERO(t) (t.QuadPart==0) + #define INSTR_TIME_GET_CURRENT(t) QueryPerformanceCounter(&t) + #define INSTR_TIME_SET_ZERO(t) t.QuadPart=0; + #define INSTR_TIME_GET_DOUBLE(t) ((double)t.QuadPart / GetTimerFrequency()) + + static __inline__ double GetTimerFrequency(void) + { + LARGE_INTEGER f; + QueryPerformanceFrequency(&f); + return (double)f.QuadPart; + } + #endif + + typedef struct Instrumentation { /* Info about current plan cycle: */ bool running; /* TRUE if we've completed first tuple */ ! instr_time starttime; /* Start time of current iteration of node */ ! instr_time 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: */ Index: backend/executor/instrument.c =================================================================== RCS file: /projects/cvsroot/pgsql/src/backend/executor/instrument.c,v retrieving revision 1.9 diff -c -r1.9 instrument.c *** backend/executor/instrument.c 1 Jan 2005 05:43:06 -0000 1.9 --- backend/executor/instrument.c 20 Mar 2005 18:35:22 -0000 *************** *** 36,64 **** if (!instr) return; ! if (instr->starttime.tv_sec != 0 || instr->starttime.tv_usec != 0) elog(DEBUG2, "InstrStartNode 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(DEBUG2, "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; --- 36,65 ---- if (!instr) return; ! if (!INSTR_TIME_IS_ZERO(instr->starttime)) elog(DEBUG2, "InstrStartNode called twice in a row"); else ! INSTR_TIME_GET_CURRENT(instr->starttime); } /* Exit from a plan node */ void InstrStopNode(Instrumentation *instr, bool returnedTuple) { ! instr_time endtime; if (!instr) return; ! if (INSTR_TIME_IS_ZERO(instr->starttime)) { elog(DEBUG2, "InstrStopNode without start"); return; } ! INSTR_TIME_GET_CURRENT(endtime); + #ifndef WIN32 instr->counter.tv_sec += endtime.tv_sec - instr->starttime.tv_sec; instr->counter.tv_usec += endtime.tv_usec - instr->starttime.tv_usec; *************** *** 73,88 **** 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) --- 74,89 ---- instr->counter.tv_usec -= 1000000; instr->counter.tv_sec++; } ! #else /* WIN32 */ ! instr->counter.QuadPart += (endtime.QuadPart - instr->starttime.QuadPart); ! #endif ! INSTR_TIME_SET_ZERO(instr->starttime); /* Is this the first tuple of this cycle? */ if (!instr->running) { instr->running = true; ! instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter); } if (returnedTuple) *************** *** 103,110 **** return; /* Accumulate statistics */ ! totaltime = (double) instr->counter.tv_sec + ! (double) instr->counter.tv_usec / 1000000.0; instr->startup += instr->firsttuple; instr->total += totaltime; --- 104,110 ---- return; /* Accumulate statistics */ ! totaltime = INSTR_TIME_GET_DOUBLE(instr->counter); instr->startup += instr->firsttuple; instr->total += totaltime; *************** *** 113,122 **** /* 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; } --- 113,120 ---- /* Reset for next cycle (if any) */ instr->running = false; ! INSTR_TIME_SET_ZERO(instr->starttime); ! INSTR_TIME_SET_ZERO(instr->counter); instr->firsttuple = 0; instr->tuplecount = 0; } Index: backend/commands/explain.c =================================================================== RCS file: /projects/cvsroot/pgsql/src/backend/commands/explain.c,v retrieving revision 1.129 diff -c -r1.129 explain.c *** backend/commands/explain.c 31 Dec 2004 21:59:41 -0000 1.129 --- backend/commands/explain.c 20 Mar 2005 18:15:42 -0000 *************** *** 46,52 **** static void ExplainOneQuery(Query *query, ExplainStmt *stmt, TupOutputState *tstate); ! static double elapsed_time(struct timeval * starttime); static void explain_outNode(StringInfo str, Plan *plan, PlanState *planstate, Plan *outer_plan, --- 46,52 ---- static void ExplainOneQuery(Query *query, ExplainStmt *stmt, TupOutputState *tstate); ! static double elapsed_time(instr_time * starttime); static void explain_outNode(StringInfo str, Plan *plan, PlanState *planstate, Plan *outer_plan, *************** *** 212,223 **** ExplainOnePlan(QueryDesc *queryDesc, ExplainStmt *stmt, TupOutputState *tstate) { ! struct timeval starttime; double totaltime = 0; ExplainState *es; StringInfo str; ! gettimeofday(&starttime, NULL); /* If analyzing, we need to cope with queued triggers */ if (stmt->analyze) --- 212,223 ---- ExplainOnePlan(QueryDesc *queryDesc, ExplainStmt *stmt, TupOutputState *tstate) { ! instr_time starttime; double totaltime = 0; ExplainState *es; StringInfo str; ! INSTR_TIME_GET_CURRENT(starttime); /* If analyzing, we need to cope with queued triggers */ if (stmt->analyze) *************** *** 275,281 **** * Close down the query and free resources; also run any queued * AFTER triggers. Include time for this in the total runtime. */ ! gettimeofday(&starttime, NULL); ExecutorEnd(queryDesc); --- 275,281 ---- * Close down the query and free resources; also run any queued * AFTER triggers. Include time for this in the total runtime. */ ! INSTR_TIME_GET_CURRENT(starttime); ExecutorEnd(queryDesc); *************** *** 303,316 **** pfree(es); } ! /* Compute elapsed time in seconds since given gettimeofday() timestamp */ static double ! elapsed_time(struct timeval * starttime) { ! struct timeval endtime; ! gettimeofday(&endtime, NULL); endtime.tv_sec -= starttime->tv_sec; endtime.tv_usec -= starttime->tv_usec; while (endtime.tv_usec < 0) --- 303,317 ---- pfree(es); } ! /* Compute elapsed time in seconds since given timestamp */ static double ! elapsed_time(instr_time * starttime) { ! instr_time endtime; ! INSTR_TIME_GET_CURRENT(endtime); + #ifndef WIN32 endtime.tv_sec -= starttime->tv_sec; endtime.tv_usec -= starttime->tv_usec; while (endtime.tv_usec < 0) *************** *** 318,325 **** endtime.tv_usec += 1000000; endtime.tv_sec--; } ! return (double) endtime.tv_sec + ! (double) endtime.tv_usec / 1000000.0; } /* --- 319,328 ---- endtime.tv_usec += 1000000; endtime.tv_sec--; } ! #else ! endtime.QuadPart -= starttime->QuadPart; ! #endif ! return INSTR_TIME_GET_DOUBLE(endtime); } /*