Re: explain analyze timings
"Magnus Hagander" <[email protected]> Sun, 20 Mar 2005 14:42:24 +0100
| Newsgroups | gmane.comp.db.postgresql.devel.win32,gmane.comp.db.postgresql.devel.patches |
|---|---|
| Message-ID | <[email protected]> |
>> There is. I beleive QueryPerformanceCounter has sub-mirosecond
>> resolution.
>
>> Can we just replace gettimeofday() with a version that's basically:
>
>No, because it's also used for actual time-of-day calls. It'd be
>necessary to hack executor/instrument.c in particular.
Here's a patch that does just this.
On my system, the counter resolution is 3192090000 ticks per second
(Intel Xeon CPU). On a AMD Athlon XP system, it's 3579545 ticks per
second (a lot less, but still way way way better than gettimeofday has
on win32).
I also hacked commands/explain.c to get the total runtime of the query
correct.
//Magnus
---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to [email protected] so that your
message can get through to the mailing list cleanly
win32_instr.patch
(application/octet-stream, 6.4 KB)
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 12:45:34 -0000
***************
*** 20,27 ****
--- 20,32 ----
{
/* Info about current plan cycle: */
bool running; /* TRUE if we've completed first tuple */
+ #ifndef WIN32
struct timeval starttime; /* Start time of current iteration of node */
struct timeval counter; /* Accumulates runtime for this node */
+ #else
+ LARGE_INTEGER starttime; /* Start time of current iteration of node */
+ LARGE_INTEGER counter; /* Accumulates runtime for this node */
+ #endif
double firsttuple; /* Time for first tuple of this cycle */
double tuplecount; /* Tuples so far this cycle */
/* Accumulated statistics across all completed cycles: */
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 13:19:28 -0000
***************
*** 46,52 ****
--- 46,56 ----
static void ExplainOneQuery(Query *query, ExplainStmt *stmt,
TupOutputState *tstate);
+ #ifndef WIN32
static double elapsed_time(struct timeval * starttime);
+ #else
+ static double elapsed_time(LARGE_INTEGER * starttime);
+ #endif
static void explain_outNode(StringInfo str,
Plan *plan, PlanState *planstate,
Plan *outer_plan,
***************
*** 212,223 ****
--- 216,235 ----
ExplainOnePlan(QueryDesc *queryDesc, ExplainStmt *stmt,
TupOutputState *tstate)
{
+ #ifndef WIN32
struct timeval starttime;
+ #else
+ LARGE_INTEGER starttime;
+ #endif
double totaltime = 0;
ExplainState *es;
StringInfo str;
+ #ifndef WIN32
gettimeofday(&starttime, NULL);
+ #else
+ QueryPerformanceCounter(&starttime);
+ #endif
/* If analyzing, we need to cope with queued triggers */
if (stmt->analyze)
***************
*** 275,281 ****
--- 287,297 ----
* Close down the query and free resources; also run any queued
* AFTER triggers. Include time for this in the total runtime.
*/
+ #ifndef WIN32
gettimeofday(&starttime, NULL);
+ #else
+ QueryPerformanceCounter(&starttime);
+ #endif
ExecutorEnd(queryDesc);
***************
*** 304,309 ****
--- 320,326 ----
}
/* Compute elapsed time in seconds since given gettimeofday() timestamp */
+ #ifndef WIN32
static double
elapsed_time(struct timeval * starttime)
{
***************
*** 321,326 ****
--- 338,356 ----
return (double) endtime.tv_sec +
(double) endtime.tv_usec / 1000000.0;
}
+ #else
+ static double
+ elapsed_time(LARGE_INTEGER *starttime)
+ {
+ LARGE_INTEGER endtime;
+ LARGE_INTEGER frequency;
+
+ QueryPerformanceCounter(&endtime);
+ QueryPerformanceFrequency(&frequency);
+
+ return (double)(endtime.QuadPart-starttime->QuadPart)/(double)frequency.QuadPart;
+ }
+ #endif
/*
* explain_outNode -
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 13:32:57 -0000
***************
*** 36,62 ****
--- 36,78 ----
if (!instr)
return;
+ #ifndef WIN32
if (instr->starttime.tv_sec != 0 || instr->starttime.tv_usec != 0)
elog(DEBUG2, "InstrStartNode called twice in a row");
else
gettimeofday(&instr->starttime, NULL);
+ #else
+ if (instr->starttime.QuadPart != 0)
+ elog(DEBUG2, "InstrStartNode called twice in a row");
+ else
+ QueryPerformanceCounter(&instr->starttime);
+ #endif
}
/* Exit from a plan node */
void
InstrStopNode(Instrumentation *instr, bool returnedTuple)
{
+ #ifndef WIN32
struct timeval endtime;
+ #else
+ LARGE_INTEGER endtime;
+ #endif
if (!instr)
return;
+ #ifndef WIN32
if (instr->starttime.tv_sec == 0 && instr->starttime.tv_usec == 0)
+ #else
+ if (instr->starttime.QuadPart == 0)
+ #endif
{
elog(DEBUG2, "InstrStopNode without start");
return;
}
+ #ifndef WIN32
gettimeofday(&endtime, NULL);
instr->counter.tv_sec += endtime.tv_sec - instr->starttime.tv_sec;
***************
*** 84,89 ****
--- 100,120 ----
instr->firsttuple = (double) instr->counter.tv_sec +
(double) instr->counter.tv_usec / 1000000.0;
}
+ #else /* WIN32 */
+ QueryPerformanceCounter(&endtime);
+ instr->counter.QuadPart += (endtime.QuadPart - instr->starttime.QuadPart);
+ instr->starttime.QuadPart = 0;
+
+ /* Is this the first tuple of this cycle? */
+ if (!instr->running)
+ {
+ LARGE_INTEGER frequency;
+
+ QueryPerformanceFrequency(&frequency);
+ instr->running = true;
+ instr->firsttuple = (double)instr->counter.QuadPart / (double)frequency.QuadPart;
+ }
+ #endif
if (returnedTuple)
instr->tuplecount += 1;
***************
*** 94,99 ****
--- 125,133 ----
InstrEndLoop(Instrumentation *instr)
{
double totaltime;
+ #ifdef WIN32
+ LARGE_INTEGER frequency;
+ #endif
if (!instr)
return;
***************
*** 103,110 ****
--- 137,149 ----
return;
/* Accumulate statistics */
+ #ifndef WIN32
totaltime = (double) instr->counter.tv_sec +
(double) instr->counter.tv_usec / 1000000.0;
+ #else
+ QueryPerformanceFrequency(&frequency);
+ totaltime = (double)instr->counter.QuadPart / (double)frequency.QuadPart;
+ #endif
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;
}
--- 152,166 ----
/* Reset for next cycle (if any) */
instr->running = false;
+ instr->firsttuple = 0;
+ instr->tuplecount = 0;
+ #ifndef WIN32
instr->starttime.tv_sec = 0;
instr->starttime.tv_usec = 0;
instr->counter.tv_sec = 0;
instr->counter.tv_usec = 0;
! #else
! instr->starttime.QuadPart = 0;
! instr->counter.QuadPart = 0;
! #endif
}