Bug 1188416 - Use monotonic clocks for Telemetry subsessionLength. r=dexter
--- 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;