Bug 1139751 - Try to collect data for Telemetry pings when the user is idle. r=vladan,a=vladan
authorGeorg Fritzsche <georg.fritzsche@googlemail.com>
Thu, 02 Apr 2015 21:33:47 +0200
changeset 265757 221c6a458a01cdabd477f6f093986a8199c5d3a4
parent 265756 c587374a3ba9fd2f26cccadbc2c0c28e43cf08b4
child 265758 daeddcbe4e41803be0cbe7e8ab594741efa8c289
push id4718
push userraliiev@mozilla.com
push dateMon, 11 May 2015 18:39:53 +0000
treeherdermozilla-beta@c20c4ef55f08 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersvladan, vladan
bugs1139751
milestone39.0a2
Bug 1139751 - Try to collect data for Telemetry pings when the user is idle. r=vladan,a=vladan
toolkit/components/telemetry/TelemetrySession.jsm
toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
--- a/toolkit/components/telemetry/TelemetrySession.jsm
+++ b/toolkit/components/telemetry/TelemetrySession.jsm
@@ -42,19 +42,17 @@ const REASON_SAVED_SESSION = "saved-sess
 const REASON_IDLE_DAILY = "idle-daily";
 const REASON_GATHER_PAYLOAD = "gather-payload";
 const REASON_TEST_PING = "test-ping";
 const REASON_ENVIRONMENT_CHANGE = "environment-change";
 const REASON_SHUTDOWN = "shutdown";
 
 const ENVIRONMENT_CHANGE_LISTENER = "TelemetrySession::onEnvironmentChange";
 
-const SEC_IN_ONE_DAY  = 24 * 60 * 60;
-const MS_IN_ONE_DAY   = SEC_IN_ONE_DAY * 1000;
-
+const MS_IN_ONE_HOUR  = 60 * 60 * 1000;
 const MIN_SUBSESSION_LENGTH_MS = 10 * 60 * 1000;
 
 // This is the HG changeset of the Histogram.json file, used to associate
 // submitted ping data with its histogram definition (bug 832007)
 #expand const HISTOGRAMS_FILE_VERSION = "__HISTOGRAMS_FILE_VERSION__";
 
 const LOGGER_NAME = "Toolkit.Telemetry";
 const LOGGER_PREFIX = "TelemetrySession::";
