diff options
-rw-r--r-- | doc/timerate.n | 11 | ||||
-rw-r--r-- | generic/tclCmdMZ.c | 50 | ||||
-rw-r--r-- | generic/tclPort.h | 3 | ||||
-rw-r--r-- | tests/cmdMZ.test | 64 | ||||
-rw-r--r-- | win/tclWinTime.c | 171 |
5 files changed, 230 insertions, 69 deletions
diff --git a/doc/timerate.n b/doc/timerate.n index df9a8f7..2380597 100644 --- a/doc/timerate.n +++ b/doc/timerate.n @@ -11,17 +11,20 @@ .SH NAME timerate \- Time-related execution resp. performance measurement of a script .SH SYNOPSIS -\fBtimerate \fIscript\fR \fI?time?\fR +\fBtimerate \fIscript\fR \fI?time ?max-count??\fR .sp -\fBtimerate \fI?-direct?\fR \fI?-overhead double?\fR \fIscript\fR \fI?time?\fR +\fBtimerate \fI?-direct?\fR \fI?-overhead double?\fR \fIscript\fR \fI?time ?max-count??\fR .sp -\fBtimerate \fI?-calibrate?\fR \fI?-direct?\fR \fIscript\fR \fI?time?\fR +\fBtimerate \fI?-calibrate?\fR \fI?-direct?\fR \fIscript\fR \fI?time ?max-count??\fR .BE .SH DESCRIPTION .PP The first and second form will evaluate \fIscript\fR until the interval \fItime\fR given in milliseconds elapses, or for 1000 milliseconds (1 second) -if \fItime\fR is not specified. +if \fItime\fR is not specified. +.sp +If \fImax-count\fR is specified, it imposes a further restriction by the maximal +number of iterations. .sp It will then return a canonical tcl-list of the form .PP diff --git a/generic/tclCmdMZ.c b/generic/tclCmdMZ.c index dd4c2a6..4bc82e4 100644 --- a/generic/tclCmdMZ.c +++ b/generic/tclCmdMZ.c @@ -4299,8 +4299,10 @@ Tcl_TimeRateObjCmd( register int result, i; Tcl_Obj *calibrate = NULL, *direct = NULL; Tcl_WideUInt count = 0; /* Holds repetition count */ - Tcl_WideInt maxms = -0x7FFFFFFFFFFFFFFFL; + Tcl_WideInt maxms = WIDE_MIN; /* Maximal running time (in milliseconds) */ + Tcl_WideUInt maxcnt = WIDE_MAX; + /* Maximal count of iterations. */ Tcl_WideUInt threshold = 1; /* Current threshold for check time (faster * repeat count without time check) */ Tcl_WideUInt maxIterTm = 1; /* Max time of some iteration as max threshold @@ -4350,24 +4352,32 @@ Tcl_TimeRateObjCmd( } } - if (i >= objc || i < objc-2) { + if (i >= objc || i < objc-3) { usage: - Tcl_WrongNumArgs(interp, 1, objv, "?-direct? ?-calibrate? ?-overhead double? command ?time?"); + Tcl_WrongNumArgs(interp, 1, objv, "?-direct? ?-calibrate? ?-overhead double? command ?time ?max-count??"); return TCL_ERROR; } objPtr = objv[i++]; - if (i < objc) { - result = TclGetWideIntFromObj(interp, objv[i], &maxms); + if (i < objc) { /* max-time */ + result = Tcl_GetWideIntFromObj(interp, objv[i++], &maxms); if (result != TCL_OK) { return result; } + if (i < objc) { /* max-count*/ + Tcl_WideInt v; + result = Tcl_GetWideIntFromObj(interp, objv[i], &v); + if (result != TCL_OK) { + return result; + } + maxcnt = (v > 0) ? v : 0; + } } /* if calibrate */ if (calibrate) { /* if no time specified for the calibration */ - if (maxms == -0x7FFFFFFFFFFFFFFFL) { + if (maxms == WIDE_MIN) { Tcl_Obj *clobjv[6]; Tcl_WideInt maxCalTime = 5000; double lastMeasureOverhead = measureOverhead; @@ -4397,7 +4407,7 @@ usage: clobjv[i++] = objPtr; /* set last measurement overhead to max */ - measureOverhead = (double)0x7FFFFFFFFFFFFFFFL; + measureOverhead = (double)UWIDE_MAX; /* calibration cycle until it'll be preciser */ maxms = -1000; @@ -4431,14 +4441,14 @@ usage: /* if time is negative - make current overhead more precise */ if (maxms > 0) { /* set last measurement overhead to max */ - measureOverhead = (double)0x7FFFFFFFFFFFFFFFL; + measureOverhead = (double)UWIDE_MAX; } else { maxms = -maxms; } } - if (maxms == -0x7FFFFFFFFFFFFFFFL) { + if (maxms == WIDE_MIN) { maxms = 1000; } if (overhead == -1) { @@ -4471,6 +4481,7 @@ usage: #endif /* start measurement */ + if (maxcnt > 0) while (1) { /* eval single iteration */ count++; @@ -4485,7 +4496,14 @@ usage: result = TclEvalObjEx(interp, objPtr, 0, NULL, 0); } if (result != TCL_OK) { - goto done; + /* allow break from measurement cycle (used for conditional stop) */ + if (result != TCL_BREAK) { + goto done; + } + /* force stop immediately */ + threshold = 1; + maxcnt = 0; + result = TCL_OK; } /* don't check time up to threshold */ @@ -4498,7 +4516,7 @@ usage: Tcl_GetTime(&now); middle = now.sec; middle *= 1000000; middle += now.usec; #endif - if (middle >= stop) { + if (middle >= stop || count >= maxcnt) { break; } @@ -4533,6 +4551,10 @@ usage: if (threshold > 100000) { /* fix for too large threshold */ threshold = 100000; } + /* consider max-count */ + if (threshold > maxcnt - count) { + threshold = maxcnt - count; + } } { @@ -4552,11 +4574,11 @@ usage: /* minimize influence of measurement overhead */ if (overhead > 0) { /* estimate the time of overhead (microsecs) */ - Tcl_WideInt curOverhead = overhead * count; + Tcl_WideUInt curOverhead = overhead * count; if (middle > curOverhead) { middle -= curOverhead; } else { - middle = 1; + middle = 0; } } } else { @@ -4585,7 +4607,7 @@ usage: /* calculate speed as rate (count) per sec */ if (!middle) middle++; /* +1 ms, just to avoid divide by zero */ - if (count < (0x7FFFFFFFFFFFFFFFL / 1000000)) { + if (count < (WIDE_MAX / 1000000)) { val = (count * 1000000) / middle; if (val < 100000) { if (val < 100) { fmt = "%.3f"; } else diff --git a/generic/tclPort.h b/generic/tclPort.h index 12a60db..9485567 100644 --- a/generic/tclPort.h +++ b/generic/tclPort.h @@ -39,5 +39,8 @@ # define LLONG_MAX (~LLONG_MIN) #endif +#define UWIDE_MAX ((Tcl_WideUInt)-1) +#define WIDE_MAX ((Tcl_WideInt)(UWIDE_MAX >> 1)) +#define WIDE_MIN ((Tcl_WideInt)((Tcl_WideUInt)WIDE_MAX+1)) #endif /* _TCLPORT */ diff --git a/tests/cmdMZ.test b/tests/cmdMZ.test index 2d68138..c3afc8d 100644 --- a/tests/cmdMZ.test +++ b/tests/cmdMZ.test @@ -342,6 +342,70 @@ test cmdMZ-5.7 {Tcl_TimeObjCmd: errors generate right trace} { invoked from within "time {error foo}"}} +test cmdMZ-6.1 {Tcl_TimeRateObjCmd: basic format of command} { + list [catch {timerate} msg] $msg +} {1 {wrong # args: should be "timerate ?-direct? ?-calibrate? ?-overhead double? command ?time ?max-count??"}} +test cmdMZ-6.2.1 {Tcl_TimeRateObjCmd: basic format of command} { + list [catch {timerate a b c d} msg] $msg +} {1 {wrong # args: should be "timerate ?-direct? ?-calibrate? ?-overhead double? command ?time ?max-count??"}} +test cmdMZ-6.2.2 {Tcl_TimeRateObjCmd: basic format of command} { + list [catch {timerate a b c} msg] $msg +} {1 {expected integer but got "b"}} +test cmdMZ-6.2.3 {Tcl_TimeRateObjCmd: basic format of command} { + list [catch {timerate a b} msg] $msg +} {1 {expected integer but got "b"}} +test cmdMZ-6.3 {Tcl_TimeRateObjCmd: basic format of command} { + list [catch {timerate -overhead b {} a b} msg] $msg +} {1 {expected floating-point number but got "b"}} +test cmdMZ-6.4 {Tcl_TimeRateObjCmd: compile of script happens even with negative iteration counts} { + list [catch {timerate "foreach a {c d e} \{" -12456} msg] $msg +} {1 {missing close-brace}} +test cmdMZ-6.5 {Tcl_TimeRateObjCmd: result format and one iteration} { + regexp {^\d+.\d+ \ws/# 1 # \d+ #/sec \d+.\d+ nett-ms$} [timerate {} 0] +} 1 +test cmdMZ-6.6 {Tcl_TimeRateObjCmd: slower commands take longer, but it remains almost the same time of measument} { + set m1 [timerate {after 0} 20] + set m2 [timerate {after 1} 20] + list \ + [expr {[lindex $m1 0] < [lindex $m2 0]}] \ + [expr {[lindex $m1 0] < 100}] \ + [expr {[lindex $m2 0] >= 500}] \ + [expr {[lindex $m1 2] > 1000}] \ + [expr {[lindex $m2 2] <= 50}] \ + [expr {[lindex $m1 4] > 10000}] \ + [expr {[lindex $m2 4] < 10000}] \ + [expr {[lindex $m1 6] > 10 && [lindex $m1 6] < 50}] \ + [expr {[lindex $m2 6] > 10 && [lindex $m2 6] < 50}] +} [lrepeat 9 1] +test cmdMZ-6.7 {Tcl_TimeRateObjCmd: errors generate right trace} { + list [catch {timerate {error foo} 1} msg] $msg $::errorInfo +} {1 foo {foo + while executing +"error foo" + invoked from within +"timerate {error foo} 1"}} +test cmdMZ-6.8 {Tcl_TimeRateObjCmd: allow (conditional) break from timerate} { + set m1 [timerate {break}] + list \ + [expr {[lindex $m1 0] < 1000}] \ + [expr {[lindex $m1 2] == 1}] \ + [expr {[lindex $m1 4] > 1000}] \ + [expr {[lindex $m1 6] < 10}] +} {1 1 1 1} +test cmdMZ-6.9 {Tcl_TimeRateObjCmd: max count of iterations} { + set m1 [timerate {} 1000 5]; # max-count wins + set m2 [timerate {after 20} 1 5]; # max-time wins + list [lindex $m1 2] [lindex $m2 2] +} {5 1} +test cmdMZ-6.10 {Tcl_TimeRateObjCmd: huge overhead cause 0us result} { + set m1 [timerate -overhead 1e6 {after 10} 100 1] + list \ + [expr {[lindex $m1 0] == 0.0}] \ + [expr {[lindex $m1 2] == 1}] \ + [expr {[lindex $m1 4] == 1000000}] \ + [expr {[lindex $m1 6] <= 0.001}] +} {1 1 1 1} + # The tests for Tcl_WhileObjCmd are in while.test # cleanup diff --git a/win/tclWinTime.c b/win/tclWinTime.c index fd14595..d4e84ba 100644 --- a/win/tclWinTime.c +++ b/win/tclWinTime.c @@ -51,6 +51,7 @@ typedef struct TimeInfo { * initialized. */ int perfCounterAvailable; /* Flag == 1 if the hardware has a performance * counter. */ + DWORD calibrationInterv; /* Calibration interval in seconds (start 1 sec) */ HANDLE calibrationThread; /* Handle to the thread that keeps the virtual * clock calibrated. */ HANDLE readyEvent; /* System event used to trigger the requesting @@ -61,7 +62,6 @@ typedef struct TimeInfo { LARGE_INTEGER nominalFreq; /* Nominal frequency of the system performance * counter, that is, the value returned from * QueryPerformanceFrequency. */ - /* * The following values are used for calculating virtual time. Virtual * time is always equal to: @@ -74,6 +74,8 @@ typedef struct TimeInfo { ULARGE_INTEGER fileTimeLastCall; LARGE_INTEGER perfCounterLastCall; LARGE_INTEGER curCounterFreq; + LARGE_INTEGER posixEpoch; /* Posix epoch expressed as 100-ns ticks since + * the windows epoch. */ /* * Data used in developing the estimate of performance counter frequency @@ -90,6 +92,7 @@ static TimeInfo timeInfo = { { NULL, 0, 0, NULL, NULL, 0 }, 0, 0, + 1, (HANDLE) NULL, (HANDLE) NULL, (HANDLE) NULL, @@ -98,11 +101,13 @@ static TimeInfo timeInfo = { (ULARGE_INTEGER) (DWORDLONG) 0, (LARGE_INTEGER) (Tcl_WideInt) 0, (LARGE_INTEGER) (Tcl_WideInt) 0, + (LARGE_INTEGER) (Tcl_WideInt) 0, #else - 0, - 0, - 0, - 0, + {0, 0}, + {0, 0}, + {0, 0}, + {0, 0}, + {0, 0}, #endif { 0 }, { 0 }, @@ -435,12 +440,20 @@ NativeScaleTime( *---------------------------------------------------------------------- */ +static inline Tcl_WideInt +NativeCalc100NsTicks( + ULONGLONG fileTimeLastCall, + LONGLONG perfCounterLastCall, + LONGLONG curCounterFreq, + LONGLONG curCounter +) { + return fileTimeLastCall + + ((curCounter - perfCounterLastCall) * 10000000 / curCounterFreq); +} + static Tcl_WideInt NativeGetMicroseconds(void) { - static LARGE_INTEGER posixEpoch; - /* Posix epoch expressed as 100-ns ticks since - * the windows epoch. */ /* * Initialize static storage on the first trip through. * @@ -452,8 +465,8 @@ NativeGetMicroseconds(void) TclpInitLock(); if (!timeInfo.initialized) { - posixEpoch.LowPart = 0xD53E8000; - posixEpoch.HighPart = 0x019DB1DE; + timeInfo.posixEpoch.LowPart = 0xD53E8000; + timeInfo.posixEpoch.HighPart = 0x019DB1DE; timeInfo.perfCounterAvailable = QueryPerformanceFrequency(&timeInfo.nominalFreq); @@ -559,16 +572,12 @@ NativeGetMicroseconds(void) * time. */ - ULARGE_INTEGER fileTimeLastCall; - LARGE_INTEGER perfCounterLastCall, curCounterFreq; + ULONGLONG fileTimeLastCall; + LONGLONG perfCounterLastCall, curCounterFreq; /* Copy with current data of calibration cycle */ LARGE_INTEGER curCounter; /* Current performance counter. */ - Tcl_WideInt curFileTime;/* Current estimated time, expressed as 100-ns - * ticks since the Windows epoch. */ - Tcl_WideInt usecSincePosixEpoch; - /* Current microseconds since Posix epoch. */ QueryPerformanceCounter(&curCounter); @@ -577,19 +586,18 @@ NativeGetMicroseconds(void) */ EnterCriticalSection(&timeInfo.cs); - fileTimeLastCall.QuadPart = timeInfo.fileTimeLastCall.QuadPart; - perfCounterLastCall.QuadPart = timeInfo.perfCounterLastCall.QuadPart; - curCounterFreq.QuadPart = timeInfo.curCounterFreq.QuadPart; + fileTimeLastCall = timeInfo.fileTimeLastCall.QuadPart; + perfCounterLastCall = timeInfo.perfCounterLastCall.QuadPart; + curCounterFreq = timeInfo.curCounterFreq.QuadPart; LeaveCriticalSection(&timeInfo.cs); /* * If calibration cycle occurred after we get curCounter */ - if (curCounter.QuadPart <= perfCounterLastCall.QuadPart) { - usecSincePosixEpoch = - (fileTimeLastCall.QuadPart - posixEpoch.QuadPart) / 10; - return usecSincePosixEpoch; + if (curCounter.QuadPart <= perfCounterLastCall) { + /* Calibrated file-time is saved from posix in 100-ns ticks */ + return fileTimeLastCall / 10; } /* @@ -602,15 +610,12 @@ NativeGetMicroseconds(void) * loop should recover. */ - if (curCounter.QuadPart - perfCounterLastCall.QuadPart < - 11 * curCounterFreq.QuadPart / 10 + if (curCounter.QuadPart - perfCounterLastCall < + 11 * curCounterFreq * timeInfo.calibrationInterv / 10 ) { - curFileTime = fileTimeLastCall.QuadPart + - ((curCounter.QuadPart - perfCounterLastCall.QuadPart) - * 10000000 / curCounterFreq.QuadPart); - - usecSincePosixEpoch = (curFileTime - posixEpoch.QuadPart) / 10; - return usecSincePosixEpoch; + /* Calibrated file-time is saved from posix in 100-ns ticks */ + return NativeCalc100NsTicks(fileTimeLastCall, + perfCounterLastCall, curCounterFreq, curCounter.QuadPart) / 10; } } @@ -681,6 +686,8 @@ NativeGetTime( *---------------------------------------------------------------------- */ +void TclWinResetTimerResolution(void); + static void StopCalibration( ClientData unused) /* Client data is unused */ @@ -969,6 +976,8 @@ CalibrationThread( QueryPerformanceFrequency(&timeInfo.curCounterFreq); timeInfo.fileTimeLastCall.LowPart = curFileTime.dwLowDateTime; timeInfo.fileTimeLastCall.HighPart = curFileTime.dwHighDateTime; + /* Calibrated file-time will be saved from posix in 100-ns ticks */ + timeInfo.fileTimeLastCall.QuadPart -= timeInfo.posixEpoch.QuadPart; ResetCounterSamples(timeInfo.fileTimeLastCall.QuadPart, timeInfo.perfCounterLastCall.QuadPart, @@ -1028,6 +1037,7 @@ UpdateTimeEachSecond(void) /* Current value returned from * QueryPerformanceCounter. */ FILETIME curSysTime; /* Current system time. */ + static LARGE_INTEGER lastFileTime; /* File time of the previous calibration */ LARGE_INTEGER curFileTime; /* File time at the time this callback was * scheduled. */ Tcl_WideInt estFreq; /* Estimated perf counter frequency. */ @@ -1039,15 +1049,24 @@ UpdateTimeEachSecond(void) * step over 1 second. */ /* - * Sample performance counter and system time. + * Sample performance counter and system time (from posix epoch). */ - QueryPerformanceCounter(&curPerfCounter); GetSystemTimeAsFileTime(&curSysTime); curFileTime.LowPart = curSysTime.dwLowDateTime; curFileTime.HighPart = curSysTime.dwHighDateTime; - - EnterCriticalSection(&timeInfo.cs); + curFileTime.QuadPart -= timeInfo.posixEpoch.QuadPart; + /* If calibration still not needed (check for possible time switch) */ + if ( curFileTime.QuadPart > lastFileTime.QuadPart + && curFileTime.QuadPart < lastFileTime.QuadPart + + (timeInfo.calibrationInterv * 10000000) + ) { + /* again in next one second */ + return; + } + QueryPerformanceCounter(&curPerfCounter); + + lastFileTime.QuadPart = curFileTime.QuadPart; /* * We devide by timeInfo.curCounterFreq.QuadPart in several places. That @@ -1059,7 +1078,6 @@ UpdateTimeEachSecond(void) */ if (timeInfo.curCounterFreq.QuadPart == 0){ - LeaveCriticalSection(&timeInfo.cs); timeInfo.perfCounterAvailable = 0; return; } @@ -1098,12 +1116,9 @@ UpdateTimeEachSecond(void) * is estFreq * 20000000 / (vt1 - vt0) */ - vt0 = 10000000 * (curPerfCounter.QuadPart - - timeInfo.perfCounterLastCall.QuadPart) - / timeInfo.curCounterFreq.QuadPart - + timeInfo.fileTimeLastCall.QuadPart; - vt1 = 20000000 + curFileTime.QuadPart; - + vt0 = NativeCalc100NsTicks(timeInfo.fileTimeLastCall.QuadPart, + timeInfo.perfCounterLastCall.QuadPart, timeInfo.curCounterFreq.QuadPart, + curPerfCounter.QuadPart); /* * If we've gotten more than a second away from system time, then drifting * the clock is going to be pretty hopeless. Just let it jump. Otherwise, @@ -1112,21 +1127,75 @@ UpdateTimeEachSecond(void) tdiff = vt0 - curFileTime.QuadPart; if (tdiff > 10000000 || tdiff < -10000000) { - timeInfo.fileTimeLastCall.QuadPart = curFileTime.QuadPart; - timeInfo.curCounterFreq.QuadPart = estFreq; + /* jump to current system time, use curent estimated frequency */ + vt0 = curFileTime.QuadPart; } else { - driftFreq = estFreq * 20000000 / (vt1 - vt0); + /* calculate new frequency and estimate drift to the next second */ + vt1 = 20000000 + curFileTime.QuadPart; + driftFreq = (estFreq * 20000000 / (vt1 - vt0)); + /* + * Avoid too large drifts (only half of the current difference), + * that allows also be more accurate (aspire to the smallest tdiff), + * so then we can prolong calibration interval by tdiff < 100000 + */ + driftFreq = timeInfo.curCounterFreq.QuadPart + + (driftFreq - timeInfo.curCounterFreq.QuadPart) / 2; - if (driftFreq > 1003*estFreq/1000) { - driftFreq = 1003*estFreq/1000; - } else if (driftFreq < 997*estFreq/1000) { - driftFreq = 997*estFreq/1000; + /* + * Average between estimated, 2 current and 5 drifted frequencies, + * (do the soft drifting as possible) + */ + estFreq = (estFreq + 2 * timeInfo.curCounterFreq.QuadPart + 5 * driftFreq) / 8; + } + + /* Avoid too large discrepancy from nominal frequency */ + if (estFreq > 1003*timeInfo.nominalFreq.QuadPart/1000) { + estFreq = 1003*timeInfo.nominalFreq.QuadPart/1000; + vt0 = curFileTime.QuadPart; + } else if (estFreq < 997*timeInfo.nominalFreq.QuadPart/1000) { + estFreq = 997*timeInfo.nominalFreq.QuadPart/1000; + vt0 = curFileTime.QuadPart; + } else if (vt0 != curFileTime.QuadPart) { + /* + * Be sure the clock ticks never backwards (avoid it by negative drifting) + * just compare native time (in 100-ns) before and hereafter using + * new calibrated values) and do a small adjustment (short time freeze) + */ + LARGE_INTEGER newPerfCounter; + Tcl_WideInt nt0, nt1; + + QueryPerformanceCounter(&newPerfCounter); + nt0 = NativeCalc100NsTicks(timeInfo.fileTimeLastCall.QuadPart, + timeInfo.perfCounterLastCall.QuadPart, timeInfo.curCounterFreq.QuadPart, + newPerfCounter.QuadPart); + nt1 = NativeCalc100NsTicks(vt0, + curPerfCounter.QuadPart, estFreq, + newPerfCounter.QuadPart); + if (nt0 > nt1) { /* drifted backwards, try to compensate with new base */ + /* first adjust with a micro jump (short frozen time is acceptable) */ + vt0 += nt0 - nt1; + /* if drift unavoidable (e. g. we had a time switch), then reset it */ + vt1 = vt0 - curFileTime.QuadPart; + if (vt1 > 10000000 || vt1 < -10000000) { + /* larger jump resp. shift relative new file-time */ + vt0 = curFileTime.QuadPart; + } } + } + + /* In lock commit new values to timeInfo (hold lock as short as possible) */ + EnterCriticalSection(&timeInfo.cs); - timeInfo.fileTimeLastCall.QuadPart = vt0; - timeInfo.curCounterFreq.QuadPart = driftFreq; + /* grow calibration interval up to 10 seconds (if still precise enough) */ + if (tdiff < -100000 || tdiff > 100000) { + /* too long drift - reset calibration interval to 1000 second */ + timeInfo.calibrationInterv = 1; + } else if (timeInfo.calibrationInterv < 10) { + timeInfo.calibrationInterv++; } + timeInfo.fileTimeLastCall.QuadPart = vt0; + timeInfo.curCounterFreq.QuadPart = estFreq; timeInfo.perfCounterLastCall.QuadPart = curPerfCounter.QuadPart; LeaveCriticalSection(&timeInfo.cs); |