diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 7a290e8836..02c9534cab 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -7,7 +7,7 @@ * Portions Copyright (c) 1994-5, Regents of the University of California * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.129 2004/12/31 21:59:41 pgsql Exp $ + * $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.130 2005/03/20 22:27:51 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -46,7 +46,7 @@ typedef struct ExplainState static void ExplainOneQuery(Query *query, ExplainStmt *stmt, TupOutputState *tstate); -static double elapsed_time(struct timeval * starttime); +static double elapsed_time(instr_time * starttime); static void explain_outNode(StringInfo str, Plan *plan, PlanState *planstate, Plan *outer_plan, @@ -212,12 +212,12 @@ void ExplainOnePlan(QueryDesc *queryDesc, ExplainStmt *stmt, TupOutputState *tstate) { - struct timeval starttime; + instr_time starttime; double totaltime = 0; ExplainState *es; StringInfo str; - gettimeofday(&starttime, NULL); + INSTR_TIME_SET_CURRENT(starttime); /* If analyzing, we need to cope with queued triggers */ if (stmt->analyze) @@ -275,7 +275,7 @@ ExplainOnePlan(QueryDesc *queryDesc, ExplainStmt *stmt, * Close down the query and free resources; also run any queued * AFTER triggers. Include time for this in the total runtime. */ - gettimeofday(&starttime, NULL); + INSTR_TIME_SET_CURRENT(starttime); ExecutorEnd(queryDesc); @@ -303,14 +303,15 @@ ExplainOnePlan(QueryDesc *queryDesc, ExplainStmt *stmt, pfree(es); } -/* Compute elapsed time in seconds since given gettimeofday() timestamp */ +/* Compute elapsed time in seconds since given timestamp */ static double -elapsed_time(struct timeval * starttime) +elapsed_time(instr_time * starttime) { - struct timeval endtime; + instr_time endtime; - gettimeofday(&endtime, NULL); + INSTR_TIME_SET_CURRENT(endtime); +#ifndef WIN32 endtime.tv_sec -= starttime->tv_sec; endtime.tv_usec -= starttime->tv_usec; while (endtime.tv_usec < 0) @@ -318,8 +319,11 @@ elapsed_time(struct timeval * starttime) endtime.tv_usec += 1000000; endtime.tv_sec--; } - return (double) endtime.tv_sec + - (double) endtime.tv_usec / 1000000.0; +#else /* WIN32 */ + endtime.QuadPart -= starttime->QuadPart; +#endif + + return INSTR_TIME_GET_DOUBLE(endtime); } /* diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index 381e6ae4ef..8b9b6abb93 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -7,7 +7,7 @@ * Copyright (c) 2001-2005, PostgreSQL Global Development Group * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/executor/instrument.c,v 1.9 2005/01/01 05:43:06 momjian Exp $ + * $PostgreSQL: pgsql/src/backend/executor/instrument.c,v 1.10 2005/03/20 22:27:51 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -36,29 +36,30 @@ InstrStartNode(Instrumentation *instr) if (!instr) return; - if (instr->starttime.tv_sec != 0 || instr->starttime.tv_usec != 0) + if (!INSTR_TIME_IS_ZERO(instr->starttime)) elog(DEBUG2, "InstrStartNode called twice in a row"); else - gettimeofday(&instr->starttime, NULL); + INSTR_TIME_SET_CURRENT(instr->starttime); } /* Exit from a plan node */ void InstrStopNode(Instrumentation *instr, bool returnedTuple) { - struct timeval endtime; + instr_time endtime; if (!instr) return; - if (instr->starttime.tv_sec == 0 && instr->starttime.tv_usec == 0) + if (INSTR_TIME_IS_ZERO(instr->starttime)) { elog(DEBUG2, "InstrStopNode without start"); return; } - gettimeofday(&endtime, NULL); + INSTR_TIME_SET_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,16 +74,17 @@ InstrStopNode(Instrumentation *instr, bool returnedTuple) instr->counter.tv_usec -= 1000000; instr->counter.tv_sec++; } +#else /* WIN32 */ + instr->counter.QuadPart += (endtime.QuadPart - instr->starttime.QuadPart); +#endif - instr->starttime.tv_sec = 0; - instr->starttime.tv_usec = 0; + INSTR_TIME_SET_ZERO(instr->starttime); /* 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; + instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter); } if (returnedTuple) @@ -103,8 +105,7 @@ InstrEndLoop(Instrumentation *instr) return; /* Accumulate statistics */ - totaltime = (double) instr->counter.tv_sec + - (double) instr->counter.tv_usec / 1000000.0; + totaltime = INSTR_TIME_GET_DOUBLE(instr->counter); instr->startup += instr->firsttuple; instr->total += totaltime; @@ -113,10 +114,8 @@ InstrEndLoop(Instrumentation *instr) /* 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_TIME_SET_ZERO(instr->starttime); + INSTR_TIME_SET_ZERO(instr->counter); instr->firsttuple = 0; instr->tuplecount = 0; } diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 754655c1fd..8936c5cce2 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -6,7 +6,7 @@ * * Copyright (c) 2001-2005, PostgreSQL Global Development Group * - * $PostgreSQL: pgsql/src/include/executor/instrument.h,v 1.8 2005/01/01 05:43:09 momjian Exp $ + * $PostgreSQL: pgsql/src/include/executor/instrument.h,v 1.9 2005/03/20 22:27:52 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -16,12 +16,51 @@ #include +/* + * gettimeofday() does not have sufficient resolution on Windows, + * so we must use QueryPerformanceCounter() instead. These macros + * also give some breathing room to use other high-precision-timing APIs + * on yet other platforms. (The macro-ization is not complete, however; + * see subtraction code in instrument.c and explain.c.) + */ +#ifndef WIN32 + +typedef struct timeval instr_time; + +#define INSTR_TIME_IS_ZERO(t) ((t).tv_sec == 0 && (t).tv_usec == 0) +#define INSTR_TIME_SET_ZERO(t) ((t).tv_sec = 0, (t).tv_usec = 0) +#define INSTR_TIME_SET_CURRENT(t) gettimeofday(&(t), NULL) +#define INSTR_TIME_GET_DOUBLE(t) \ + (((double) (t).tv_sec) + ((double) (t).tv_usec) / 1000000.0) + +#else /* WIN32 */ + +typedef LARGE_INTEGER instr_time; + +#define INSTR_TIME_IS_ZERO(t) ((t).QuadPart == 0) +#define INSTR_TIME_SET_ZERO(t) ((t).QuadPart = 0) +#define INSTR_TIME_SET_CURRENT(t) QueryPerformanceCounter(&(t)) +#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 /* WIN32 */ + + 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 */ + 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: */