Bug 792037 - Improve idle daily logic such that we shorten idle time waits if it has been a long time since the last idle-daily. Improves telemetry data collection on Win8 tablets. r=gpascutto, mak77
authorJim Mathies <jmathies@mozilla.com>
Fri, 12 Oct 2012 08:02:24 -0500
changeset 110217 31bebe4cdeede3e717a021aef7c0007389bec00f
parent 110216 3044539fec87be189addde74159b93293c6301cb
child 110218 5540b310d435b0616b878b5a279f9ae65c2baa3f
push id93
push usernmatsakis@mozilla.com
push dateWed, 31 Oct 2012 21:26:57 +0000
reviewersgpascutto, mak77
bugs792037
milestone19.0a1
Bug 792037 - Improve idle daily logic such that we shorten idle time waits if it has been a long time since the last idle-daily. Improves telemetry data collection on Win8 tablets. r=gpascutto, mak77
widget/xpwidgets/nsIdleService.cpp
widget/xpwidgets/nsIdleService.h
--- a/widget/xpwidgets/nsIdleService.cpp
+++ b/widget/xpwidgets/nsIdleService.cpp
@@ -21,20 +21,29 @@
 #include <android/log.h>
 #endif
 
 using namespace mozilla;
 
 // interval in milliseconds between internal idle time requests.
 #define MIN_IDLE_POLL_INTERVAL_MSEC (5 * PR_MSEC_PER_SEC) /* 5 sec */
 
-// Time used by the daily idle serivce to determine a significant idle time.
-#define DAILY_SIGNIFICANT_IDLE_SERVICE_SEC 300 /* 5 min */
+// After the twenty four hour period expires for an idle daily, this is the
+// amount of idle time we wait for before actually firing the idle-daily
+// event.
+#define DAILY_SIGNIFICANT_IDLE_SERVICE_SEC (3 * 60)
+
+// In cases where it's been longer than twenty four hours since the last
+// idle-daily, this is the shortend amount of idle time we wait for before
+// firing the idle-daily event.
+#define DAILY_SHORTENED_IDLE_SERVICE_SEC 60
+
 // Pref for last time (seconds since epoch) daily notification was sent.
 #define PREF_LAST_DAILY "idle.lastDailyNotification"
+
 // 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:
