Bug 1214158 - New module StartupPerformance to monitor the duration of restoration of initial tabs;r=mconley draft
authorDavid Rajchenbach-Teller <dteller@mozilla.com>
Thu, 26 Nov 2015 18:01:56 +0100
changeset 320702 862330eecf29d2eb88ddbfbb8f9d73b205f1e1e7
parent 320463 5acc2a44834ce0614f98466475e674517daf0041
child 320703 cde8bcddcd2432691a820a37c942218cf01453b8
push id9277
push userdteller@mozilla.com
push dateTue, 12 Jan 2016 09:32:09 +0000
reviewersmconley
bugs1214158
milestone46.0a1
Bug 1214158 - New module StartupPerformance to monitor the duration of restoration of initial tabs;r=mconley
browser/components/sessionstore/SessionStore.jsm
browser/components/sessionstore/StartupPerformance.jsm
browser/components/sessionstore/content/aboutSessionRestore.js
browser/components/sessionstore/moz.build
browser/components/sessionstore/nsSessionStartup.js
toolkit/components/telemetry/Histograms.json
--- a/browser/components/sessionstore/SessionStore.jsm
+++ b/browser/components/sessionstore/SessionStore.jsm
@@ -13,19 +13,24 @@ const Cr = Components.results;
 
 // Current version of the format used by Session Restore.
 const FORMAT_VERSION = 1;
 
 const TAB_STATE_NEEDS_RESTORE = 1;
 const TAB_STATE_RESTORING = 2;
 const TAB_STATE_WILL_RESTORE = 3;
 
+// A new window has just been restored. At this stage, tabs are generally
+// not restored.
+const NOTIFY_SINGLE_WINDOW_RESTORED = "sessionstore-single-window-restored";
 const NOTIFY_WINDOWS_RESTORED = "sessionstore-windows-restored";
 const NOTIFY_BROWSER_STATE_RESTORED = "sessionstore-browser-state-restored";
 const NOTIFY_LAST_SESSION_CLEARED = "sessionstore-last-session-cleared";
+const NOTIFY_RESTORING_ON_STARTUP = "sessionstore-restoring-on-startup";
+const NOTIFY_INITIATING_MANUAL_RESTORE = "sessionstore-initiating-manual-restore";
 
 const NOTIFY_TAB_RESTORED = "sessionstore-debug-tab-restored"; // WARNING: debug-only
 
 // Maximum number of tabs to restore simultaneously. Previously controlled by
 // the browser.sessionstore.max_concurrent_tabs pref.
 const MAX_CONCURRENT_TAB_RESTORES = 3;
 
 // global notifications observed
@@ -1174,16 +1179,19 @@ var SessionStoreInternal = {
       }
 
       if (this._sessionInitialized) {
         this.initializeWindow(aWindow);
       } else {
         let initialState = this.initSession();
         this._sessionInitialized = true;
 
+        if (initialState) {
+          Services.obs.notifyObservers(null, NOTIFY_RESTORING_ON_STARTUP, "");
+        }
         TelemetryStopwatch.start("FX_SESSION_RESTORE_STARTUP_ONLOAD_INITIAL_WINDOW_MS");
         this.initializeWindow(aWindow, initialState);
         TelemetryStopwatch.finish("FX_SESSION_RESTORE_STARTUP_ONLOAD_INITIAL_WINDOW_MS");
 
         // Let everyone know we're done.
         this._deferredInitialized.resolve();
       }
     }, console.error);
