Bug 671041 - batch 'o telemetry metrics for session restore.

r=zpao

browser/components/sessionstore/src/nsSessionStartup.js

@@ -72,6 +72,7 @@ const Cr = Components.results;
 const Cu = Components.utils;
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
+Cu.import("resource:///modules/TelemetryStopwatch.jsm");
 
 const STATE_RUNNING_STR = "running";
 const MAX_FILE_SIZE = 100 * 1024 * 1024; // 100 megabytes
@@ -127,23 +128,30 @@ SessionStartup.prototype = {
       return;
 
     // parse the session state into a JS object
+    // remove unneeded braces (added for compatibility with Firefox 2.0 and 3.0)
+    if (iniString.charAt(0) == '(')
+      iniString = iniString.slice(1, -1);
+    let corruptFile = false;
     try {
-      // remove unneeded braces (added for compatibility with Firefox 2.0 and 3.0)
+      this._initialState = JSON.parse(iniString);
-      if (iniString.charAt(0) == '(')
+    }
-        iniString = iniString.slice(1, -1);
+    catch (ex) {
+      debug("The session file contained un-parse-able JSON: " + ex);
+      // Try to eval.
+      // evalInSandbox will throw if iniString is not parse-able.
       try {
-        this._initialState = JSON.parse(iniString);
-      }
-      catch (exJSON) {
         var s = new Cu.Sandbox("about:blank", {sandboxName: 'nsSessionStartup'});
         this._initialState = Cu.evalInSandbox("(" + iniString + ")", s);
+      } catch(ex) {
+        debug("The session file contained un-eval-able JSON: " + ex);
+        corruptFile = true;
       }
-
-      // If this is a normal restore then throw away any previous session
-      if (!doResumeSessionOnce)
-        delete this._initialState.lastSessionState;
     }
-    catch (ex) { debug("The session file is invalid: " + ex); }
+    Services.telemetry.getHistogramById("FX_SESSION_RESTORE_CORRUPT_FILE").add(corruptFile);
+
+    // If this is a normal restore then throw away any previous session
+    if (!doResumeSessionOnce)
+      delete this._initialState.lastSessionState;
 
     let resumeFromCrash = prefBranch.getBoolPref("sessionstore.resume_from_crash");
     let lastSessionCrashed =
@@ -154,8 +162,7 @@ SessionStartup.prototype = {
     // Report shutdown success via telemetry. Shortcoming here are
     // being-killed-by-OS-shutdown-logic, shutdown freezing after
     // session restore was written, etc.
-    let Telemetry = Cc["@mozilla.org/base/telemetry;1"].getService(Ci.nsITelemetry);
+    Services.telemetry.getHistogramById("SHUTDOWN_OK").add(!lastSessionCrashed);
-    Telemetry.getHistogramById("SHUTDOWN_OK").add(!lastSessionCrashed);
 
     // set the startup type
     if (lastSessionCrashed && resumeFromCrash)
@@ -296,9 +303,11 @@ SessionStartup.prototype = {
    * @returns a session state string
    */
   _readStateFile: function sss_readStateFile(aFile) {
+    TelemetryStopwatch.start("FX_SESSION_RESTORE_READ_FILE_MS");
     var stateString = Cc["@mozilla.org/supports-string;1"].
                         createInstance(Ci.nsISupportsString);
     stateString.data = this._readFile(aFile) || "";
+    TelemetryStopwatch.finish("FX_SESSION_RESTORE_READ_FILE_MS");
 
     Services.obs.notifyObservers(stateString, "sessionstore-state-read", "");
 

browser/components/sessionstore/src/nsSessionStore.js

@@ -131,6 +131,7 @@ Cu.import("resource://gre/modules/Services.jsm");
 Cu.import("resource://gre/modules/debug.js");
 
 Cu.import("resource:///modules/TelemetryTimestamps.jsm");
+Cu.import("resource:///modules/TelemetryStopwatch.jsm");
 
 XPCOMUtils.defineLazyGetter(this, "NetUtil", function() {
   Cu.import("resource://gre/modules/NetUtil.jsm");
@@ -3653,6 +3654,8 @@ SessionStoreService.prototype = {
     // if we crash.
     let pinnedOnly = this._loadState == STATE_RUNNING && !this._resume_from_crash;
 
+    TelemetryStopwatch.start("FX_SESSION_RESTORE_COLLECT_DATA_MS");
+
     var oState = this._getCurrentState(aUpdateAll, pinnedOnly);
     if (!oState)
       return;
@@ -3691,6 +3694,8 @@ SessionStoreService.prototype = {
     if (this._lastSessionState)
       oState.lastSessionState = this._lastSessionState;
 
+    TelemetryStopwatch.finish("FX_SESSION_RESTORE_COLLECT_DATA_MS");
+
     this._saveStateObject(oState);
   },
 
@@ -3698,9 +3703,11 @@ SessionStoreService.prototype = {
    * write a state object to disk
    */
   _saveStateObject: function sss_saveStateObject(aStateObj) {
+    TelemetryStopwatch.start("FX_SESSION_RESTORE_SERIALIZE_DATA_MS");
     var stateString = Cc["@mozilla.org/supports-string;1"].
                         createInstance(Ci.nsISupportsString);
     stateString.data = this._toJSONString(aStateObj);
+    TelemetryStopwatch.finish("FX_SESSION_RESTORE_SERIALIZE_DATA_MS");
 
     Services.obs.notifyObservers(stateString, "sessionstore-state-write", "");
 
@@ -4427,6 +4434,7 @@ SessionStoreService.prototype = {
    *        String data
    */
   _writeFile: function sss_writeFile(aFile, aData) {
+    TelemetryStopwatch.start("FX_SESSION_RESTORE_WRITE_FILE_MS");
     // Initialize the file output stream.
     var ostream = Cc["@mozilla.org/network/safe-file-output-stream;1"].
                   createInstance(Ci.nsIFileOutputStream);
@@ -4442,6 +4450,7 @@ SessionStoreService.prototype = {
     var self = this;
     NetUtil.asyncCopy(istream, ostream, function(rc) {
       if (Components.isSuccessCode(rc)) {
+        TelemetryStopwatch.finish("FX_SESSION_RESTORE_WRITE_FILE_MS");
         Services.obs.notifyObservers(null,
                                      "sessionstore-state-write-complete",
                                      "");

toolkit/components/telemetry/TelemetryHistograms.h

@@ -344,6 +344,15 @@ HISTOGRAM(FX_BOOKMARKS_TOOLBAR_INIT_MS, 50, 5000, 10, EXPONENTIAL, "Firefox: Tim
 HISTOGRAM(FX_THUMBNAILS_CAPTURE_TIME_MS, 1, 500, 15, EXPONENTIAL, "THUMBNAILS: Time (ms) it takes to capture a thumbnail")
 HISTOGRAM(FX_THUMBNAILS_STORE_TIME_MS, 1, 500, 15, EXPONENTIAL, "THUMBNAILS: Time (ms) it takes to store a thumbnail in the cache")
 HISTOGRAM(FX_THUMBNAILS_HIT_OR_MISS, 0, 1, 2, BOOLEAN, "THUMBNAILS: Thumbnail found")
+
+/**
+ * Session restore telemetry
+ */
+HISTOGRAM(FX_SESSION_RESTORE_COLLECT_DATA_MS, 1, 30000, 10, EXPONENTIAL, "Session restore: Time to collect all window and tab data (ms)")
+HISTOGRAM(FX_SESSION_RESTORE_SERIALIZE_DATA_MS, 1, 1000, 10, EXPONENTIAL, "Session restore: Time to JSON serialize session data (ms)")
+HISTOGRAM(FX_SESSION_RESTORE_READ_FILE_MS, 1, 3000, 10, EXPONENTIAL, "Session restore: Time to read the session data from the file on disk (ms)")
+HISTOGRAM(FX_SESSION_RESTORE_WRITE_FILE_MS, 1, 3000, 10, EXPONENTIAL, "Session restore: Time to write the session data to the file on disk (ms)")
+HISTOGRAM_BOOLEAN(FX_SESSION_RESTORE_CORRUPT_FILE, "Session restore: Whether the file read on startup contained parse-able JSON")
 // #endif
 
 HISTOGRAM_BOOLEAN(INNERWINDOWS_WITH_MUTATION_LISTENERS, "Deleted or to-be-reused innerwindow which has had mutation event listeners.")