Bug 826893 - Health Report provider for application sessions; r=rnewman
authorGregory Szorc <gps@mozilla.com>
Sun, 06 Jan 2013 12:24:26 -0800
changeset 117845 36592fb313ada1629fe3b7b00866e75d52938f0d
parent 117844 d4ce01fb62551508ec19742b8143db19de5d6d90
child 117846 66786ce0c5fb77dee8e985da64b45e3f25025d8f
push id24116
push usergszorc@mozilla.com
push dateMon, 07 Jan 2013 08:22:48 +0000
treeherdermozilla-central@66d595814554 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersrnewman
bugs826893
milestone20.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 826893 - Health Report provider for application sessions; r=rnewman
services/healthreport/HealthReportComponents.manifest
services/healthreport/providers.jsm
services/healthreport/tests/xpcshell/test_provider_sessions.js
services/healthreport/tests/xpcshell/xpcshell.ini
--- a/services/healthreport/HealthReportComponents.manifest
+++ b/services/healthreport/HealthReportComponents.manifest
@@ -7,9 +7,10 @@
 
 component {e354c59b-b252-4040-b6dd-b71864e3e35c} HealthReportService.js
 contract @mozilla.org/healthreport/service;1 {e354c59b-b252-4040-b6dd-b71864e3e35c}
 category app-startup HealthReportService service,@mozilla.org/healthreport/service;1 application={3c2e2abc-06d4-11e1-ac3b-374f68613e61} application={ec8030f7-c20a-464f-9b0e-13a3a9e97384} application={aa3c5121-dab2-40e2-81ca-7ea25febc110} application={a23983c0-fd0e-11dc-95ff-0800200c9a66}
 
 category healthreport-js-provider AppInfoProvider resource://gre/modules/services/healthreport/providers.jsm
 category healthreport-js-provider SysInfoProvider resource://gre/modules/services/healthreport/providers.jsm
 category healthreport-js-provider ProfileMetadataProvider resource://gre/modules/services/healthreport/profile.jsm
+category healthreport-js-provider SessionsProvider resource://gre/modules/services/healthreport/providers.jsm
 
--- a/services/healthreport/providers.jsm
+++ b/services/healthreport/providers.jsm
@@ -11,16 +11,17 @@
  * compartments reaches a reasonable level, this file should be split
  * up.
  */
 
 "use strict";
 
 this.EXPORTED_SYMBOLS = [
   "AppInfoProvider",
+  "SessionsProvider",
   "SysInfoProvider",
 ];
 
 const {classes: Cc, interfaces: Ci, utils: Cu} = Components;
 
 Cu.import("resource://gre/modules/Metrics.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 Cu.import("resource://gre/modules/Task.jsm");
@@ -88,16 +89,17 @@ AppVersionMeasurement.prototype = Object
 
   configureStorage: function () {
     return this.registerStorageField("version",
                                      this.storage.FIELD_DAILY_DISCRETE_TEXT);
   },
 });
 
 
+
 this.AppInfoProvider = function AppInfoProvider() {
   Metrics.Provider.call(this);
 
   this._prefs = new Preferences({defaultBranch: null});
 }
 AppInfoProvider.prototype = Object.freeze({
   __proto__: Metrics.Provider.prototype,
 
@@ -305,8 +307,306 @@ SysInfoProvider.prototype = Object.freez
       } catch (ex) {
         this._log.warn("Error obtaining system info field: " + k + " " +
                        CommonUtils.exceptionStr(ex));
       }
     }
   },
 });
 