@@ -53,189 +62,243 @@ public:
 
 NS_IMPL_ISUPPORTS2(nsIdleServiceDaily, nsIObserver, nsISupportsWeakReference)
 
 NS_IMETHODIMP
 nsIdleServiceDaily::Observe(nsISupports *,
                             const char *aTopic,
                             const PRUnichar *)
 {
+  PR_LOG(sLog, PR_LOG_DEBUG,
+         ("nsIdleServiceDaily: Observe '%s' (%d)",
+          aTopic, mShutdownInProgress));
+
   if (strcmp(aTopic, "profile-after-change") == 0) {
     // We are back. Start sending notifications again.
     mShutdownInProgress = false;
     return NS_OK;
   }
 
   if (strcmp(aTopic, "xpcom-will-shutdown") == 0 ||
       strcmp(aTopic, "profile-change-teardown") == 0) {
     mShutdownInProgress = true;
   }
 
   if (mShutdownInProgress || strcmp(aTopic, OBSERVER_TOPIC_ACTIVE) == 0) {
     return NS_OK;
   }
   MOZ_ASSERT(strcmp(aTopic, OBSERVER_TOPIC_IDLE) == 0);
 
+  PR_LOG(sLog, PR_LOG_DEBUG,
+         ("nsIdleServiceDaily: Notifying idle-daily observers"));
 #ifdef ANDROID
-  __android_log_print(ANDROID_LOG_INFO, "IdleService", "Notifying idle-daily observers");
+  __android_log_print(ANDROID_LOG_INFO, "IdleService",
+                      "Notifying idle-daily observers");
 #endif
 
-  // Notify anyone who cares.
+  // Send the idle-daily observer event
   nsCOMPtr<nsIObserverService> observerService =
     mozilla::services::GetObserverService();
   NS_ENSURE_STATE(observerService);
   (void)observerService->NotifyObservers(nullptr,
                                          OBSERVER_TOPIC_IDLE_DAILY,
                                          nullptr);
 
   // Notify the category observers.
   const nsCOMArray<nsIObserver> &entries = mCategoryObservers.GetEntries();
   for (int32_t i = 0; i < entries.Count(); ++i) {
     (void)entries[i]->Observe(nullptr, OBSERVER_TOPIC_IDLE_DAILY, nullptr);
   }
 
   // Stop observing idle for today.
-  (void)mIdleService->RemoveIdleObserver(this,
-                                         DAILY_SIGNIFICANT_IDLE_SERVICE_SEC);
+  (void)mIdleService->RemoveIdleObserver(this, mIdleDailyTriggerWait);
 
   // Set the last idle-daily time pref.
   int32_t nowSec = static_cast<int32_t>(PR_Now() / PR_USEC_PER_SEC);
   Preferences::SetInt(PREF_LAST_DAILY, nowSec);
 
   // Force that to be stored so we don't retrigger twice a day under
   // any circumstances.
   nsIPrefService* prefs = Preferences::GetService();
   if (prefs) {
     prefs->SavePrefFile(nullptr);
   }
 
+  PR_LOG(sLog, PR_LOG_DEBUG,
+         ("nsIdleServiceDaily: Storing last idle time as %d sec.", nowSec));
 #ifdef ANDROID
-  __android_log_print(ANDROID_LOG_INFO, "IdleService", "Storing last idle time as %d",
-                      nowSec);
+  __android_log_print(ANDROID_LOG_INFO, "IdleService",
+                      "Storing last idle time as %d", nowSec);
 #endif
 
-  // Note the moment we started our timer.
-  mDailyTimerStart  = PR_Now();
+  // Note the moment we expect to get the next timer callback
+  mExpectedTriggerTime  = PR_Now() + ((PRTime)SECONDS_PER_DAY *
+                                      (PRTime)PR_USEC_PER_SEC);
+
+  PR_LOG(sLog, PR_LOG_DEBUG,
+         ("nsIdleServiceDaily: Restarting daily timer"));
 
   // Start timer for the next check in one day.
   (void)mTimer->InitWithFuncCallback(DailyCallback,
                                      this,
                                      SECONDS_PER_DAY * PR_MSEC_PER_SEC,
                                      nsITimer::TYPE_ONE_SHOT);
 
   return NS_OK;
 }
 
 nsIdleServiceDaily::nsIdleServiceDaily(nsIIdleService* aIdleService)
   : mIdleService(aIdleService)
   , mTimer(do_CreateInstance(NS_TIMER_CONTRACTID))
   , mCategoryObservers(OBSERVER_TOPIC_IDLE_DAILY)
