From e320b2da343617747f5550dfd9d44e91c79dca25 Mon Sep 17 00:00:00 2001 From: Irving Reid Date: Thu, 26 Apr 2012 19:21:37 -0400 Subject: [PATCH] Bug 744527 - Fix idle poll interval, add tracing to idle service. r=bbondy --- widget/xpwidgets/nsIdleService.cpp | 89 ++++++++++++++++++++++++------ 1 file changed, 73 insertions(+), 16 deletions(-) diff --git a/widget/xpwidgets/nsIdleService.cpp b/widget/xpwidgets/nsIdleService.cpp index fd39230251e5..64ff52ab2982 100644 --- a/widget/xpwidgets/nsIdleService.cpp +++ b/widget/xpwidgets/nsIdleService.cpp @@ -47,6 +47,7 @@ #include "nsDebug.h" #include "nsCOMArray.h" #include "prinrval.h" +#include "prlog.h" #include "mozilla/Services.h" #include "mozilla/Preferences.h" #include "mozilla/Telemetry.h" @@ -67,6 +68,10 @@ using namespace mozilla; // Number of seconds in a day. #define SECONDS_PER_DAY 86400 +#ifdef PR_LOGGING +static PRLogModuleInfo *sLog = NULL; +#endif + // Use this to find previously added observers in our array: class IdleListenerComparator { @@ -274,8 +279,12 @@ nsIdleServiceDaily::DailyCallback(nsITimer* aTimer, void* aClosure) nsIdleService::nsIdleService() : mCurrentlySetToTimeoutAtInPR(0), mAnyObserverIdle(false), mDeltaToNextIdleSwitchInS(PR_UINT32_MAX), - mLastUserInteractionInPR(0) + mLastUserInteractionInPR(PR_Now()) { +#ifdef PR_LOGGING + if (sLog == NULL) + sLog = PR_NewLogModule("idleService"); +#endif mDailyIdle = new nsIdleServiceDaily(this); mDailyIdle->Init(); } @@ -290,6 +299,10 @@ nsIdleService::~nsIdleService() NS_IMETHODIMP nsIdleService::AddIdleObserver(nsIObserver* aObserver, PRUint32 aIdleTimeInS) { + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: Register idle observer %x for %d seconds", + aObserver, aIdleTimeInS)); + NS_ENSURE_ARG_POINTER(aObserver); // We don't accept idle time at 0, and we can't handle idle time that are too // high either - no more than ~136 years. @@ -310,10 +323,13 @@ nsIdleService::AddIdleObserver(nsIObserver* aObserver, PRUint32 aIdleTimeInS) } // Check if the newly added observer has a smaller wait time than what we - // are wating for now. + // are waiting for now. if (mDeltaToNextIdleSwitchInS > aIdleTimeInS) { // If it is, then this is the next to move to idle (at this point we // don't care if it should have switched already). + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: Register: adjusting next switch from %d to %d seconds", + mDeltaToNextIdleSwitchInS, aIdleTimeInS)); mDeltaToNextIdleSwitchInS = aIdleTimeInS; } @@ -336,21 +352,33 @@ nsIdleService::RemoveIdleObserver(nsIObserver* aObserver, PRUint32 aTimeInS) // little while. IdleListenerComparator c; if (mArrayListeners.RemoveElement(listener, c)) { + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: Remove idle observer %x (%d seconds)", + aObserver, aTimeInS)); return NS_OK; } // If we get here, we haven't removed anything: + PR_LOG(sLog, PR_LOG_WARNING, + ("idleService: Failed to remove idle observer %x (%d seconds)", + aObserver, aTimeInS)); return NS_ERROR_FAILURE; } void nsIdleService::ResetIdleTimeOut(PRUint32 idleDeltaInMS) { + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: Reset idle timeout (last interaction %u msec)", + idleDeltaInMS)); + // Store the time mLastUserInteractionInPR = PR_Now() - (idleDeltaInMS * PR_USEC_PER_MSEC); // If no one is idle, then we are done, any existing timers can keep running. if (!mAnyObserverIdle) { + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: Reset idle timeout: no idle observers")); return; } @@ -399,6 +427,9 @@ nsIdleService::ResetIdleTimeOut(PRUint32 idleDeltaInMS) // Send the "non-idle" events. while (numberOfPendingNotifications--) { + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: Reset idle timeout: tell observer %x user is back", + notifyList[numberOfPendingNotifications])); notifyList[numberOfPendingNotifications]->Observe(this, OBSERVER_TOPIC_BACK, timeStr.get()); @@ -419,22 +450,18 @@ nsIdleService::GetIdleTime(PRUint32* idleTime) bool polledIdleTimeIsValid = PollIdleTime(&polledIdleTimeMS); - // If we don't have any valid data, then we are not in idle - pr. definition. - if (!polledIdleTimeIsValid && 0 == mLastUserInteractionInPR) { - *idleTime = 0; - return NS_OK; - } - - // If we never got a reset, just return the pulled time. - if (0 == mLastUserInteractionInPR) { - *idleTime = polledIdleTimeMS; - return NS_OK; - } - + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: Get idle time: polled %u msec, valid = %d", + polledIdleTimeMS, polledIdleTimeIsValid)); + // timeSinceReset is in milliseconds. PRUint32 timeSinceResetInMS = (PR_Now() - mLastUserInteractionInPR) / PR_USEC_PER_MSEC; + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: Get idle time: time since reset %u msec", + timeSinceResetInMS)); + // If we did't get pulled data, return the time since last idle reset. if (!polledIdleTimeIsValid) { // We need to convert to ms before returning the time. @@ -479,11 +506,17 @@ nsIdleService::IdleTimerCallback(void) PRUint32 currentIdleTimeInMS; if (NS_FAILED(GetIdleTime(¤tIdleTimeInMS))) { + PR_LOG(sLog, PR_LOG_ALWAYS, + ("idleService: Idle timer callback: failed to get idle time")); return; } + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: Idle timer callback: current idle time %u msec", + currentIdleTimeInMS)); + // Check if we have had some user interaction we didn't handle previously - // we do the caluculation in ms to lessen the chance for rounding errors to + // we do the calculation in ms to lessen the chance for rounding errors to // trigger wrong results, it is also very important that we call PR_Now AFTER // the call to GetIdleTime(). if (((PR_Now() - mLastUserInteractionInPR) / PR_USEC_PER_MSEC) > @@ -557,6 +590,9 @@ nsIdleService::IdleTimerCallback(void) // Notify all listeners that just timed out. while (numberOfPendingNotifications--) { + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: Idle timer callback: tell observer %x user is idle", + notifyList[numberOfPendingNotifications])); notifyList[numberOfPendingNotifications]->Observe(this, OBSERVER_TOPIC_IDLE, timeStr.get()); @@ -566,6 +602,10 @@ nsIdleService::IdleTimerCallback(void) void nsIdleService::SetTimerExpiryIfBefore(PRTime aNextTimeoutInPR) { + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: SetTimerExpiryIfBefore: next timeout %lld usec", + aNextTimeoutInPR)); + // Bail if we don't have a timer service. if (!mTimer) { return; @@ -576,6 +616,10 @@ nsIdleService::SetTimerExpiryIfBefore(PRTime aNextTimeoutInPR) if (mCurrentlySetToTimeoutAtInPR > aNextTimeoutInPR || !mCurrentlySetToTimeoutAtInPR) { +#ifdef PR_LOGGING + PRTime oldTimeout = mCurrentlySetToTimeoutAtInPR; +#endif + mCurrentlySetToTimeoutAtInPR = aNextTimeoutInPR ; // Stop the current timer (it's ok to try'n stop it, even it isn't running). @@ -590,6 +634,10 @@ nsIdleService::SetTimerExpiryIfBefore(PRTime aNextTimeoutInPR) // Add 10 ms to ensure we don't undershoot, and never get a "0" timer. mCurrentlySetToTimeoutAtInPR += 10 * PR_USEC_PER_MSEC; + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: reset timer expiry from %lld usec to %lld usec", + oldTimeout, mCurrentlySetToTimeoutAtInPR)); + // Start the timer mTimer->InitWithFuncCallback(StaticIdleTimerCallback, this, @@ -608,6 +656,8 @@ nsIdleService::ReconfigureTimer(void) if (!mAnyObserverIdle && PR_UINT32_MAX == mDeltaToNextIdleSwitchInS) { // If not, just let any existing timers run to completion // And bail out. + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: ReconfigureTimer: no idle or waiting observers")); return; } @@ -621,12 +671,19 @@ nsIdleService::ReconfigureTimer(void) (((PRTime)mDeltaToNextIdleSwitchInS) * PR_USEC_PER_SEC); + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: next timeout %lld usec (%u msec from now)", + nextTimeoutAtInPR, + (PRUint32)((nextTimeoutAtInPR - curTimeInPR) / PR_USEC_PER_MSEC))); // Check if we should correct the timeout time because we should poll before. if (mAnyObserverIdle && UsePollMode()) { PRTime pollTimeout = curTimeInPR + - MIN_IDLE_POLL_INTERVAL_MSEC * PR_USEC_PER_SEC; + MIN_IDLE_POLL_INTERVAL_MSEC * PR_USEC_PER_MSEC; if (nextTimeoutAtInPR > pollTimeout) { + PR_LOG(sLog, PR_LOG_DEBUG, + ("idleService: idle observers, reducing timeout to %u msec from now", + MIN_IDLE_POLL_INTERVAL_MSEC)); nextTimeoutAtInPR = pollTimeout; } }