+
+/**
+ * Holds information about the current/active session.
+ *
+ * The fields within the current session are moved to daily session fields when
+ * the application is shut down.
+ */
+function CurrentSessionMeasurement() {
+  Metrics.Measurement.call(this);
+}
+
+CurrentSessionMeasurement.prototype = Object.freeze({
+  __proto__: Metrics.Measurement.prototype,
+
+  name: "current",
+  version: 1,
+
+  LAST_NUMERIC_FIELDS: [
+    // Day on which the session was started.
+    // This is used to determine which day the record will be moved under when
+    // moved to daily sessions.
+    "startDay",
+
+    // Time in milliseconds the session was active for.
+    "activeTime",
+
+    // Total time in milliseconds of the session.
+    "totalTime",
+
+    // Startup times, in milliseconds.
+    "main",
+    "firstPaint",
+    "sessionRestored",
+  ],
+
+  configureStorage: function () {
+    return Task.spawn(function configureStorage() {
+      for (let field of this.LAST_NUMERIC_FIELDS) {
+        yield this.registerStorageField(field, this.storage.FIELD_LAST_NUMERIC);
+      }
+    }.bind(this));
+  },
+});
+
+
+/**
+ * Records a history of all application sessions.
+ */
+function PreviousSessionsMeasurement() {
+  Metrics.Measurement.call(this);
+}
+
+PreviousSessionsMeasurement.prototype = Object.freeze({
+  __proto__: Metrics.Measurement.prototype,
+
+  name: "previous",
+  version: 1,
+
+  DAILY_DISCRETE_NUMERIC_FIELDS: [
+    // Milliseconds of sessions that were properly shut down.
+    "cleanActiveTime",
+    "cleanTotalTime",
+
+    // Milliseconds of sessions that were not properly shut down.
+    "abortedActiveTime",
+    "abortedTotalTime",
+
+    // Startup times in milliseconds.
+    "main",
+    "firstPaint",
+    "sessionRestored",
+  ],
+
+  configureStorage: function () {
+    return Task.spawn(function configureStorage() {
+      for (let field of this.DAILY_DISCRETE_NUMERIC_FIELDS) {
+        yield this.registerStorageField(field, this.storage.FIELD_DAILY_DISCRETE_NUMERIC);
+      }
+    }.bind(this));
+  },
+});
+
+
+/**
+ * Records information about the current browser session.
+ *
+ * A browser session is defined as an application/process lifetime. We
+ * start a new session when the application starts (essentially when
+ * this provider is instantiated) and end the session on shutdown.
+ *
+ * As the application runs, we record basic information about the
+ * "activity" of the session. Activity is defined by the presence of
+ * physical input into the browser (key press, mouse click, touch, etc).
+ *
+ * We differentiate between regular sessions and "aborted" sessions. An
+ * aborted session is one that does not end expectedly. This is often the
+ * result of a crash. We detect aborted sessions by storing the current
+ * session separate from completed sessions. We normally move the
+ * current session to completed sessions on application shutdown. If a
+ * current session is present on application startup, that means that
+ * the previous session was aborted.
+ */
+this.SessionsProvider = function () {
+  Metrics.Provider.call(this);
+
+  this._startDate = null;
+  this._currentActiveTime = null;
+  this._lastActivityDate = null;
+  this._lastActivityWasInactive = false;
+};
+
+SessionsProvider.prototype = Object.freeze({
+  __proto__: Metrics.Provider.prototype,
+
+  name: "org.mozilla.appSessions",
+
+  measurementTypes: [CurrentSessionMeasurement, PreviousSessionsMeasurement],
+
+  _OBSERVERS: ["user-interaction-active", "user-interaction-inactive"],
+
+  onInit: function () {
+    return Task.spawn(this._onInit.bind(this));
+  },
+
+  _onInit: function () {
+    // We could cross day boundary between the application started and when
+    // this code is called. Meh.
+    let now = new Date();
+    this._startDate = now;
+    let current = this.getMeasurement("current", 1);
+
+    // Initialization occurs serially so we don't need to enqueue
+    // storage operations.
+    let currentData = yield this.storage.getMeasurementLastValuesFromMeasurementID(current.id);
+
+    // Normal shutdown should purge all data for this measurement. If
+    // there is data here, the session was aborted.
+    if (currentData.size) {
+      this._log.info("Data left over from old session. Counting as aborted.");
+      yield Task.spawn(this._moveCurrentToDaily.bind(this, currentData, true));
+    }
+
+    this._currentActiveTime = 0;
+    this._lastActivityDate = now;
+
+    this._log.debug("Registering new/current session.");
+    yield current.setLastNumeric("activeTime", 0, now);
+    yield current.setLastNumeric("totalTime", 0, now);
+    yield current.setLastNumeric("startDay", this._dateToDays(now), now);
+
+    let si = this._getStartupInfo();
+
+    for (let field of ["main", "firstPaint", "sessionRestored"]) {
+      if (!(field in si)) {
+        continue;
+      }
+
+      // si.process is the Date when the process actually started.
+      let value = si[field] - si.process;
+      yield current.setLastNumeric(field, value, now);
+    }
+
+    for (let channel of this._OBSERVERS) {
+      Services.obs.addObserver(this, channel, false);
+    }
+  },
+
+  onShutdown: function () {
+    for (let channel of this._OBSERVERS) {
+      Services.obs.removeObserver(this, channel);
+    }
+
+    return Task.spawn(this._onShutdown.bind(this));
+  },
+
+  _onShutdown: function () {
+    this._log.debug("Recording clean shutdown.");
+    yield this.recordBrowserActivity(true);
+    let current = this.getMeasurement("current", 1);
+
+    let self = this;
+    yield this.enqueueStorageOperation(function doShutdown() {
+      return Task.spawn(function shutdownTask() {
+        let data = yield self.storage.getMeasurementLastValuesFromMeasurementID(current.id);
+        yield self._moveCurrentToDaily(data, false);
+      });
+    });
+  },
+
+  /**
+   * Record browser activity.
+   *
+   * This should be called periodically to update the stored times of how often
+   * the user was active with the browser.
+   *
+   * The underlying browser activity observer fires every 5 seconds if there
+   * is activity. If there is inactivity, it fires after 5 seconds of inactivity
+   * and doesn't fire again until there is activity.
+   *
+   * @param active
+   *        (bool) Whether the browser was active or inactive.
+   */
+  recordBrowserActivity: function (active) {
+    // There is potential for clock skew to result in incorrect measurements
+    // here. We should count ticks instead of calculating intervals.
+    // FUTURE count ticks not intervals.
+    let now = new Date();
+    this._log.trace("Recording browser activity. Active? " + !!active);
+
+    let m = this.getMeasurement("current", 1);
+
+    let updateActive = active && !this._lastActivityWasInactive;
+    this._lastActivityWasInactive = !active;
+
+    if (updateActive) {
+      this._currentActiveTime += now - this._lastActivityDate;
+    }
+
+    this._lastActivityDate = now;
+
+    let totalTime = now - this._startDate;
+    let activeTime = this._currentActiveTime;
+
+    return this.enqueueStorageOperation(function op() {
+      let promise = m.setLastNumeric("totalTime", totalTime, now);
+
+      if (!updateActive) {
+        return promise;
+      }
+
+      return m.setLastNumeric("activeTime", activeTime, now);
+    });
+  },
+
+  _moveCurrentToDaily: function (fields, aborted) {
+    this._log.debug("Moving current session to past. Aborted? " + aborted);
+    let current = this.getMeasurement("current", 1);
+
+    function clearCurrent() {
+      current.deleteLastNumeric("startDay");
+      current.deleteLastNumeric("activeTime");
+      current.deleteLastNumeric("totalTime");
+      current.deleteLastNumeric("main");
+      current.deleteLastNumeric("firstPaint");
+      return current.deleteLastNumeric("sessionRestored");
+    }
+
+    // We should never have incomplete values. But if we do, handle it
+    // gracefully.
+    if (!fields.has("startDay") || !fields.has("activeTime") || !fields.has("totalTime")) {
+      yield clearCurrent();
+      return;
+    }
+
+    let daily = this.getMeasurement("previous", 1);
+
+    let startDays = fields.get("startDay")[1];
+    let activeTime = fields.get("activeTime")[1];
+    let totalTime = fields.get("totalTime")[1];
+
+    let date = this._daysToDate(startDays);
+    let type = aborted ? "aborted" : "clean";
+
+    yield daily.addDailyDiscreteNumeric(type + "ActiveTime", activeTime, date);
+    yield daily.addDailyDiscreteNumeric(type + "TotalTime", totalTime, date);
+
+    for (let field of ["main", "firstPaint", "sessionRestored"]) {
+      if (!fields.has(field)) {
+        this._log.info(field + " field not recorded for current session.");
+        continue;
+      }
+
+      yield daily.addDailyDiscreteNumeric(field, fields.get(field)[1], date);
+    }
+
+    yield clearCurrent();
+  },
+
+  observe: function (subject, topic, data) {
+    switch (topic) {
+      case "user-interaction-active":
+        this.recordBrowserActivity(true);
+        break;
+
+      case "user-interaction-inactive":
+        this.recordBrowserActivity(false);
+        break;
+    }
+  },
+
+  // Implemented as a function to allow for monkeypatching in tests.
+  _getStartupInfo: function () {
+    return Cc["@mozilla.org/toolkit/app-startup;1"]
+             .getService(Ci.nsIAppStartup)
+             .getStartupInfo();
+  },
+});
+
new file mode 100644
--- /dev/null
+++ b/services/healthreport/tests/xpcshell/test_provider_sessions.js
@@ -0,0 +1,208 @@
+/* Any copyright is dedicated to the Public Domain.
+ * http://creativecommons.org/publicdomain/zero/1.0/ */
+
+"use strict";
+
+const {utils: Cu} = Components;
+
+
+Cu.import("resource://gre/modules/commonjs/promise/core.js");
+Cu.import("resource://gre/modules/Metrics.jsm");
+Cu.import("resource://gre/modules/Services.jsm");
+Cu.import("resource://gre/modules/Task.jsm");
+Cu.import("resource://gre/modules/services-common/utils.js");
+Cu.import("resource://gre/modules/services/healthreport/providers.jsm");
+
+
+function run_test() {
+  run_next_test();
+}
+
+add_test(function test_constructor() {
+  let provider = new SessionsProvider();
+
+  run_next_test();
+});
+
+add_task(function test_init() {
+  let storage = yield Metrics.Storage("init");
+  let provider = new SessionsProvider();
+  yield provider.init(storage);
+  yield provider.shutdown();
+
+  yield storage.close();
+});
+
+function getProvider(name, now=new Date()) {
+  return Task.spawn(function () {
+    let storage = yield Metrics.Storage(name);
+    let provider = new SessionsProvider();
+    monkeypatchStartupInfo(provider, now);
+    yield provider.init(storage);
+
+    throw new Task.Result([provider, storage]);
+  });
+}
+
+function monkeypatchStartupInfo(provider, start=new Date(), offset=500) {
+  Object.defineProperty(provider, "_getStartupInfo", {
+    value: function _getStartupInfo() {
+      return {
+        process: start,
+        main: new Date(start.getTime() + offset),
+        firstPaint: new Date(start.getTime() + 2 * offset),
+        sessionRestored: new Date(start.getTime() + 3 * offset),
+      };
+    }
+  });
+}
+
+add_task(function test_record_current_on_init() {
+  let [provider, storage] = yield getProvider("record_current_on_init");
+
+  let now = new Date();
+
+  let current = provider.getMeasurement("current", 1);
+  let values = yield current.getValues();
+  let fields = values.singular;
+  do_check_eq(fields.size, 6);
+  do_check_eq(fields.get("main")[1], 500);
+  do_check_eq(fields.get("firstPaint")[1], 1000);
+  do_check_eq(fields.get("sessionRestored")[1], 1500);
+  do_check_eq(fields.get("startDay")[1], provider._dateToDays(now));
+  do_check_eq(fields.get("activeTime")[1], 0);
+  do_check_eq(fields.get("totalTime")[1], 0);
+
+  yield provider.shutdown();
+  yield storage.close();
+});
+
+add_task(function test_current_moved_on_shutdown() {
+  let [provider, storage] = yield getProvider("current_moved_on_shutdown");
+  let now = new Date();
+
+  let previous = provider.getMeasurement("previous", 1);
+
+  yield provider.shutdown();
+
+  // This relies on undocumented behavior of the underlying measurement not
+  // being invalidated on provider shutdown. If this breaks, we should rewrite
+  // the test and not hold up implementation changes.
+  let values = yield previous.getValues();
+  do_check_eq(values.days.size, 1);
+  do_check_true(values.days.hasDay(now));
+  let fields = values.days.getDay(now);
+
+  // 3 startup + 2 clean.
+  do_check_eq(fields.size, 5);
+  for (let field of ["cleanActiveTime", "cleanTotalTime", "main", "firstPaint", "sessionRestored"]) {
+    do_check_true(fields.has(field));
+    do_check_true(Array.isArray(fields.get(field)));
+    do_check_eq(fields.get(field).length, 1);
+  }
+
+  do_check_eq(fields.get("main")[0], 500);
+  do_check_eq(fields.get("firstPaint")[0], 1000);
+  do_check_eq(fields.get("sessionRestored")[0], 1500);
+  do_check_true(fields.get("cleanActiveTime")[0] > 0);
+  do_check_true(fields.get("cleanTotalTime")[0] > 0);
+
+  yield storage.close();
+});
+
+add_task(function test_detect_abort() {
+  let [provider, storage] = yield getProvider("detect_abort");
+
+  let now = new Date();
+
+  let m = provider.getMeasurement("current", 1);
+  let original = yield m.getValues().singular;
+
+  let provider2 = new SessionsProvider();
+  monkeypatchStartupInfo(provider2);
+  yield provider2.init(storage);
+
+  let previous = provider.getMeasurement("previous", 1);
+  let values = yield previous.getValues();
+  do_check_true(values.days.hasDay(now));
+  let day = values.days.getDay(now);
+  do_check_eq(day.size, 5);
+  do_check_true(day.has("abortedActiveTime"));
+  do_check_true(day.has("abortedTotalTime"));
+  do_check_eq(day.get("abortedActiveTime")[0], 0);
+  do_check_eq(day.get("abortedTotalTime")[0], 0);
+
+  yield provider.shutdown();
+  yield provider2.shutdown();
+  yield storage.close();
+});
+
+// This isn't a perfect test because we only simulate the observer
+// notifications. We should probably supplement this with a mochitest.
+add_task(function test_record_browser_activity() {
+  let [provider, storage] = yield getProvider("record_browser_activity");
+
+  function waitOnDB () {
+    return provider.enqueueStorageOperation(function () {
+      return storage._connection.execute("SELECT 1");
+    });
+  }
+
+  let current = provider.getMeasurement("current", 1);
+
+  Services.obs.notifyObservers(null, "user-interaction-active", null);
+  yield waitOnDB();
+
+  let values = yield current.getValues();
+  let fields = values.singular;
+  let activeTime = fields.get("activeTime")[1];
+  let totalTime = fields.get("totalTime")[1];
+
+  do_check_eq(activeTime, totalTime);
+  do_check_true(activeTime > 0);
+
+  // Another active should have similar effects.
+  Services.obs.notifyObservers(null, "user-interaction-active", null);
+  yield waitOnDB();
+
+  values = yield current.getValues();
+  fields = values.singular;
+
+  do_check_true(fields.get("activeTime")[1] > activeTime);
+  activeTime = fields.get("activeTime")[1];
+  totalTime = fields.get("totalTime")[1];
+  do_check_eq(activeTime, totalTime);
+
+  // Now send inactive. We should increment total time but not active.
+  Services.obs.notifyObservers(null, "user-interaction-inactive", null);
+  yield waitOnDB();
+  values = yield current.getValues();
+  fields = values.singular;
+  do_check_eq(fields.get("activeTime")[1], activeTime);
+  totalTime = fields.get("totalTime")[1];
+  do_check_true(totalTime > activeTime);
+
+  // If we send an active again, this should be counted as inactive.
+  Services.obs.notifyObservers(null, "user-interaction-active", null);
+  yield waitOnDB();
+  values = yield current.getValues();
+  fields = values.singular;
+
+  do_check_eq(fields.get("activeTime")[1], activeTime);
+  do_check_true(fields.get("totalTime")[1] > totalTime);
+  do_check_neq(fields.get("activeTime")[1], fields.get("totalTime")[1]);
+  activeTime = fields.get("activeTime")[1];
+  totalTime = fields.get("totalTime")[1];
+
+  // Another active should increment active this time.
+  Services.obs.notifyObservers(null, "user-interaction-active", null);
+  yield waitOnDB();
+  values = yield current.getValues();
+  fields = values.singular;
+  do_check_true(fields.get("activeTime")[1] > activeTime);
+  do_check_true(fields.get("totalTime")[1] > totalTime);
+
+  yield provider.shutdown();
+  yield storage.close();
+});
+
--- a/services/healthreport/tests/xpcshell/xpcshell.ini
+++ b/services/healthreport/tests/xpcshell/xpcshell.ini
@@ -3,9 +3,10 @@ head = head.js
 tail =
 
 [test_load_modules.js]
 [test_profile.js]
 [test_policy.js]
 [test_healthreporter.js]
 [test_provider_appinfo.js]
 [test_provider_sysinfo.js]
+[test_provider_sessions.js]