+  , mExpectedTriggerTime(0)
+  , mIdleDailyTriggerWait(DAILY_SIGNIFICANT_IDLE_SERVICE_SEC)
   , mShutdownInProgress(false)
 {
 }
 
 void
 nsIdleServiceDaily::Init()
 {
-  // Check time of the last idle-daily notification.  If it was more than 24
-  // hours ago listen for idle, otherwise set a timer for 24 hours from now.
+  // First check the time of the last idle-daily event notification. If it
+  // has been 24 hours or higher, or if we have never sent an idle-daily,
+  // get ready to send an idle-daily event. Otherwise set a timer targeted
+  // at 24 hours past the last idle-daily we sent.
+
   int32_t nowSec = static_cast<int32_t>(PR_Now() / PR_USEC_PER_SEC);
   int32_t lastDaily = Preferences::GetInt(PREF_LAST_DAILY, 0);
   if (lastDaily < 0 || lastDaily > nowSec) {
     // The time is bogus, use default.
     lastDaily = 0;
   }
+  int32_t secondsSinceLastDaily = nowSec - lastDaily;
 
-  // Check if it has been a day since the last notification.
-  if (nowSec - lastDaily > SECONDS_PER_DAY) {
+  PR_LOG(sLog, PR_LOG_DEBUG,
+         ("nsIdleServiceDaily: Init: seconds since last daily: %d",
+          secondsSinceLastDaily));
+
+  // If it has been twenty four hours or more or if we have never sent an
+  // idle-daily event get ready to send it during the next idle period.
+  if (secondsSinceLastDaily > SECONDS_PER_DAY) {
+    // Check for a "long wait", e.g. 48-hours or more.
+    bool hasBeenLongWait = (lastDaily &&
+                            (secondsSinceLastDaily > (SECONDS_PER_DAY * 2)));
+
+    PR_LOG(sLog, PR_LOG_DEBUG,
+           ("nsIdleServiceDaily: has been long wait? %d",
+            hasBeenLongWait));
+
+    // StageIdleDaily sets up a wait for the user to become idle and then
+    // sends the idle-daily event.
+    StageIdleDaily(hasBeenLongWait);
+  } else {
+    PR_LOG(sLog, PR_LOG_DEBUG,
+           ("nsIdleServiceDaily: Setting timer a day from now"));
 #ifdef ANDROID
-    __android_log_print(ANDROID_LOG_INFO, "IdleService", "DailyCallback started");
-#endif
-    // The timer would have been started after the previous idle-daily. Need to
-    // set this here so DailyCallback knows the timer didn't fire early.
-    mDailyTimerStart = lastDaily * PR_USEC_PER_SEC;
-
-    // Wait for the user to become idle, so we can do todays idle tasks.
-    DailyCallback(nullptr, this);
-  }
-  else {
-#ifdef ANDROID
-    __android_log_print(ANDROID_LOG_INFO, "IdleService", "Setting timer a day from now");
+    __android_log_print(ANDROID_LOG_INFO, "IdleService",
+                        "Setting timer a day from now");
 #endif
 
-    // Note the moment we started our timer.
-    mDailyTimerStart  = PR_Now();
+    // According to our last idle-daily pref, the last idle-daily was fired
+    // less then 24 hours ago. Set a wait for the amount of time remaining.
+    int32_t milliSecLeftUntilDaily = (SECONDS_PER_DAY - secondsSinceLastDaily)
+      * PR_MSEC_PER_SEC;
 
-    // Start timer for the next check in one day.
+    PR_LOG(sLog, PR_LOG_DEBUG,
+           ("nsIdleServiceDaily: Seconds till next timeout: %d",
+            (SECONDS_PER_DAY - secondsSinceLastDaily)));
+
+    // Mark the time at which we expect this to fire. On systems with faulty
+    // timers, we need to be able to cross check that the timer fired at the
+    // expected time.
+    mExpectedTriggerTime  = PR_Now() +
+      (milliSecLeftUntilDaily * PR_USEC_PER_MSEC);
+
     (void)mTimer->InitWithFuncCallback(DailyCallback,
                                        this,
-                                       SECONDS_PER_DAY * PR_MSEC_PER_SEC,
+                                       milliSecLeftUntilDaily,
                                        nsITimer::TYPE_ONE_SHOT);
   }
 
   // Register for when we should terminate/pause
   nsCOMPtr<nsIObserverService> obs = mozilla::services::GetObserverService();
   if (obs) {
+    PR_LOG(sLog, PR_LOG_DEBUG,
+           ("nsIdleServiceDaily: Registering for system event observers."));
     obs->AddObserver(this, "xpcom-will-shutdown", true);
     obs->AddObserver(this, "profile-change-teardown", true);
     obs->AddObserver(this, "profile-after-change", true);
   }
 }
 
 nsIdleServiceDaily::~nsIdleServiceDaily()
 {
   if (mTimer) {
     mTimer->Cancel();
     mTimer = nullptr;
   }
 }
 
+
+void
+nsIdleServiceDaily::StageIdleDaily(bool aHasBeenLongWait)
+{
+  NS_ASSERTION(mIdleService, "No idle service available?");
+  PR_LOG(sLog, PR_LOG_DEBUG,
+          ("nsIdleServiceDaily: Registering Idle observer callback "
+           "(short wait requested? %d)", aHasBeenLongWait));
+#ifdef ANDROID
+  __android_log_print(ANDROID_LOG_INFO, "IdleService",
+                      "Registering Idle observer callback");
+#endif
+  mIdleDailyTriggerWait = (aHasBeenLongWait ?
+                             DAILY_SHORTENED_IDLE_SERVICE_SEC :
+                             DAILY_SIGNIFICANT_IDLE_SERVICE_SEC);
+  (void)mIdleService->AddIdleObserver(this, mIdleDailyTriggerWait);
+}
+
 // static
 void
 nsIdleServiceDaily::DailyCallback(nsITimer* aTimer, void* aClosure)
 {
+  PR_LOG(sLog, PR_LOG_DEBUG,
+          ("nsIdleServiceDaily: DailyCallback running"));
 #ifdef ANDROID
-  __android_log_print(ANDROID_LOG_INFO, "IdleService", "DailyCallback running");
+  __android_log_print(ANDROID_LOG_INFO, "IdleService",
+                      "DailyCallback running");
 #endif
 
-  nsIdleServiceDaily* me = static_cast<nsIdleServiceDaily*>(aClosure);
-
-  PRTime now = PR_Now();
-  PRTime launchTime = me->mDailyTimerStart + ((PRTime)SECONDS_PER_DAY * PR_USEC_PER_SEC);
+  nsIdleServiceDaily* self = static_cast<nsIdleServiceDaily*>(aClosure);
 
-  // Check if it has been a day since we launched this timer.
-  if (now < launchTime) {
-      // Timer returned early, reschedule.
-      PRTime newTime = launchTime;
+  // Check to be sure the timer didn't fire early. This currently only
+  // happens on android.
+  PRTime now = PR_Now();
+  if (self->mExpectedTriggerTime && now < self->mExpectedTriggerTime) {
+    // Timer returned early, reschedule to the appropriate time.
+    PRTime newTime = self->mExpectedTriggerTime - now;
 
-      // Add 10 ms to ensure we don't undershoot, and never get a "0" timer.
-      newTime += 10 * PR_USEC_PER_MSEC;
+    // Add 10 ms to ensure we don't undershoot, and never get a "0" timer.
+    newTime += 10 * PR_USEC_PER_MSEC;
 
 #ifdef ANDROID
-      __android_log_print(ANDROID_LOG_INFO, "IdleService",
-                          "DailyCallback resetting timer to %lld msec",
-                          (newTime - now) / PR_USEC_PER_MSEC);
+    __android_log_print(ANDROID_LOG_INFO, "IdleService",
+                        "DailyCallback resetting timer to %lld msec",
+                        (newTime - now) / PR_USEC_PER_MSEC);
 #endif
 
-      // Refire the timer.
-      (void)me->mTimer->InitWithFuncCallback(DailyCallback,
-                                             me,
+    (void)self->mTimer->InitWithFuncCallback(DailyCallback,
+                                             self,
                                              (newTime - now) / PR_USEC_PER_MSEC,
                                              nsITimer::TYPE_ONE_SHOT);
-      return;
+    return;
   }
 
-#ifdef ANDROID
-  __android_log_print(ANDROID_LOG_INFO, "IdleService", "DailyCallback registering Idle observer");
-#endif
-
-  // The one thing we do every day is to start waiting for the user to "have
-  // a significant idle time".
-  (void)me->mIdleService->AddIdleObserver(me,
-                                          DAILY_SIGNIFICANT_IDLE_SERVICE_SEC);
+  // Register for a short term wait for idle event. When this fires we fire
+  // our idle-daily event.
+  self->StageIdleDaily(false);
 }
 
 
 /**
  * The idle services goal is to notify subscribers when a certain time has
  * passed since the last user interaction with the system.
  *
  * On some platforms this is defined as the last time user events reached this
@@ -348,17 +411,18 @@ NS_IMPL_ISUPPORTS2(nsIdleService, nsIIdl
 
 NS_IMETHODIMP
 nsIdleService::AddIdleObserver(nsIObserver* aObserver, uint32_t aIdleTimeInS)
 {
   PR_LOG(sLog, PR_LOG_DEBUG,
          ("idleService: Register idle observer %x for %d seconds",
           aObserver, aIdleTimeInS));
 #ifdef ANDROID
-  __android_log_print(ANDROID_LOG_INFO, "IdleService", "Register idle observer %x for %d seconds",
+  __android_log_print(ANDROID_LOG_INFO, "IdleService",
+                      "Register idle observer %x for %d seconds",
                       aObserver, aIdleTimeInS);
 #endif
 
   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.
   NS_ENSURE_ARG_RANGE(aIdleTimeInS, 1, (UINT32_MAX / 10) - 1);
 
@@ -664,27 +728,29 @@ nsIdleService::IdleTimerCallback(void)
   ReconfigureTimer();
 
   int32_t numberOfPendingNotifications = notifyList.Count();
   Telemetry::Accumulate(Telemetry::IDLE_NOTIFY_IDLE_LISTENERS,
                         numberOfPendingNotifications);
 
   // Bail if nothing to do.
   if (!numberOfPendingNotifications) {
+    PR_LOG(sLog, PR_LOG_DEBUG,
+           ("idleService: **** Idle timer callback: no observers to message."));
     return;
   }
 
   // We need a text string to send with any state change events.
   nsAutoString timeStr;
   timeStr.AppendInt(currentIdleTimeInS);
 
   // 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",
+           ("idleService: **** Idle timer callback: tell observer %x user is idle",
             notifyList[numberOfPendingNotifications]));
 #ifdef ANDROID
   __android_log_print(ANDROID_LOG_INFO, "IdleService",
                       "Idle timer callback: tell observer %x user is idle",
                       notifyList[numberOfPendingNotifications]);
 #endif
     notifyList[numberOfPendingNotifications]->Observe(this,
                                                       OBSERVER_TOPIC_IDLE,
--- a/widget/xpwidgets/nsIdleService.h
+++ b/widget/xpwidgets/nsIdleService.h
@@ -53,16 +53,28 @@ public:
    * corruption due to AddRef/Release of "this".
    */
   void Init();
 
   virtual ~nsIdleServiceDaily();
 
 private:
   /**
+   * StageIdleDaily is the interim call made when an idle-daily event is due.
+   * However we don't want to fire idle-daily until the user is idle for this
+   * session, so this sets up a short wait for an idle event which triggers
+   * the actual idle-daily event.
+   *
+   * @param aHasBeenLongWait Pass true indicating nsIdleServiceDaily is having
+   * trouble getting the idle-daily event fired. If true StageIdleDaily will
+   * use a shorter idle wait time before firing idle-daily.
+   */
+  void StageIdleDaily(bool aHasBeenLongWait);
+
+  /**
    * @note This is a normal pointer, part to avoid creating a cycle with the
    * idle service, part to avoid potential pointer corruption due to this class
    * being instantiated in the constructor of the service itself.
    */
   nsIIdleService* mIdleService;
 
   /**
    * Place to hold the timer used by this class to determine when a day has
@@ -81,20 +93,27 @@ private:
   nsCategoryCache<nsIObserver> mCategoryObservers;
 
   /**
    * Boolean set to true when daily idle notifications should be disabled.
    */
   bool mShutdownInProgress;
 
   /**
-   * Real time we fired off the one-day timer, in case timers aren't
-   * very reliable.
+   * Next time we expect an idle-daily timer to fire, in case timers aren't
+   * very reliable on the platform. Value is in PR_Now microsecond units.
    */
-  PRTime mDailyTimerStart;
+  PRTime mExpectedTriggerTime;
+
+  /**
+   * Tracks which idle daily observer callback we ask for. There are two: a
+   * regular long idle wait and a shorter wait if we've been waiting to fire
+   * idle daily for an extended period. Set by StageIdleDaily.
+   */
+  int32_t mIdleDailyTriggerWait;
 };
 
 class nsIdleService : public nsIIdleServiceInternal
 {
 public:
   NS_DECL_ISUPPORTS
   NS_DECL_NSIIDLESERVICE
   NS_DECL_NSIIDLESERVICEINTERNAL