Bug 1188416 - Use monotonic clocks for Telemetry subsessionLength. r=dexter

toolkit/components/telemetry/TelemetrySession.jsm

@@ -162,11 +162,21 @@ function generateUUID() {
   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),
@@ -710,6 +720,7 @@ this.TelemetrySession = Object.freeze({
     Impl._subsessionCounter = 0;
     Impl._profileSubsessionCounter = 0;
     Impl._subsessionStartActiveTicks = 0;
+    Impl._subsessionStartTimeMonotonic = 0;
     this.uninstall();
     return this.setup();
   },
@@ -795,6 +806,9 @@ let Impl = {
   _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
@@ -1079,11 +1093,9 @@ let Impl = {
   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,
@@ -1105,7 +1117,13 @@ let Impl = {
 
       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.
@@ -1334,6 +1352,7 @@ let Impl = {
    */
   startNewSubsession: function () {
     this._subsessionStartDate = Policy.now();
+    this._subsessionStartTimeMonotonic = Policy.monotonicNow();
     this._previousSubsessionId = this._subsessionId;
     this._subsessionId = Policy.generateSubsessionUUID();
     this._subsessionCounter++;

toolkit/components/telemetry/docs/main-ping.rst

@@ -39,7 +39,8 @@ Structure::
 
         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
@@ -58,3 +59,21 @@ Structure::
       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.

toolkit/components/telemetry/tests/unit/head.js

@@ -248,6 +248,12 @@ function fakeNow(...args) {
   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");

toolkit/components/telemetry/tests/unit/test_TelemetrySession.js

@@ -519,6 +519,7 @@ add_task(function* test_simplePing() {
   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";
@@ -529,6 +530,7 @@ add_task(function* test_simplePing() {
   // 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();