Bug 1139751 - Try to collect data for Telemetry pings when the user is idle. r=vladan
☠☠ backed out by b482ca2ea198 ☠ ☠
authorGeorg Fritzsche <georg.fritzsche@googlemail.com>
Fri, 27 Mar 2015 21:01:20 +0100
changeset 266516 e0ed9413cc171f1cb5c99b20e7d14b5d99cde940
parent 266515 208c445781e79f72d7a7a1261d03fbadda246d8b
child 266517 4d163f1939b512490f4b86f6f3dd426f9a554f35
push id830
push userraliiev@mozilla.com
push dateFri, 19 Jun 2015 19:24:37 +0000
treeherdermozilla-release@932614382a68 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersvladan
bugs1139751
milestone39.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1139751 - Try to collect data for Telemetry pings when the user is idle. r=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 HAS_DATAREPORTINGSERVICE = "@mozilla.org/datareporting/service;1" in Cc;
@@ -134,17 +134,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() {
@@ -1019,18 +1019,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();
@@ -1042,17 +1044,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();
 
@@ -1624,37 +1625,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