@@ -192,29 +190,39 @@ function truncateToDays(date) {
  * @return {Boolean} True if the absolute time difference is within the tolerance, false
  *                   otherwise.
  */
 function areTimesClose(t1, t2, tolerance) {
   return Math.abs(t1 - t2) <= tolerance;
 }
 
 /**
+ * Get the next midnight for a date.
+ * @param {Object} date The date object to check.
+ * @return {Object} The Date object representing the next midnight.
+ */
+function getNextMidnight(date) {
+  let nextMidnight = new Date(truncateToDays(date));
+  nextMidnight.setDate(nextMidnight.getDate() + 1);
+  return nextMidnight;
+}
+
+/**
  * Get the midnight which is closer to the provided date.
  * @param {Object} date The date object to check.
  * @return {Object} The Date object representing the closes midnight, or null if midnight
  *                  is not within the midnight tolerance.
  */
 function getNearestMidnight(date) {
   let lastMidnight = truncateToDays(date);
   if (areTimesClose(date.getTime(), lastMidnight.getTime(), SCHEDULER_MIDNIGHT_TOLERANCE_MS)) {
     return lastMidnight;
   }
 
-  let nextMidnightDate = new Date(lastMidnight);
-  nextMidnightDate.setDate(nextMidnightDate.getDate() + 1);
+  const nextMidnightDate = getNextMidnight(date);
   if (areTimesClose(date.getTime(), nextMidnightDate.getTime(), SCHEDULER_MIDNIGHT_TOLERANCE_MS)) {
     return nextMidnightDate;
   }
   return null;
 }
 
 /**
  * Get the ping type based on the payload.
@@ -416,83 +424,113 @@ let TelemetryScheduler = {
   // The number of times a daily ping fails.
   _dailyPingRetryAttempts: 0,
 
   // The timer which drives the scheduler.
   _schedulerTimer: null,
   // The interval used by the scheduler timer.
   _schedulerInterval: 0,
   _shuttingDown: true,
+  _isUserIdle: false,
 
   /**
    * Initialises the scheduler and schedules the first daily/aborted session pings.
    */
   init: function() {
     this._log = Log.repository.getLoggerWithMessagePrefix(LOGGER_NAME, "TelemetryScheduler::");
     this._log.trace("init");
     this._shuttingDown = false;
+    this._isUserIdle = false;
     // Initialize the last daily ping and aborted session last due times to the current time.
     // Otherwise, we might end up sending daily pings even if the subsession is not long enough.
     let now = Policy.now();
     this._lastDailyPingTime = now.getTime();
     this._lastSessionCheckpointTime = now.getTime();
-    this._schedulerInterval = SCHEDULER_TICK_INTERVAL_MS;
     this._rescheduleTimeout();
     idleService.addIdleObserver(this, IDLE_TIMEOUT_SECONDS);
   },
 
   /**
    * Reschedules the tick timer.
    */
   _rescheduleTimeout: function() {
-    this._log.trace("_rescheduleTimeout - timeout: " + this._schedulerInterval);
+    this._log.trace("_rescheduleTimeout - isUserIdle: " + this._isUserIdle);
     if (this._shuttingDown) {
       this._log.warn("_rescheduleTimeout - already shutdown");
       return;
     }
 
     if (this._schedulerTimer) {
       Policy.clearSchedulerTickTimeout(this._schedulerTimer);
     }
 
+    const now = Policy.now();
+    let timeout = SCHEDULER_TICK_INTERVAL_MS;
+
+    // When the user is idle we want to fire the timer less often.
+    if (this._isUserIdle) {
+      timeout = SCHEDULER_TICK_IDLE_INTERVAL_MS;
+      // We need to make sure though that we don't miss sending pings around
+      // midnight when we use the longer idle intervals.
+      const nextMidnight = getNextMidnight(now);
+      timeout = Math.min(timeout, nextMidnight.getTime() - now.getTime());
+    }
+
+    this._log.trace("_rescheduleTimeout - scheduling next tick for " + new Date(now.getTime() + timeout));
     this._schedulerTimer =
-      Policy.setSchedulerTickTimeout(() => this._onSchedulerTick(), this._schedulerInterval);
+      Policy.setSchedulerTickTimeout(() => this._onSchedulerTick(), timeout);
+  },
+
+  _sentDailyPingToday: function(nowDate) {
+    // This is today's date and also the previous midnight (0:00).
+    const todayDate = truncateToDays(nowDate);
+    const nearestMidnight = getNearestMidnight(nowDate);
+    // If we are close to midnight, we check against that, otherwise against the last midnight.
+    const checkDate = nearestMidnight || todayDate;
+    // We consider a ping sent for today if it occured after midnight, or prior within the tolerance.
+    return (this._lastDailyPingTime >= (checkDate.getTime() - SCHEDULER_MIDNIGHT_TOLERANCE_MS));
   },
 
   /**
    * Checks if we can send a daily ping or not.
    * @param {Object} nowDate A date object.
    * @return {Boolean} True if we can send the daily ping, false otherwise.
    */
   _isDailyPingDue: function(nowDate) {
-    let nearestMidnight = getNearestMidnight(nowDate);
-    if (nearestMidnight) {
-      let subsessionLength = Math.abs(nowDate.getTime() - this._lastDailyPingTime);
-      if (subsessionLength < MIN_SUBSESSION_LENGTH_MS) {
-        // Generating a daily ping now would create a very short subsession.
-        return false;
-      } else if (areTimesClose(this._lastDailyPingTime, nearestMidnight.getTime(),
-                               SCHEDULER_MIDNIGHT_TOLERANCE_MS)) {
-        // We've already sent a ping for this midnight.
-        return false;
-      }
+    const sentPingToday = this._sentDailyPingToday(nowDate);
+
+    // The daily ping is not due if we already sent one today.
+    if (sentPingToday) {
+      this._log.trace("_isDailyPingDue - already sent one today");
+      return false;
+    }
+
+    const nearestMidnight = getNearestMidnight(nowDate);
+    if (!sentPingToday && !nearestMidnight) {
+      // Computer must have gone to sleep, the daily ping is overdue.
+      this._log.trace("_isDailyPingDue - daily ping is overdue... computer went to sleep?");
       return true;
     }
 
-    let lastDailyPingDate = truncateToDays(new Date(this._lastDailyPingTime));
-    // This is today's date and also the previous midnight (0:00).
-    let todayDate = truncateToDays(nowDate);
-    // Check that _lastDailyPingTime isn't today nor within SCHEDULER_MIDNIGHT_TOLERANCE_MS of the
-    // *previous* midnight.
-    if ((lastDailyPingDate.getTime() != todayDate.getTime()) &&
-        !areTimesClose(this._lastDailyPingTime, todayDate.getTime(), SCHEDULER_MIDNIGHT_TOLERANCE_MS)) {
-      // Computer must have gone to sleep, the daily ping is overdue.
-      return true;
+    // Avoid overly short sessions.
+    const timeSinceLastDaily = nowDate.getTime() - this._lastDailyPingTime;
+    if (timeSinceLastDaily < MIN_SUBSESSION_LENGTH_MS) {
+      this._log.trace("_isDailyPingDue - delaying daily to keep minimum session length");
+      return false;
     }
-    return false;
+
+    // To fight jank, we allow daily pings to be collected on user idle before midnight
+    // within the tolerance interval.
+    if (!this._isUserIdle && (nowDate.getTime() < nearestMidnight.getTime())) {
+      this._log.trace("_isDailyPingDue - waiting for user idle period");
+      return false;
+    }
+
+    this._log.trace("_isDailyPingDue - is due");
+    return true;
   },
 
   /**
    * An helper function to save an aborted-session ping.
    * @param {Number} now The current time, in milliseconds.
    * @param {Object} [competingPayload=null] If we are coalescing the daily and the
    *                 aborted-session pings, this is the payload for the former. Note
    *                 that the reason field of this payload will be changed.
@@ -507,36 +545,36 @@ let TelemetryScheduler = {
   /**
    * The notifications handler.
    */
   observe: function(aSubject, aTopic, aData) {
     this._log.trace("observe - aTopic: " + aTopic);
     switch(aTopic) {
       case "idle":
         // If the user is idle, increase the tick interval.
-        this._schedulerInterval = SCHEDULER_TICK_IDLE_INTERVAL_MS;
-        this._rescheduleTimeout();
+        this._isUserIdle = true;
+        return this._onSchedulerTick();
         break;
       case "active":
         // User is back to work, restore the original tick interval.
-        this._schedulerInterval = SCHEDULER_TICK_INTERVAL_MS;
-        this._rescheduleTimeout();
+        this._isUserIdle = false;
+        return this._onSchedulerTick();
         break;
     }
   },
 
   /**
    * Performs a scheduler tick. This function manages Telemetry recurring operations.
    * @return {Promise} A promise, only used when testing, resolved when the scheduled
    *                   operation completes.
    */
   _onSchedulerTick: function() {
     if (this._shuttingDown) {
       this._log.warn("_onSchedulerTick - already shutdown.");
-      return;
+      return Promise.reject(new Error("Already shutdown."));
     }
 
     let promise = Promise.resolve();
     try {
       promise = this._schedulerTickLogic();
     } catch (e) {
       this._log.error("_onSchedulerTick - There was an exception", e);
     } finally {
--- a/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
+++ b/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
@@ -56,18 +56,18 @@ const FAILED_PROFILE_LOCK_ATTEMPTS = 2;
 const PR_WRONLY = 0x2;
 const PR_CREATE_FILE = 0x8;
 const PR_TRUNCATE = 0x20;
 const RW_OWNER = parseInt("0600", 8);
 
 const NUMBER_OF_THREADS_TO_LAUNCH = 30;
 let gNumberOfThreadsLaunched = 0;
 
-const SEC_IN_ONE_DAY  = 24 * 60 * 60;
-const MS_IN_ONE_DAY   = SEC_IN_ONE_DAY * 1000;
+const MS_IN_ONE_HOUR  = 60 * 60 * 1000;
+const MS_IN_ONE_DAY   = 24 * MS_IN_ONE_HOUR;
 
 const PREF_BRANCH = "toolkit.telemetry.";
 const PREF_ENABLED = PREF_BRANCH + "enabled";
 const PREF_SERVER = PREF_BRANCH + "server";
 const PREF_FHR_UPLOAD_ENABLED = "datareporting.healthreport.uploadEnabled";
 const PREF_FHR_SERVICE_ENABLED = "datareporting.healthreport.service.enabled";
 
 const SESSION_RECORDER_EXPECTED = HAS_DATAREPORTINGSERVICE &&
@@ -133,17 +133,17 @@ function wrapWithExceptionHandler(f) {
 function fakeGenerateUUID(sessionFunc, subsessionFunc) {
   let session = Cu.import("resource://gre/modules/TelemetrySession.jsm");
   session.Policy.generateSessionUUID = sessionFunc;
   session.Policy.generateSubsessionUUID = subsessionFunc;
 }
 
 function fakeIdleNotification(topic) {
   let session = Cu.import("resource://gre/modules/TelemetrySession.jsm");
-  session.TelemetryScheduler.observe(null, topic, null);
+  return session.TelemetryScheduler.observe(null, topic, null);
 }
 
 function registerPingHandler(handler) {
   gHttpServer.registerPrefixHandler("/submit/telemetry/",
 				   wrapWithExceptionHandler(handler));
 }
 
 function setupTestData() {
@@ -1018,18 +1018,20 @@ add_task(function* test_dailyDuplication
 
   let schedulerTickCallback = null;
   let now = new Date(2030, 1, 1, 0, 0, 0);
   fakeNow(now);
   // Fake scheduler functions to control daily collection flow in tests.
   fakeSchedulerTimer(callback => schedulerTickCallback = callback, () => {});
   yield TelemetrySession.setup();
 
-  // Make sure the daily ping gets triggered just before midnight.
-  let firstDailyDue = new Date(2030, 1, 1, 23, 45, 0);
+  // Make sure the daily ping gets triggered at midnight.
+  // We need to make sure that we trigger this after the period where we wait for
+  // the user to become idle.
+  let firstDailyDue = new Date(2030, 1, 2, 0, 0, 0);
   fakeNow(firstDailyDue);
 
   // Run a scheduler tick: it should trigger the daily ping.
   Assert.ok(!!schedulerTickCallback);
   yield schedulerTickCallback();
 
   // Get the first daily ping.
   let request = yield gRequestIterator.next();
@@ -1041,17 +1043,16 @@ add_task(function* test_dailyDuplication
 
   // We don't expect to receive any other daily ping in this test, so assert if we do.
   registerPingHandler((req, res) => {
     Assert.ok(false, "No more daily pings should be sent/received in this test.");
   });
 
   // Set the current time to a bit after midnight.
   let secondDailyDue = new Date(firstDailyDue);
-  secondDailyDue.setDate(firstDailyDue.getDate() + 1);
   secondDailyDue.setHours(0);
   secondDailyDue.setMinutes(15);
   fakeNow(secondDailyDue);
 
   // Run a scheduler tick: it should NOT trigger the daily ping.
   Assert.ok(!!schedulerTickCallback);
   yield schedulerTickCallback();
 
@@ -1623,37 +1624,100 @@ add_task(function* test_schedulerUserIdl
   if (gIsAndroid || gIsGonk) {
     // We don't have the aborted session or the daily ping here.
     return;
   }
 
   const SCHEDULER_TICK_INTERVAL_MS = 5 * 60 * 1000;
   const SCHEDULER_TICK_IDLE_INTERVAL_MS = 60 * 60 * 1000;
 
+  let now = new Date(2010, 1, 1, 11, 0, 0);
+  fakeNow(now);
+
   let schedulerTimeout = 0;
   fakeSchedulerTimer((callback, timeout) => {
     schedulerTimeout = timeout;
   }, () => {});
   yield TelemetrySession.reset();
+  gRequestIterator = Iterator(new Request());
 
   // When not idle, the scheduler should have a 5 minutes tick interval.
   Assert.equal(schedulerTimeout, SCHEDULER_TICK_INTERVAL_MS);
 
   // Send an "idle" notification to the scheduler.
   fakeIdleNotification("idle");
 
   // When idle, the scheduler should have a 1hr tick interval.
   Assert.equal(schedulerTimeout, SCHEDULER_TICK_IDLE_INTERVAL_MS);
 
   // Send an "active" notification to the scheduler.
   fakeIdleNotification("active");
 
   // When user is back active, the scheduler tick should be 5 minutes again.
   Assert.equal(schedulerTimeout, SCHEDULER_TICK_INTERVAL_MS);
 
+  // We should not miss midnight when going to idle.
+  now.setHours(23);
+  now.setMinutes(50);
+  fakeIdleNotification("idle");
+  Assert.equal(schedulerTimeout, 10 * 60 * 1000);
+
+  yield TelemetrySession.shutdown();
+});
+
+add_task(function* test_sendDailyOnIdle() {
+  if (gIsAndroid || gIsGonk) {
+    // We don't have the aborted session or the daily ping here.
+    return;
+  }
+
+  let now = new Date(2040, 1, 1, 11, 0, 0);
+  fakeNow(now);
+
+  let schedulerTickCallback = 0;
+  fakeSchedulerTimer((callback, timeout) => {
+    schedulerTickCallback = callback;
+  }, () => {});
+  yield TelemetrySession.reset();
+
+  // Make sure we are not sending a daily before midnight when active.
+  now = new Date(2040, 1, 1, 23, 55, 0);
+  fakeNow(now);
+  registerPingHandler((req, res) => {
+    Assert.ok(false, "No daily ping should be received yet when the user is active.");
+  });
+  yield fakeIdleNotification("active");
+
+  // The Request constructor restores the previous ping handler.
+  gRequestIterator = Iterator(new Request());
+
+  // We should receive a daily ping after midnight.
+  now = new Date(2040, 1, 2, 0, 05, 0);
+  fakeNow(now);
+  yield schedulerTickCallback();
+
+  let request = yield gRequestIterator.next();
+  Assert.ok(!!request);
+  let ping = decodeRequestPayload(request);
+
+  Assert.equal(ping.type, PING_TYPE_MAIN);
+  Assert.equal(ping.payload.info.reason, REASON_DAILY);
+
+  // We should also trigger a ping when going idle shortly before next midnight.
+  now = new Date(2040, 1, 2, 23, 55, 0);
+  fakeNow(now);
+  yield fakeIdleNotification("idle");
+
+  request = yield gRequestIterator.next();
+  Assert.ok(!!request);
+  ping = decodeRequestPayload(request);
+
+  Assert.equal(ping.type, PING_TYPE_MAIN);
+  Assert.equal(ping.payload.info.reason, REASON_DAILY);
+
   yield TelemetrySession.shutdown();
 });
 
 add_task(function* stopServer(){
   gHttpServer.stop(do_test_finished);
 });
 
 // An iterable sequence of http requests