Bug 1188416 - Use monotonic clocks for Telemetry subsessionLength. r=dexter,a=ritu
authorGeorg Fritzsche <georg.fritzsche@googlemail.com>
Wed, 29 Jul 2015 14:47:01 +0200
changeset 281893 a5c248399f2d5aa6a921597296564e3b0350ae69
parent 281892 3e50944418196c031473afc849bb7e8b39ed878b
child 281894 b626e62c6974c6989898a2baf77a3734aca06ecf
push id4948
push usergeorg.fritzsche@googlemail.com
push dateWed, 12 Aug 2015 14:33:05 +0000
treeherdermozilla-beta@8ff9920688c1 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersdexter, ritu
bugs1188416
milestone41.0
Bug 1188416 - Use monotonic clocks for Telemetry subsessionLength. r=dexter,a=ritu
toolkit/components/telemetry/TelemetrySession.jsm
toolkit/components/telemetry/docs/main-ping.rst
toolkit/components/telemetry/tests/unit/head.js
toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
--- a/toolkit/components/telemetry/TelemetrySession.jsm
+++ b/toolkit/components/telemetry/TelemetrySession.jsm
@@ -157,21 +157,31 @@ XPCOMUtils.defineLazyModuleGetter(this, 
                                   "resource://services-common/utils.js");
 
 function generateUUID() {
   let str = Cc["@mozilla.org/uuid-generator;1"].getService(Ci.nsIUUIDGenerator).generateUUID().toString();
   // strip {}
   return str.substring(1, str.length - 1);
 }
 
+function getMsSinceProcessStart() {
+  try {
+    return Telemetry.msSinceProcessStart();
+  } catch (ex) {
+    // If this fails return a special value.
+    return -1;
+  }
+}
+
 /**
  * This is a policy object used to override behavior for testing.
  */
 let Policy = {
   now: () => new Date(),
+  monotonicNow: getMsSinceProcessStart,
   generateSessionUUID: () => generateUUID(),
   generateSubsessionUUID: () => generateUUID(),
   setSchedulerTickTimeout: (callback, delayMs) => setTimeout(callback, delayMs),
   clearSchedulerTickTimeout: id => clearTimeout(id),
 };
 
 /**
  * Get the ping type based on the payload.
@@ -705,16 +715,17 @@ this.TelemetrySession = Object.freeze({
   reset: function() {
     Impl._sessionId = null;
     Impl._subsessionId = null;
     Impl._previousSessionId = null;
     Impl._previousSubsessionId = null;
     Impl._subsessionCounter = 0;
     Impl._profileSubsessionCounter = 0;
     Impl._subsessionStartActiveTicks = 0;
+    Impl._subsessionStartTimeMonotonic = 0;
     this.uninstall();
     return this.setup();
   },
   /**
    * Used only for testing purposes.
    * @param {Boolean} [aForceSavePending=true] If true, always saves the ping whether Telemetry
    *        can send pings or not, which is used for testing.
    */
