Re: [pgsql-hackers-win32] explain analyze timings
"Magnus Hagander" <[email protected]> Sun, 20 Mar 2005 19:37:13 +0100
| Newsgroups | gmane.comp.db.postgresql.devel.patches,gmane.comp.db.postgresql.devel.win32 |
|---|---|
| Message-ID | <[email protected]> |
>> Here's a patch that does just this.
>
>This seems about the ugliest and most intrusive way you could have
>done it :-(. A judicious typedef and macro or two could eliminate
>most of the #ifdefs and code duplication, thereby preserving
>readability...
Well, I certainly can't argue with that, now that you mention it ;-)
Here is a second attempt, hope it's closer to what you expected.
I still left two #ifdefs in there, for the addition and subtraction of
timeval:s specifically. They could be made functions/macros too, just
not sure if it's worth it.
Tested on win32 and linux (now that it changes non-win32 specific code
as well).
//Magnus
---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?
http://www.postgresql.org/docs/faq
win32_instr2.patch
(application/octet-stream, 8.8 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 18:12:45 -0000
***************
*** 15,27 ****
#include <sys/time.h>
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 <sys/time.h>
+ /*
+ * 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);
}
/*