From 81ddd6526f239549a107a5b790e50ebc8428cea2 Mon Sep 17 00:00:00 2001 From: "brendan%mozilla.org" Date: Mon, 18 Feb 2002 00:10:55 +0000 Subject: [PATCH] Digital filter for adaptive timeout adjustment, needs trunk baking, makes things better so far (117061, r=pavlov, sr=jst). --- xpcom/threads/TimerThread.cpp | 158 ++++++++++++++++++++++------------ xpcom/threads/TimerThread.h | 16 ++++ xpcom/threads/nsITimer.h | 52 ++++++----- xpcom/threads/nsTimerImpl.cpp | 76 +++++++++------- xpcom/threads/nsTimerImpl.h | 10 +-- 5 files changed, 200 insertions(+), 112 deletions(-) diff --git a/xpcom/threads/TimerThread.cpp b/xpcom/threads/TimerThread.cpp index 087f6220ac7..a87395b18d6 100644 --- a/xpcom/threads/TimerThread.cpp +++ b/xpcom/threads/TimerThread.cpp @@ -43,19 +43,14 @@ NS_IMPL_THREADSAFE_ISUPPORTS1(TimerThread, nsIRunnable) -#undef ACCEPT_WRONG_TIMES - -#ifdef ACCEPT_WRONG_TIMES -// allow the thread to wake up and process timers +/- 3ms of when they -// are really supposed to fire. -static const PRIntervalTime kThreeMS = PR_MillisecondsToInterval(3); -#endif - TimerThread::TimerThread() : - mCondVar(nsnull), mLock(nsnull), + mCondVar(nsnull), mProcessing(PR_FALSE), - mWaiting(PR_FALSE) + mWaiting(PR_FALSE), + mDelayLineCounter(0), + mMinTimerPeriod(0), + mTimeoutAdjustment(0) { NS_INIT_REFCNT(); } @@ -119,79 +114,136 @@ nsresult TimerThread::Shutdown() RemoveTimerInternal(timer); } } - + mThread->Join(); // wait for the thread to die return NS_OK; } +// Keep track of how early (positive slack) or late (negative slack) timers +// are running, and use the filtered slack number to adaptively estimate how +// early timers should fire to be "on time". +void TimerThread::UpdateFilter(PRUint32 aDelay, PRIntervalTime aTimeout, + PRIntervalTime aNow) +{ + PRInt32 slack = (PRInt32) (aTimeout - aNow); + double smoothSlack = 0; + PRUint32 i, filterLength; + static PRIntervalTime kFilterFeedbackMaxTicks = + PR_MillisecondsToInterval(FILTER_FEEDBACK_MAX); + + if (slack > 0) { + if (slack > (PRInt32)kFilterFeedbackMaxTicks) + slack = kFilterFeedbackMaxTicks; + } else { + if (slack < -(PRInt32)kFilterFeedbackMaxTicks) + slack = -(PRInt32)kFilterFeedbackMaxTicks; + } + mDelayLine[mDelayLineCounter & DELAY_LINE_LENGTH_MASK] = slack; + if (++mDelayLineCounter < DELAY_LINE_LENGTH) { + // Startup mode: accumulate a full delay line before filtering. + PR_ASSERT(mTimeoutAdjustment == 0); + filterLength = 0; + } else { + // Past startup: compute number of filter taps based on mMinTimerPeriod. + if (mMinTimerPeriod == 0) { + mMinTimerPeriod = (aDelay != 0) ? aDelay : 1; + } else if (aDelay != 0 && aDelay < mMinTimerPeriod) { + mMinTimerPeriod = aDelay; + } + + filterLength = (PRUint32) (FILTER_DURATION / mMinTimerPeriod); + if (filterLength > DELAY_LINE_LENGTH) + filterLength = DELAY_LINE_LENGTH; + else if (filterLength < 4) + filterLength = 4; + + for (i = 1; i <= filterLength; i++) + smoothSlack += mDelayLine[(mDelayLineCounter-i) & DELAY_LINE_LENGTH_MASK]; + smoothSlack /= filterLength; + + // XXXbe do we need amplification? hacking a fudge factor, need testing... + mTimeoutAdjustment = (PRInt32) (smoothSlack * 1.5); + } + +#ifdef DEBUG_TIMERS + if (PR_LOG_TEST(gTimerLog, PR_LOG_DEBUG)) { + PR_LOG(gTimerLog, PR_LOG_DEBUG, + ("UpdateFilter: smoothSlack = %g, filterLength = %u\n", + smoothSlack, filterLength)); + } +#endif +} + /* void Run(); */ NS_IMETHODIMP TimerThread::Run() { + nsAutoLock lock(mLock); mProcessing = PR_TRUE; while (mProcessing) { - nsTimerImpl *theTimer = nsnull; + PRIntervalTime now = PR_IntervalNow(); + nsTimerImpl *timer = nsnull; if (mTimers.Count() > 0) { - nsAutoLock lock(mLock); - nsTimerImpl *timer = NS_STATIC_CAST(nsTimerImpl*, mTimers[0]); + timer = NS_STATIC_CAST(nsTimerImpl*, mTimers[0]); - PRIntervalTime itIsNow = PR_IntervalNow(); -#ifdef ACCEPT_WRONG_TIMES - if (itIsNow + kThreeMS > timer->mTimeout - kThreeMS) -#else - if (itIsNow >= timer->mTimeout) -#endif - { + if (now >= timer->mTimeout + mTimeoutAdjustment) { + next: RemoveTimerInternal(timer); - theTimer = timer; - NS_ADDREF(theTimer); - } - } + NS_ADDREF(timer); + + // We release mLock around the Fire call, of course, to avoid deadlock. + lock.unlock(); - if (theTimer) { #ifdef DEBUG_TIMERS - if (PR_LOG_TEST(gTimerLog, PR_LOG_DEBUG)) { - PRIntervalTime now = PR_IntervalNow(); - PR_LOG(gTimerLog, PR_LOG_DEBUG, ("Timer thread woke up %dms from when it was supposed to\n", - ((now > theTimer->mTimeout) ? PR_IntervalToMilliseconds(now - theTimer->mTimeout) : - -(PRInt32)PR_IntervalToMilliseconds(theTimer->mTimeout - now)))); - } + if (PR_LOG_TEST(gTimerLog, PR_LOG_DEBUG)) { + PR_LOG(gTimerLog, PR_LOG_DEBUG, + ("Timer thread woke up %dms from when it was supposed to\n", + (now >= timer->mTimeout) + ? PR_IntervalToMilliseconds(now - timer->mTimeout) + : -(PRInt32)PR_IntervalToMilliseconds(timer->mTimeout - now)) + ); + } #endif - // We are going to let the call to Fire here handle the release of the timer so that - // we don't end up releasing the timer on the TimerThread - theTimer->Fire(); + // We are going to let the call to Fire here handle the release of the + // timer so that we don't end up releasing the timer on the TimerThread + // instead of on the thread it targets. + timer->Fire(); + timer = nsnull; - theTimer = nsnull; + lock.lock(); + if (!mProcessing) + break; + + // Update now, as Fire plus the locking may have taken a tick or two, + // and we may goto next below. + now = PR_IntervalNow(); + } } - nsAutoLock lock(mLock); - PRIntervalTime waitFor = PR_INTERVAL_NO_TIMEOUT; if (mTimers.Count() > 0) { - PRIntervalTime now = PR_IntervalNow(); - PRIntervalTime timeout = NS_STATIC_CAST(nsTimerImpl *, mTimers[0])->mTimeout; + timer = NS_STATIC_CAST(nsTimerImpl *, mTimers[0]); -#ifdef ACCEPT_WRONG_TIMES - if (timeout > now + kThreeMS) -#else - if (timeout > now) -#endif - waitFor = timeout - now; - else - waitFor = PR_INTERVAL_NO_WAIT; + PRIntervalTime timeout = timer->mTimeout + mTimeoutAdjustment; + + // Don't wait at all (even for PR_INTERVAL_NO_WAIT) if the next timer is + // due now or overdue. + if (now >= timeout) + goto next; + waitFor = timeout - now; } #ifdef DEBUG_TIMERS if (PR_LOG_TEST(gTimerLog, PR_LOG_DEBUG)) { if (waitFor == PR_INTERVAL_NO_TIMEOUT) - PR_LOG(gTimerLog, PR_LOG_DEBUG, ("waiting for PR_INTERVAL_NO_TIMEOUT\n")); - else if (waitFor == PR_INTERVAL_NO_WAIT) - PR_LOG(gTimerLog, PR_LOG_DEBUG, ("waiting for PR_INTERVAL_NO_WAIT\n")); + PR_LOG(gTimerLog, PR_LOG_DEBUG, + ("waiting for PR_INTERVAL_NO_TIMEOUT\n")); else - PR_LOG(gTimerLog, PR_LOG_DEBUG, ("waiting for %u\n", PR_IntervalToMilliseconds(waitFor))); + PR_LOG(gTimerLog, PR_LOG_DEBUG, + ("waiting for %u\n", PR_IntervalToMilliseconds(waitFor))); } #endif @@ -243,7 +295,7 @@ PRInt32 TimerThread::AddTimerInternal(nsTimerImpl *aTimer) PRInt32 i = 0; for (; i < count; i++) { nsTimerImpl *timer = NS_STATIC_CAST(nsTimerImpl *, mTimers[i]); - + if (aTimer->mTimeout < timer->mTimeout) { break; } diff --git a/xpcom/threads/TimerThread.h b/xpcom/threads/TimerThread.h index a759264ec6f..52b22d64528 100644 --- a/xpcom/threads/TimerThread.h +++ b/xpcom/threads/TimerThread.h @@ -46,6 +46,7 @@ #include "nsVoidArray.h" #include "prcvar.h" +#include "prinrval.h" #include "prlock.h" class TimerThread : public nsIRunnable @@ -64,6 +65,12 @@ public: nsresult TimerDelayChanged(nsTimerImpl *aTimer); nsresult RemoveTimer(nsTimerImpl *aTimer); +#define FILTER_DURATION 1e3 /* one second */ +#define FILTER_FEEDBACK_MAX 100 /* 1/10th of a second */ + + void UpdateFilter(PRUint32 aDelay, PRIntervalTime aTimeout, + PRIntervalTime aNow); + // For use by nsTimerImpl::Fire() nsCOMPtr mEventQueueService; @@ -82,6 +89,15 @@ private: PRPackedBool mWaiting; nsVoidArray mTimers; + +#define DELAY_LINE_LENGTH_LOG2 5 +#define DELAY_LINE_LENGTH_MASK PR_BITMASK(DELAY_LINE_LENGTH_LOG2) +#define DELAY_LINE_LENGTH PR_BIT(DELAY_LINE_LENGTH_LOG2) + + PRInt32 mDelayLine[DELAY_LINE_LENGTH]; + PRUint32 mDelayLineCounter; + PRUint32 mMinTimerPeriod; // milliseconds + PRInt32 mTimeoutAdjustment; }; #endif /* TimerThread_h___ */ diff --git a/xpcom/threads/nsITimer.h b/xpcom/threads/nsITimer.h index ee7d08e3da6..d6b380ccb16 100644 --- a/xpcom/threads/nsITimer.h +++ b/xpcom/threads/nsITimer.h @@ -49,16 +49,18 @@ class nsITimer; class nsITimerCallback; -// Implementations of nsITimer should be written such that there are no limitations -// on what can be called by the TimerCallbackFunc. On platforms like the Macintosh this -// means that callback functions must be called from the main event loop NOT from -// an interrupt. +/** + * Implementations of nsITimer should be written such that there are no + * limitations on what can be called by the TimerCallbackFunc. On platforms + * such as the Macintosh this means that callback functions must be called + * from the main event loop, NOT from an interrupt. + */ -/// Signature of timer callback function +// Signature of timer callback function typedef void (*nsTimerCallbackFunc) (nsITimer *aTimer, void *aClosure); -/// Interface IID for nsITimer +// Interface IID for nsITimer #define NS_ITIMER_IID \ { 0x497eed20, 0xb740, 0x11d1, \ { 0x9b, 0xc3, 0x00, 0x60, 0x08, 0x8c, 0xa6, 0xb3 } } @@ -72,22 +74,32 @@ typedef void #define NS_PRIORITY_LOWEST 0 // --- Timer types --- -#define NS_TYPE_ONE_SHOT 0 // Timer which fires once only +enum nsTimerType { + /** + * Type of a timer that fires once only. + */ + NS_TYPE_ONE_SHOT = 0, -#define NS_TYPE_REPEATING_SLACK 1 // After firing, timer is stopped and not - // restarted until notifcation routine completes. - // Specified timer period will be at least time between - // when processing for last firing notifcation completes - // and when the next firing occurs. This is the preferable - // repeating type for most situations. + /** + * After firing, a NS_REPEATING_SLACK timer is stopped and not restarted + * until its callback completes. Specified timer period will be at least + * the time between when processing for last firing the callback completes + * and when the next firing occurs. + * + * This is the preferable repeating type for most situations. + */ + NS_TYPE_REPEATING_SLACK = 1, -#define NS_TYPE_REPEATING_PRECISE 2 // Timer which aims to have constant time between firings. - // The processing time for each timer notification should - // not influence timer period. However, if the processing - // for the last timer firing could not be completed until - // just before the next firing occurs, then you could have - // two timer notification routines being executed in quick - // sucession. + /** + * An NS_REPEATING_PRECISE repeating timer aims to have constant period + * between firings. The processing time for each timer callback should not + * influence the timer period. However, if the processing for the last + * timer firing could not be completed until just before the next firing + * occurs, then you could have two timer notification routines being + * executed in quick succession. + */ + NS_TYPE_REPEATING_PRECISE = 2 +}; #define REPEATING_TIMERS 1 diff --git a/xpcom/threads/nsTimerImpl.cpp b/xpcom/threads/nsTimerImpl.cpp index b1d8fb7398a..2b1b28b2bf4 100644 --- a/xpcom/threads/nsTimerImpl.cpp +++ b/xpcom/threads/nsTimerImpl.cpp @@ -76,12 +76,16 @@ NS_IMPL_THREADSAFE_ISUPPORTS1(nsTimerImpl, nsITimer) PR_STATIC_CALLBACK(PRStatus) InitThread(void) { gThread = new TimerThread(); - if (!gThread) return PR_FAILURE; + if (!gThread) + return PR_FAILURE; - gThread->AddRef(); + NS_ADDREF(gThread); nsresult rv = gThread->Init(); - if (NS_FAILED(rv)) return PR_FAILURE; + if (NS_FAILED(rv)) { + NS_RELEASE(gThread); + return PR_FAILURE; + } return PR_SUCCESS; } @@ -90,7 +94,8 @@ nsTimerImpl::nsTimerImpl() : mClosure(nsnull), mCallbackType(CALLBACK_TYPE_UNKNOWN), mFiring(PR_FALSE), - mCancelled(PR_FALSE) + mCancelled(PR_FALSE), + mTimeout(0) { NS_INIT_REFCNT(); nsIThread::GetCurrent(getter_AddRefs(mCallingThread)); @@ -132,8 +137,7 @@ void nsTimerImpl::Shutdown() return; gThread->Shutdown(); - gThread->Release(); - gThread = nsnull; + NS_RELEASE(gThread); } @@ -143,7 +147,8 @@ NS_IMETHODIMP nsTimerImpl::Init(nsTimerCallbackFunc aFunc, PRUint32 aPriority, PRUint32 aType) { - SetDelayInternal(aDelay); + if (!gThread) + return NS_ERROR_FAILURE; mCallback.c = aFunc; mCallbackType = CALLBACK_TYPE_FUNC; @@ -153,8 +158,7 @@ NS_IMETHODIMP nsTimerImpl::Init(nsTimerCallbackFunc aFunc, mPriority = (PRUint8)aPriority; mType = (PRUint8)aType; - if (!gThread) - return NS_ERROR_FAILURE; + SetDelayInternal(aDelay); gThread->AddTimer(this); @@ -166,7 +170,8 @@ NS_IMETHODIMP nsTimerImpl::Init(nsITimerCallback *aCallback, PRUint32 aPriority, PRUint32 aType) { - SetDelayInternal(aDelay); + if (!gThread) + return NS_ERROR_FAILURE; mCallback.i = aCallback; NS_ADDREF(mCallback.i); @@ -175,8 +180,7 @@ NS_IMETHODIMP nsTimerImpl::Init(nsITimerCallback *aCallback, mPriority = (PRUint8)aPriority; mType = (PRUint8)aType; - if (!gThread) - return NS_ERROR_FAILURE; + SetDelayInternal(aDelay); gThread->AddTimer(this); @@ -218,27 +222,34 @@ void nsTimerImpl::Process() if (mCancelled) return; + PRIntervalTime now = PR_IntervalNow(); #ifdef DEBUG_TIMERS - PRIntervalTime now; if (PR_LOG_TEST(gTimerLog, PR_LOG_DEBUG)) { - now = PR_IntervalNow(); PRIntervalTime a = now - mStart; // actual delay in intervals PRUint32 b = PR_MillisecondsToInterval(mDelay); // expected delay in intervals - PRUint32 d = PR_IntervalToMilliseconds((a > b) ? a - b : 0); // delta in ms + PRUint32 d = PR_IntervalToMilliseconds((a > b) ? a - b : b - a); // delta in ms sDeltaSum += d; sDeltaSumSquared += double(d) * double(d); sNum++; - PR_LOG(gTimerLog, PR_LOG_DEBUG, ("[this=%p] expected delay time %dms\n", this, mDelay)); - PR_LOG(gTimerLog, PR_LOG_DEBUG, ("[this=%p] actual delay time %dms\n", this, PR_IntervalToMilliseconds(a))); - PR_LOG(gTimerLog, PR_LOG_DEBUG, ("[this=%p] -------\n", this)); - PR_LOG(gTimerLog, PR_LOG_DEBUG, ("[this=%p] delta %dms\n", this, d)); + PR_LOG(gTimerLog, PR_LOG_DEBUG, ("[this=%p] expected delay time %4dms\n", this, mDelay)); + PR_LOG(gTimerLog, PR_LOG_DEBUG, ("[this=%p] actual delay time %4dms\n", this, PR_IntervalToMilliseconds(a))); + PR_LOG(gTimerLog, PR_LOG_DEBUG, ("[this=%p] (mType is %d) -------\n", this, mType)); + PR_LOG(gTimerLog, PR_LOG_DEBUG, ("[this=%p] delta %4dms\n", this, (a > b) ? (PRInt32)d : -(PRInt32)d)); mStart = mStart2; mStart2 = 0; } #endif + PRIntervalTime timeout = mTimeout; + if (mType == NS_TYPE_REPEATING_PRECISE) { + // Precise repeating timers advance mTimeout by mDelay without fail before + // calling Process(). + timeout -= mDelay; + } + gThread->UpdateFilter(mDelay, timeout, now); + mFiring = PR_TRUE; if (mCallback.c) { @@ -253,8 +264,9 @@ void nsTimerImpl::Process() #ifdef DEBUG_TIMERS if (PR_LOG_TEST(gTimerLog, PR_LOG_DEBUG)) { - PR_LOG(gTimerLog, PR_LOG_DEBUG, ("[this=%p] Took %dms to fire process timer callback\n", this, - PR_IntervalToMilliseconds(PR_IntervalNow() - now))); + PR_LOG(gTimerLog, PR_LOG_DEBUG, + ("[this=%p] Took %dms to fire process timer callback\n", + this, PR_IntervalToMilliseconds(PR_IntervalNow() - now))); } #endif @@ -279,8 +291,10 @@ void* handleMyEvent(MyEventType* event) { #ifdef DEBUG_TIMERS if (PR_LOG_TEST(gTimerLog, PR_LOG_DEBUG)) { - PR_LOG(gTimerLog, PR_LOG_DEBUG, ("[this=%p] time between Fire() and Process(): %dms\n", - event->e.owner, PR_IntervalToMilliseconds(PR_IntervalNow() - event->mInit))); + PRIntervalTime now = PR_IntervalNow(); + PR_LOG(gTimerLog, PR_LOG_DEBUG, + ("[this=%p] time between Fire() and Process(): %dms\n", + event->e.owner, PR_IntervalToMilliseconds(now - event->mInit))); } #endif NS_STATIC_CAST(nsTimerImpl*, event->e.owner)->Process(); @@ -306,11 +320,11 @@ void nsTimerImpl::Fire() // initialize PL_InitEvent((PLEvent*)event, this, - (PLHandleEventProc)handleMyEvent, - (PLDestroyEventProc)destroyMyEvent); + (PLHandleEventProc)handleMyEvent, + (PLDestroyEventProc)destroyMyEvent); - // Since TimerThread addref'd 'this' for us, we don't need to addref here. We will release - // in destroyMyEvent. + // Since TimerThread addref'd 'this' for us, we don't need to addref here. + // We will release in destroyMyEvent. #ifdef DEBUG_TIMERS if (PR_LOG_TEST(gTimerLog, PR_LOG_DEBUG)) { @@ -318,8 +332,8 @@ void nsTimerImpl::Fire() } #endif - // If this is a repeating precise timer, we need to calulate the time for the next timer to fire - // prior to making the callback. + // If this is a repeating precise timer, we need to calculate the time for + // the next timer to fire before we make the callback. if (mType == NS_TYPE_REPEATING_PRECISE) { SetDelayInternal(mDelay); if (gThread) @@ -341,8 +355,10 @@ void nsTimerImpl::SetDelayInternal(PRUint32 aDelay) mDelay = aDelay; PRIntervalTime now = PR_IntervalNow(); + if (mTimeout == 0 || mType == NS_TYPE_REPEATING_SLACK) + mTimeout = now; - mTimeout = now + PR_MillisecondsToInterval(mDelay); + mTimeout += PR_MillisecondsToInterval(aDelay); if (mTimeout < now) { // we overflowed mTimeout = PRIntervalTime(-1); diff --git a/xpcom/threads/nsTimerImpl.h b/xpcom/threads/nsTimerImpl.h index 5fbc240a483..6d24d3b9998 100644 --- a/xpcom/threads/nsTimerImpl.h +++ b/xpcom/threads/nsTimerImpl.h @@ -50,16 +50,8 @@ #include "prlog.h" #if defined(PR_LOGGING) -// stupid NS_DECL_LOG crap -#ifdef PRLogModuleInfo -#undef PRLogModuleInfo -#endif -#ifdef PR_NewLogModule -#undef PR_NewLogModule -#endif - static PRLogModuleInfo *gTimerLog = PR_NewLogModule("nsTimerImpl"); -#define DEBUG_TIMERS +#define DEBUG_TIMERS 1 #else #undef DEBUG_TIMERS #endif