@@ -790,16 +801,19 @@ let Impl = {
   // null on first run.
   _previousSubsessionId: null,
   // The running no. of subsessions since the start of the browser session
   _subsessionCounter: 0,
   // The running no. of all subsessions for the whole profile life time
   _profileSubsessionCounter: 0,
   // Date of the last session split
   _subsessionStartDate: null,
+  // Start time of the current subsession using a monotonic clock for the subsession
+  // length measurements.
+  _subsessionStartTimeMonotonic: 0,
   // The active ticks counted when the subsession starts
   _subsessionStartActiveTicks: 0,
   // A task performing delayed initialization of the chrome process
   _delayedInitTask: null,
   // The deferred promise resolved when the initialization task completes.
   _delayedInitTaskDeferred: null,
   // Used to serialize session state writes to disk.
   _stateSaveSerializer: new SaveSerializer(),
@@ -1074,21 +1088,19 @@ let Impl = {
    * @param  reason
    *         The reason for the telemetry ping, this will be included in the
    *         returned metadata,
    * @return The metadata as a JS object
    */
   getMetadata: function getMetadata(reason) {
     this._log.trace("getMetadata - Reason " + reason);
 
-    let sessionStartDate = toLocalTimeISOString(Utils.truncateToDays(this._sessionStartDate));
-    let subsessionStartDate = toLocalTimeISOString(Utils.truncateToDays(this._subsessionStartDate));
-    // Compute the subsession length in milliseconds, then convert to seconds.
-    let subsessionLength =
-      Math.floor((Policy.now() - this._subsessionStartDate.getTime()) / 1000);
+    const sessionStartDate = toLocalTimeISOString(Utils.truncateToDays(this._sessionStartDate));
+    const subsessionStartDate = toLocalTimeISOString(Utils.truncateToDays(this._subsessionStartDate));
+    const monotonicNow = Policy.monotonicNow();
 
     let ret = {
       reason: reason,
       revision: HISTOGRAMS_FILE_VERSION,
       asyncPluginInit: Preferences.get(PREF_ASYNC_PLUGIN_INIT, false),
 
       // Date.getTimezoneOffset() unintuitively returns negative values if we are ahead of
       // UTC and vice versa (e.g. -60 for UTC+1). We invert the sign here.
@@ -1100,17 +1112,23 @@ let Impl = {
       previousSessionId: this._previousSessionId,
       previousSubsessionId: this._previousSubsessionId,
 
       subsessionCounter: this._subsessionCounter,
       profileSubsessionCounter: this._profileSubsessionCounter,
 
       sessionStartDate: sessionStartDate,
       subsessionStartDate: subsessionStartDate,
-      subsessionLength: subsessionLength,
+
+      // Compute the session and subsession length in seconds.
+      // We use monotonic clocks as Date() is affected by jumping clocks (leading
+      // to negative lengths and other issues).
+      sessionLength: Math.floor(monotonicNow / 1000),
+      subsessionLength:
+        Math.floor((monotonicNow - this._subsessionStartTimeMonotonic) / 1000),
     };
 
     // TODO: Remove this when bug 1124128 lands.
     if (this._addons)
       ret.addons = this._addons;
 
     // TODO: Remove this when bug 1124128 lands.
     let flashVersion = this.getFlashVersion();
@@ -1329,16 +1347,17 @@ let Impl = {
     return payloadObj;
   },
 
   /**
    * Start a new subsession.
    */
   startNewSubsession: function () {
     this._subsessionStartDate = Policy.now();
+    this._subsessionStartTimeMonotonic = Policy.monotonicNow();
     this._previousSubsessionId = this._subsessionId;
     this._subsessionId = Policy.generateSubsessionUUID();
     this._subsessionCounter++;
     this._profileSubsessionCounter++;
   },
 
   getSessionPayload: function getSessionPayload(reason, clearSubsession) {
     this._log.trace("getSessionPayload - reason: " + reason + ", clearSubsession: " + clearSubsession);
--- a/toolkit/components/telemetry/docs/main-ping.rst
+++ b/toolkit/components/telemetry/docs/main-ping.rst
@@ -34,17 +34,18 @@ Structure::
         previousSubsessionId: <uuid>, // subsession id of the previous subsession (even if it was in a different session),
                                       // null on first run.
 
         subsessionCounter: <number>, // the running no. of this subsession since the start of the browser session
         profileSubsessionCounter: <number>, // the running no. of all subsessions for the whole profile life time
 
         sessionStartDate: <ISO date>, // daily precision
         subsessionStartDate: <ISO date>, // daily precision, ISO date in local time
-        subsessionLength: <number>, // the subsession length in seconds
+        sessionLength: <number>, // the session length until now in seconds, monotonic
+        subsessionLength: <number>, // the subsession length in seconds, monotonic
       },
 
       childPayloads: {...}, // only present with e10s; a reduced payload from content processes
 
       simpleMeasurements: { ... },
       histograms: {},
       keyedHistograms: {},
       chromeHangs: {},
@@ -53,8 +54,26 @@ Structure::
       fileIOReports: {...},
       lateWrites: {...},
       addonDetails: { ... },
       addonHistograms: {...},
       UIMeasurements: {...},
       slowSQL: {...},
       slowSQLstartup: {...},
     }
+
+info
+----
+
+sessionLength
+~~~~~~~~~~~~~
+The length of the current session so far in seconds.
+This uses a monotonic clock, so this may mismatch with other measurements that
+are not monotonic like calculations based on ``Date.now()``.
+
+If the monotonic clock failed, this will be ``-1``.
+
+subsessionLength
+~~~~~~~~~~~~~~~~
+The length of this subsession in seconds.
+This uses a monotonic clock, so this may mismatch with other measurements that are not monotonic (e.g. based on Date.now()).
+
+If ``sessionLength`` is ``-1``, the monotonic clock is not working.
--- a/toolkit/components/telemetry/tests/unit/head.js
+++ b/toolkit/components/telemetry/tests/unit/head.js
@@ -243,16 +243,22 @@ function fakeNow(...args) {
 
   for (let m of modules) {
     m.Policy.now = () => date;
   }
 
   return new Date(date);
 }
 
+function fakeMonotonicNow(ms) {
+  const m = Cu.import("resource://gre/modules/TelemetrySession.jsm");
+  m.Policy.monotonicNow = () => ms;
+  return ms;
+}
+
 // Fake the timeout functions for TelemetryController sending.
 function fakePingSendTimer(set, clear) {
   let module = Cu.import("resource://gre/modules/TelemetrySend.jsm");
   let obj = Cu.cloneInto({set, clear}, module, {cloneFunctions:true});
   module.Policy.setSchedulerTickTimeout = obj.set;
   module.Policy.clearSchedulerTickTimeout = obj.clear;
 }
 
--- a/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
+++ b/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
@@ -514,26 +514,28 @@ add_task(function* test_simplePing() {
   yield clearPendingPings();
   yield TelemetrySend.reset();
   PingServer.start();
   Preferences.set(PREF_SERVER, "http://localhost:" + PingServer.port);
 
   let now = new Date(2020, 1, 1, 12, 0, 0);
   let expectedDate = new Date(2020, 1, 1, 0, 0, 0);
   fakeNow(now);
+  const monotonicStart = fakeMonotonicNow(5000);
 
   const expectedSessionUUID = "bd314d15-95bf-4356-b682-b6c4a8942202";
   const expectedSubsessionUUID = "3e2e5f6c-74ba-4e4d-a93f-a48af238a8c7";
   fakeGenerateUUID(() => expectedSessionUUID, () => expectedSubsessionUUID);
   yield TelemetrySession.reset();
 
   // Session and subsession start dates are faked during TelemetrySession setup. We can
   // now fake the session duration.
   const SESSION_DURATION_IN_MINUTES = 15;
   fakeNow(new Date(2020, 1, 1, 12, SESSION_DURATION_IN_MINUTES, 0));
+  fakeMonotonicNow(monotonicStart + SESSION_DURATION_IN_MINUTES * 60 * 1000);
 
   yield sendPing();
   let ping = yield PingServer.promiseNextPing();
 
   checkPingFormat(ping, PING_TYPE_MAIN, true, true);
 
   // Check that we get the data we expect.
   let payload = ping.payload;