Bug 841244 - More Telemetry probes for Firefox Health Report. r=rnewman,gps,vladan
authorGregory Szorc <gps@mozilla.com>
Mon, 18 Feb 2013 12:45:53 -0800
changeset 132128 6e0f106fd859046a1d5dbad9c5dd5df33f464e94
parent 132127 584660a01e6411e8c0089b900863b3514437dd57
child 132129 7da1d0ed25d7b57d9d4b8ea8b15f53e8da566d38
push id2323
push userbbajaj@mozilla.com
push dateMon, 01 Apr 2013 19:47:02 +0000
treeherdermozilla-beta@7712be144d91 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersrnewman, gps, vladan
bugs841244
milestone21.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 841244 - More Telemetry probes for Firefox Health Report. r=rnewman,gps,vladan
services/healthreport/healthreporter.jsm
toolkit/components/telemetry/Histograms.json
--- a/services/healthreport/healthreporter.jsm
+++ b/services/healthreport/healthreporter.jsm
@@ -33,21 +33,28 @@ Cu.import("resource://gre/modules/XPCOMU
 // 2012 and no dates older than that should be encountered.
 const OLDEST_ALLOWED_YEAR = 2012;
 
 const DAYS_IN_PAYLOAD = 180;
 
 const DEFAULT_DATABASE_NAME = "healthreport.sqlite";
 
 const TELEMETRY_INIT = "HEALTHREPORT_INIT_MS";
+const TELEMETRY_INIT_FIRSTRUN = "HEALTHREPORT_INIT_FIRSTRUN_MS";
+const TELEMETRY_DB_OPEN = "HEALTHREPORT_DB_OPEN_MS";
+const TELEMETRY_DB_OPEN_FIRSTRUN = "HEALTHREPORT_DB_OPEN_FIRSTRUN_MS";
 const TELEMETRY_GENERATE_PAYLOAD = "HEALTHREPORT_GENERATE_JSON_PAYLOAD_MS";
+const TELEMETRY_JSON_PAYLOAD_SERIALIZE = "HEALTHREPORT_JSON_PAYLOAD_SERIALIZE_MS";
 const TELEMETRY_PAYLOAD_SIZE = "HEALTHREPORT_PAYLOAD_UNCOMPRESSED_BYTES";
 const TELEMETRY_SAVE_LAST_PAYLOAD = "HEALTHREPORT_SAVE_LAST_PAYLOAD_MS";
 const TELEMETRY_UPLOAD = "HEALTHREPORT_UPLOAD_MS";
 const TELEMETRY_SHUTDOWN_DELAY = "HEALTHREPORT_SHUTDOWN_DELAY_MS";
+const TELEMETRY_COLLECT_CONSTANT = "HEALTHREPORT_COLLECT_CONSTANT_DATA_MS";
+const TELEMETRY_COLLECT_DAILY = "HEALTHREPORT_COLLECT_DAILY_MS";
+const TELEMETRY_SHUTDOWN = "HEALTHREPORT_SHUTDOWN_MS";
 
 /**
  * This is the abstract base class of `HealthReporter`. It exists so that
  * we can sanely divide work on platforms where control of Firefox Health
  * Report is outside of Gecko (e.g., Android).
  */
 function AbstractHealthReporter(branch, policy, sessionRecorder) {
   if (!branch.endsWith(".")) {
@@ -81,17 +88,21 @@ function AbstractHealthReporter(branch, 
   this._shutdownComplete = false;
   this._shutdownCompleteCallback = null;
 
   this._constantOnlyProviders = {};
   this._constantOnlyProvidersRegistered = false;
   this._lastDailyDate = null;
 
   // Yes, this will probably run concurrently with remaining constructor work.
-  TelemetryStopwatch.start(TELEMETRY_INIT, this);
+  let hasFirstRun = this._prefs.get("service.firstRun", false);
+  this._initHistogram = hasFirstRun ? TELEMETRY_INIT : TELEMETRY_INIT_FIRSTRUN;
+  this._dbOpenHistogram = hasFirstRun ? TELEMETRY_DB_OPEN : TELEMETRY_DB_OPEN_FIRSTRUN;
+
+  TelemetryStopwatch.start(this._initHistogram, this);
 
   this._ensureDirectoryExists(this._stateDir)
       .then(this._onStateDirCreated.bind(this),
             this._onInitError.bind(this));
 }
 
 AbstractHealthReporter.prototype = Object.freeze({
   QueryInterface: XPCOMUtils.generateQI([Ci.nsIObserver]),
@@ -107,17 +118,21 @@ AbstractHealthReporter.prototype = Objec
 
   //----------------------------------------------------
   // SERVICE CONTROL FUNCTIONS
   //
   // You shouldn't need to call any of these externally.
   //----------------------------------------------------
 
   _onInitError: function (error) {
-    TelemetryStopwatch.cancel(TELEMETRY_INIT, this);
+    TelemetryStopwatch.cancel(this._initHistogram, this);
+    TelemetryStopwatch.cancel(this._dbOpenHistogram, this);
+    delete this._initHistogram;
+    delete this._dbOpenHistogram;
+
     this._log.error("Error during initialization: " +
                     CommonUtils.exceptionStr(error));
     this._initializeHadError = true;
     this._initiateShutdown();
     this._initializedDeferred.reject(error);
 
     // FUTURE consider poisoning prototype's functions so calls fail with a
     // useful error message.
@@ -125,22 +140,25 @@ AbstractHealthReporter.prototype = Objec
 
   _onStateDirCreated: function () {
     // As soon as we have could storage, we need to register cleanup or
     // else bad things happen on shutdown.
     Services.obs.addObserver(this, "quit-application", false);
     Services.obs.addObserver(this, "profile-before-change", false);
 
     this._storageInProgress = true;
+    TelemetryStopwatch.start(this._dbOpenHistogram, this);
     Metrics.Storage(this._dbName).then(this._onStorageCreated.bind(this),
                                        this._onInitError.bind(this));
   },
 
   // Called when storage has been opened.
   _onStorageCreated: function (storage) {
+    TelemetryStopwatch.finish(this._dbOpenHistogram, this);
+    delete this._dbOpenHistogram;
     this._log.info("Storage initialized.");
     this._storage = storage;
     this._storageInProgress = false;
 
     if (this._shutdownRequested) {
       this._initiateShutdown();
       return;
     }
@@ -163,17 +181,18 @@ AbstractHealthReporter.prototype = Objec
     if (catString.length) {
       for (let category of catString.split(",")) {
         yield this.registerProvidersFromCategoryManager(category);
       }
     }
   },
 
   _onCollectorInitialized: function () {
-    TelemetryStopwatch.finish(TELEMETRY_INIT, this);
+    TelemetryStopwatch.finish(this._initHistogram, this);
+    delete this._initHistogram;
     this._log.debug("Collector initialized.");
     this._collectorInProgress = false;
 
     if (this._shutdownRequested) {
       this._initiateShutdown();
       return;
     }
 
@@ -229,16 +248,18 @@ AbstractHealthReporter.prototype = Objec
       this._log.warn("Storage is in progress of initializing. Waiting to finish.");
       return;
     }
 
     this._log.warn("Initiating main shutdown procedure.");
 
     // Everything from here must only be performed once or else race conditions
     // could occur.
+
+    TelemetryStopwatch.start(TELEMETRY_SHUTDOWN, this);
     this._shutdownInitiated = true;
 
     // We may not have registered the observer yet. If not, this will
     // throw.
     try {
       Services.obs.removeObserver(this, "idle-daily");
     } catch (ex) { }
 
@@ -292,16 +313,17 @@ AbstractHealthReporter.prototype = Objec
 
     this._storage = null;
     this._onShutdownComplete();
   },
 
   _onShutdownComplete: function () {
     this._log.warn("Shutdown complete.");
     this._shutdownComplete = true;
+    TelemetryStopwatch.finish(TELEMETRY_SHUTDOWN, this);
 
     if (this._shutdownCompleteCallback) {
       this._shutdownCompleteCallback();
     }
   },
 
   _waitForShutdown: function () {
     if (this._shutdownComplete) {
@@ -543,35 +565,41 @@ AbstractHealthReporter.prototype = Objec
   },
 
   /**
    * Collect all measurements for all registered providers.
    */
   collectMeasurements: function () {
     return Task.spawn(function doCollection() {
       try {
+        TelemetryStopwatch.start(TELEMETRY_COLLECT_CONSTANT, this);
         yield this._collector.collectConstantData();
+        TelemetryStopwatch.finish(TELEMETRY_COLLECT_CONSTANT, this);
       } catch (ex) {
+        TelemetryStopwatch.cancel(TELEMETRY_COLLECT_CONSTANT, this);
         this._log.warn("Error collecting constant data: " +
                        CommonUtils.exceptionStr(ex));
       }
 
       // Daily data is collected if it hasn't yet been collected this
       // application session or if it has been more than a day since the
       // last collection. This means that providers could see many calls to
       // collectDailyData per calendar day. However, this collection API
       // makes no guarantees about limits. The alternative would involve
       // recording state. The simpler implementation prevails for now.
       if (!this._lastDailyDate ||
           Date.now() - this._lastDailyDate > MILLISECONDS_PER_DAY) {
 
         try {
+          TelemetryStopwatch.start(TELEMETRY_COLLECT_DAILY, this);
           this._lastDailyDate = new Date();
           yield this._collector.collectDailyData();
+          TelemetryStopwatch.finish(TELEMETRY_COLLECT_DAILY, this);
         } catch (ex) {
+          TelemetryStopwatch.cancel(TELEMETRY_COLLECT_DAILY, this);
           this._log.warn("Error collecting daily data from providers: " +
                          CommonUtils.exceptionStr(ex));
         }
       }
 
       throw new Task.Result();
     }.bind(this));
   },
@@ -745,17 +773,23 @@ AbstractHealthReporter.prototype = Objec
     }
 
     if (errors.length) {
       o.errors = errors;
     }
 
     this._storage.compact();
 
-    throw new Task.Result(asObject ? o : JSON.stringify(o));
+    if (!asObject) {
+      TelemetryStopwatch.start(TELEMETRY_JSON_PAYLOAD_SERIALIZE, this);
+      o = JSON.stringify(o);
+      TelemetryStopwatch.finish(TELEMETRY_JSON_PAYLOAD_SERIALIZE, this);
+    }
+
+    throw new Task.Result(o);
   },
 
   get _stateDir() {
     let profD = OS.Constants.Path.profileDir;
 
     // Work around bug 810543 until OS.File is more resilient.
     if (!profD || !profD.length) {
       throw new Error("Could not obtain profile directory. OS.File not " +
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -2834,16 +2834,34 @@
   },
   "SSL_INITIAL_FAILED_CERT_VALIDATION_TIME_CLASSIC" : {
     "kind": "exponential",
     "high": "60000",
     "n_buckets": 50,
     "extended_statistics_ok": true,
     "description": "Time spent on an initially failed cert  verification in classic mode (ms)"
   },
+  "HEALTHREPORT_DB_OPEN_FIRSTRUN_MS": {
+    "kind": "exponential",
+    "high": "20000",
+    "n_buckets": 15,
+    "description": "Time (ms) spent to open Firefox Health Report's database the first time, including schema setup."
+  },
+  "HEALTHREPORT_DB_OPEN_MS": {
+    "kind": "exponential",
+    "high": "20000",
+    "n_buckets": 15,
+    "description": "Time (ms) spent to open Firefox Health Report's database."
+  },
+  "HEALTHREPORT_INIT_FIRSTRUN_MS": {
+    "kind": "exponential",
+    "high": "20000",
+    "n_buckets": 15,
+    "description": "Time (ms) spent to initialize Firefox Health Report the first time, including provider and collector initialization."
+  },
   "HEALTHREPORT_INIT_MS": {
     "kind": "exponential",
     "high": "20000",
     "n_buckets": 15,
     "extended_statistics_ok": true,
     "description": "Time (ms) spent to initialize Firefox Health Report service."
   },
   "HEALTHREPORT_SHUTDOWN_DELAY_MS": {
@@ -2855,16 +2873,22 @@
   },
   "HEALTHREPORT_GENERATE_JSON_PAYLOAD_MS": {
     "kind": "exponential",
     "high": "30000",
     "n_buckets": 20,
     "extended_statistics_ok": true,
     "description": "Time (ms) it takes to obtain and format a Health Report JSON payload."
   },
+  "HEALTHREPORT_JSON_PAYLOAD_SERIALIZE_MS": {
+    "kind": "exponential",
+    "high": "5000",
+    "n_buckets": 10,
+    "description": "Time (ms) it takes to JSON.stringify() the FHR JSON payload."
+  },
   "HEALTHREPORT_PAYLOAD_UNCOMPRESSED_BYTES": {
     "kind": "linear",
     "high": "2000000",
     "n_buckets": 202,
     "description": "Size (in bytes) of the raw Health Report payload."
   },
   "HEALTHREPORT_UPLOAD_MS": {
     "kind": "exponential",
@@ -2875,16 +2899,34 @@
   },
   "HEALTHREPORT_SAVE_LAST_PAYLOAD_MS": {
     "kind": "exponential",
     "high": "10000",
     "n_buckets": 10,
     "extended_statistics_ok": true,
     "description": "Time (ms) it takes to persist the last submitted Health Report payload to disk."
   },
+  "HEALTHREPORT_COLLECT_CONSTANT_DATA_MS": {
+    "kind": "exponential",
+    "high": "20000",
+    "n_buckets": 15,
+    "description": "Time (ms) it takes FHR to collect constant data."
+  },
+  "HEALTHREPORT_COLLECT_DAILY_MS": {
+    "kind": "exponential",
+    "high": "20000",
+    "n_buckets": 15,
+    "description": "Time (ms) it takes FHR to collect daily data."
+  },
+  "HEALTHREPORT_SHUTDOWN_MS": {
+    "kind": "exponential",
+    "high": "20000",
+    "n_buckets": 15,
+    "description": "Time (ms) it takes FHR to shut down."
+  },
   "POPUP_NOTIFICATION_MAINACTION_TRIGGERED_MS": {
     "kind": "linear",
     "low": 25,
     "high": "80 * 25",
     "n_buckets": "80 + 1",
     "description": "The time (in milliseconds) after showing a PopupNotification that the mainAction was first triggered"
   }
 }