Bug 1188416 - Use monotonic clocks for Telemetry subsessionLength. r=dexter
authorGeorg Fritzsche <georg.fritzsche@googlemail.com>
Wed, 29 Jul 2015 14:47:01 +0200
changeset 286870 48e058ea4b7409ca33d16c74ee826f56ec970af9
parent 286869 053724fc9915da2c50ee97596c6198369c6d8db0
child 286871 82fac7af188e0d8b7e6f2678cb2f3e4bf7c919b3
push id5067
push userraliiev@mozilla.com
push dateMon, 21 Sep 2015 14:04:52 +0000
treeherdermozilla-beta@14221ffe5b2f [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersdexter
bugs1188416
milestone42.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 1188416 - Use monotonic clocks for Telemetry subsessionLength. r=dexter
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;