@@ -2311,16 +2319,18 @@ var SessionStoreInternal = {
    * be opened.
    */
   restoreLastSession: function ssi_restoreLastSession() {
     // Use the public getter since it also checks PB mode
     if (!this.canRestoreLastSession) {
       throw Components.Exception("Last session can not be restored");
     }
 
+    Services.obs.notifyObservers(null, NOTIFY_INITIATING_MANUAL_RESTORE, "");
+
     // First collect each window with its id...
     let windows = {};
     this._forEachBrowserWindow(function(aWindow) {
       if (aWindow.__SS_lastSessionWindowID)
         windows[aWindow.__SS_lastSessionWindowID] = aWindow;
     });
 
     let lastSessionState = LastSession.getState();
@@ -3012,16 +3022,19 @@ var SessionStoreInternal = {
     }
 
     // set smoothScroll back to the original value
     tabstrip.smoothScroll = smoothScroll;
 
     TelemetryStopwatch.finish("FX_SESSION_RESTORE_RESTORE_WINDOW_MS");
 
     this._setWindowStateReady(aWindow);
+
+    Services.obs.notifyObservers(aWindow, NOTIFY_SINGLE_WINDOW_RESTORED, "");
+
     this._sendRestoreCompletedNotifications();
   },
 
   /**
    * Restore multiple windows using the provided state.
    * @param aWindow
    *        Window reference to the first window to use for restoration.
    *        Additionally required windows will be opened.
new file mode 100644
--- /dev/null
+++ b/browser/components/sessionstore/StartupPerformance.jsm
@@ -0,0 +1,183 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this file,
+ * You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+"use strict";
+
+this.EXPORTED_SYMBOLS = ["StartupPerformance"];
+
+const { utils: Cu, classes: Cc, interfaces: Ci } = Components;
+
+Cu.import("resource://gre/modules/XPCOMUtils.jsm", this);
+
+XPCOMUtils.defineLazyModuleGetter(this, "Services",
+  "resource://gre/modules/Services.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "console",
+  "resource://gre/modules/Console.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "setTimeout",
+  "resource://gre/modules/Timer.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "clearTimeout",
+  "resource://gre/modules/Timer.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "Promise",
+  "resource://gre/modules/Promise.jsm");
+
+const COLLECT_RESULTS_AFTER_MS = 10000;
+
+const TOPICS = ["sessionstore-restoring-on-startup", "sessionstore-initiating-manual-restore"];
+
+this.StartupPerformance = {
+  // Instant at which we have started restoration (notification "sessionstore-restoring-on-startup")
+  _startTimeStamp: null,
+
+  // Latest instant at which we have finished restoring a tab (DOM event "SSTabRestored")
+  _latestRestoredTimeStamp: null,
+
+  // A promise resolved once we have finished restoring all the startup tabs.
+  _promiseFinished: null,
+
+  // Function `resolve()` for `_promiseFinished`.
+  _resolveFinished: null,
+
+  // A timer
+  _deadlineTimer: null,
+
+  // `true` once the timer has fired
+  _hasFired: false,
+
+  init: function() {
+    for (let topic of TOPICS) {
+      Services.obs.addObserver(this, topic, false);
+    }
+  },
+
+  // Called when restoration starts.
+  // Record the start timestamp, setup the timer and `this._promiseFinished`.
+  // Behavior is unspecified if there was already an ongoing measure.
+  _onRestorationStarts: function(isAutoRestore) {
+    this._startTimeStamp = Date.now();
+
+    // While we may restore several sessions in a single run of the browser,
+    // that's a very unusual case, and not really worth measuring, so let's
+    // stop listening for further restorations.
+
+    for (let topic of TOPICS) {
+      Services.obs.removeObserver(this, topic);
+    }
+
+    Services.obs.addObserver(this, "sessionstore-single-window-restored", false);
+    this._promiseFinished = new Promise(resolve => {
+      this._resolveFinished = resolve;
+    });
+    this._promiseFinished.then(() => {
+      try {
+        if (!this._latestRestoredTimeStamp) {
+          // Apparently, we haven't restored any tab.
+          return;
+        }
+
+        // Once we are done restoring tabs, update Telemetry.
+        let histogramName = isAutoRestore ?
+          "FX_SESSION_RESTORE_AUTO_RESTORE_DURATION_UNTIL_EAGER_TABS_RESTORED_MS" :
+          "FX_SESSION_RESTORE_MANUAL_RESTORE_DURATION_UNTIL_EAGER_TABS_RESTORED_MS";
+        let histogram = Services.telemetry.getHistogramById(histogramName);
+        let delta = this._latestRestoredTimeStamp - this._startTimeStamp;
+        histogram.add(delta);
+
+        // Reset
+        this._startTimeStamp = null;
+      } catch (ex) {
+        console.error("StartupPerformance: error after resolving promise", ex);
+      }
+    });
+  },
+
+  _startTimer: function() {
+    if (this._hasFired) {
+      return;
+    }
+    if (this._deadlineTimer) {
+      clearTimeout(this._deadlineTimer);
+    }
+    this._deadlineTimer = setTimeout(() => {
+      try {
+        this._resolveFinished();
+      } catch (ex) {
+        console.error("StartupPerformance: Error in timeout handler", ex);
+      } finally {
+        // Clean up.
+        this._deadlineTimer = null;
+        this._hasFired = true;
+        this._resolveFinished = null;
+        Services.obs.removeObserver(this, "sessionstore-single-window-restored");
+      }
+    }, COLLECT_RESULTS_AFTER_MS);
+  },
+
+  observe: function(subject, topic, details) {
+    try {
+      switch (topic) {
+        case "sessionstore-restoring-on-startup":
+          this._onRestorationStarts(true);
+          break;
+        case "sessionstore-initiating-manual-restore":
+          this._onRestorationStarts(false);
+          break;
+        case "sessionstore-single-window-restored": {
+          // Session Restore has just opened a window with (initially empty) tabs.
+          // Some of these tabs will be restored eagerly, while others will be
+          // restored on demand. The process becomes usable only when all windows
+          // have finished restored their eager tabs.
+          //
+          // While it would be possible to track the restoration of each tab
+          // from within SessionRestore to determine exactly when the process
+          // becomes usable, experience shows that this is too invasive. Rather,
+          // we employ the following heuristic:
+          // - we maintain a timer of `COLLECT_RESULTS_AFTER_MS` that we expect
+          //   will be triggered only once all tabs have been restored;
+          // - whenever we restore a new window (hence a bunch of eager tabs),
+          //   we postpone the timer to ensure that the new eager tabs have
+          //   `COLLECT_RESULTS_AFTER_MS` to be restored;
+          // - whenever a tab is restored, we update
+          //   `this._latestRestoredTimeStamp`;
+          // - after `COLLECT_RESULTS_AFTER_MS`, we collect the final version
+          //   of `this._latestRestoredTimeStamp`, and use it to determine the
+          //   entire duration of the collection.
+          //
+          // Note that this heuristic may be inaccurate if a user clicks
+          // immediately on a restore-on-demand tab before the end of
+          // `COLLECT_RESULTS_AFTER_MS`. We assume that this will not
+          // affect too much the results.
+          //
+          // Reset the delay, to give the tabs a little (more) time to restore.
+          this._startTimer();
+
+          // Observe the restoration of all tabs. We assume that all tabs of this
+          // window will have been restored before `COLLECT_RESULTS_AFTER_MS`.
+          // The last call to `observer` will let us determine how long it took
+          // to reach that point.
+          let win = subject;
+
+          let observer = () => {
+            this._latestRestoredTimeStamp = Date.now();
+          };
+          win.gBrowser.tabContainer.addEventListener("SSTabRestored", observer);
+
+          // Once we have finished collecting the results, clean up the observers.
+          this._promiseFinished.then(() => {
+            if (!win.gBrowser.tabContainer) {
+              // May be undefined during shutdown and/or some tests.
+              return;
+            }
+            win.gBrowser.tabContainer.removeEventListener("SSTabRestored", observer);
+          });
+        }
+        break;
+        default:
+          throw new Error(`Unexpected topic ${topic}`);
+      }
+    } catch (ex) {
+      console.error("StartupPerformance error", ex, ex.stack);
+      throw ex;
+    }
+  }
+};
--- a/browser/components/sessionstore/content/aboutSessionRestore.js
+++ b/browser/components/sessionstore/content/aboutSessionRestore.js
@@ -107,16 +107,17 @@ function updateTabListVisibility() {
   } else {
     tabList.removeAttribute("available");
     container.classList.remove("restore-chosen");
   }
   initTreeView();
 }
 
 function restoreSession() {
+  Services.obs.notifyObservers(null, "sessionstore-initiating-manual-restore", "");
   document.getElementById("errorTryAgain").disabled = true;
 
   if (isTreeViewVisible()) {
     if (!gTreeData.some(aItem => aItem.checked)) {
       // This should only be possible when we have no "cancel" button, and thus
       // the "Restore session" button always remains enabled.  In that case and
       // when nothing is selected, we just want a new session.
       startNewSession();
--- a/browser/components/sessionstore/moz.build
+++ b/browser/components/sessionstore/moz.build
@@ -36,16 +36,17 @@ EXTRA_JS_MODULES.sessionstore = [
     'SessionFile.jsm',
     'SessionHistory.jsm',
     'SessionMigration.jsm',
     'SessionSaver.jsm',
     'SessionStorage.jsm',
     'SessionStore.jsm',
     'SessionWorker.js',
     'SessionWorker.jsm',
+    'StartupPerformance.jsm',
     'TabAttributes.jsm',
     'TabState.jsm',
     'TabStateCache.jsm',
     'TabStateFlusher.jsm',
     'Utils.jsm',
 ]
 
 with Files('**'):
--- a/browser/components/sessionstore/nsSessionStartup.js
+++ b/browser/components/sessionstore/nsSessionStartup.js
@@ -40,16 +40,18 @@ Cu.import("resource://gre/modules/Servic
 Cu.import("resource://gre/modules/TelemetryStopwatch.jsm");
 Cu.import("resource://gre/modules/PrivateBrowsingUtils.jsm");
 Cu.import("resource://gre/modules/Promise.jsm");
 
 XPCOMUtils.defineLazyModuleGetter(this, "console",
   "resource://gre/modules/Console.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "SessionFile",
   "resource:///modules/sessionstore/SessionFile.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "StartupPerformance",
+  "resource:///modules/sessionstore/StartupPerformance.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "CrashMonitor",
   "resource://gre/modules/CrashMonitor.jsm");
 
 const STATE_RUNNING_STR = "running";
 
 // 'browser.startup.page' preference value to resume the previous session.
 const BROWSER_STARTUP_RESUME_SESSION = 3;
 
@@ -91,16 +93,17 @@ SessionStartup.prototype = {
 
 /* ........ Global Event Handlers .............. */
 
   /**
    * Initialize the component
    */
   init: function sss_init() {
     Services.obs.notifyObservers(null, "sessionstore-init-started", null);
+    StartupPerformance.init();
 
     // do not need to initialize anything in auto-started private browsing sessions
     if (PrivateBrowsingUtils.permanentPrivateBrowsing) {
       this._initialized = true;
       gOnceInitializedDeferred.resolve();
       return;
     }
 
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -4219,16 +4219,34 @@
   },
   "FX_SESSION_RESTORE_DOM_STORAGE_SIZE_ESTIMATE_CHARS": {
     "expires_in_version": "default",
     "kind": "exponential",
     "high": "30000000",
     "n_buckets": 20,
     "description": "Session restore: Number of characters in DOM Storage for a tab. Pages without DOM Storage or with an empty DOM Storage are ignored."
   },
+  "FX_SESSION_RESTORE_AUTO_RESTORE_DURATION_UNTIL_EAGER_TABS_RESTORED_MS": {
+    "alert_emails": ["session-restore-telemetry-alerts@mozilla.com"],
+    "expires_in_version": "default",
+    "kind": "exponential",
+    "low": "100",
+    "high": "100000",
+    "n_buckets": 20,
+    "description": "Session restore: If the browser is setup to auto-restore tabs, this probe measures the time elapsed between the instant we start Session Restore and the instant we have finished restoring tabs eagerly. At this stage, the tabs that are restored on demand are not restored yet."
+  },
+  "FX_SESSION_RESTORE_MANUAL_RESTORE_DURATION_UNTIL_EAGER_TABS_RESTORED_MS": {
+    "alert_emails": ["session-restore-telemetry-alerts@mozilla.com"],
+    "expires_in_version": "default",
+    "kind": "exponential",
+    "low": "100",
+    "high": "100000",
+    "n_buckets": 20,
+    "description": "Session restore: If a session is restored by the user clicking on 'Restore Session', this probe measures the time elapsed between the instant the user has clicked and the instant we have finished restoring tabs eagerly. At this stage, the tabs that are restored on demand are not restored yet."
+  },
   "FX_TABLETMODE_PAGE_LOAD": {
     "expires_in_version": "47",
     "kind": "exponential",
     "high": 100000,
     "n_buckets": 30,
     "keyed": true,
     "description": "Number of toplevel location changes in tablet and desktop mode (only used on win10 where tablet mode is available)"
   },