Bug 1352961 - P2: Measure for the delay before a new tab starts processing the first URL. r=mconley, data-r=bsmedberg

Opening pages in a new tab might suffer an extra delay from e10s-multi because
the new process has to start up and then run all the process / frame scripts
before it can react on the request from the parent to load the first page.

There are two code paths. Either we start the tab with a remote browser and
then the RemoteWebNavigation will send the request. Or we start with a non-remote
browser and have to change the remoteness flag on it, and then the SessionStore
will send the request.

In each cases we start the timer on the parent side, send it with the message,
and when the child receives it it stops the timer and reports the measured delay.

browser/components/sessionstore/SessionStore.jsm

@@ -3851,7 +3851,7 @@ var SessionStoreInternal = {
 
     browser.messageManager.sendAsyncMessage("SessionStore:restoreTabContent",
       {loadArguments: aLoadArguments, isRemotenessUpdate,
-       reason: aReason});
+       reason: aReason, requestTime: Services.telemetry.msSystemNow()});
   },
 
   /**

browser/components/sessionstore/content/content-sessionStore.js

@@ -144,6 +144,11 @@ var MessageListener = {
         this.restoreHistory(data);
         break;
       case "SessionStore:restoreTabContent":
+        if (data.isRemotenessUpdate) {
+          let histogram = Services.telemetry.getKeyedHistogramById("FX_TAB_REMOTE_NAVIGATION_DELAY_MS");
+          histogram.add("SessionStore:restoreTabContent",
+                        Services.telemetry.msSystemNow() - data.requestTime);
+        }
         this.restoreTabContent(data);
         break;
       case "SessionStore:resetRestore":

devtools/client/responsive.html/browser/web-navigation.js

@@ -79,6 +79,7 @@ BrowserElementWebNavigation.prototype = {
       triggeringPrincipal: triggeringPrincipal
                            ? Utils.serializePrincipal(triggeringPrincipal)
                            : null,
+      requestTime: Services.telemetry.msSystemNow(),
     });
   },
 

dom/ipc/tests/browser.ini

@@ -6,3 +6,5 @@ support-files =
 [browser_domainPolicy.js]
 [browser_memory_distribution_telemetry.js]
 skip-if = !e10 # This is an e10s only probe.
+[browser_remote_navigation_delay_telemetry.js]
+skip-if = !e10s # This is an e10s only probe.

dom/ipc/tests/browser_remote_navigation_delay_telemetry.js

@@ -0,0 +1,52 @@
+"use strict";
+
+var session = Cu.import("resource://gre/modules/TelemetrySession.jsm", {});
+
+add_task(function* test_memory_distribution() {
+  if (Services.prefs.getIntPref("dom.ipc.processCount", 1) < 2) {
+    ok(true, "Skip this test if e10s-multi is disabled.");
+    return;
+  }
+
+  yield SpecialPowers.pushPrefEnv({set: [["toolkit.telemetry.enabled", true]]});
+  let canRecordExtended = Services.telemetry.canRecordExtended;
+  Services.telemetry.canRecordExtended = true;
+  registerCleanupFunction(() => Services.telemetry.canRecordExtended = canRecordExtended);
+
+  // Note the #content suffix after the id. This is the only way this API lets us fetch the
+  // histogram entries reported by a content process.
+  let histogram = Services.telemetry.getKeyedHistogramById("FX_TAB_REMOTE_NAVIGATION_DELAY_MS#content");
+  histogram.clear();
+
+  // Open a remote page in a new tab to trigger the WebNavigation:LoadURI.
+  let tab1 = yield BrowserTestUtils.openNewForegroundTab(gBrowser, "http://example.com");
+  ok(tab1.linkedBrowser.isRemoteBrowser, "|tab1| should have a remote browser.");
+
+  // Open a new tab with about:robots, so it ends up in the parent process with a non-remote browser.
+  let tab2 = yield BrowserTestUtils.openNewForegroundTab(gBrowser, "about:robots");
+  ok(!tab2.linkedBrowser.isRemoteBrowser, "|tab2| should have a non-remote browser.");
+  // Navigate the tab, so it will change remotness and it triggers the SessionStore:restoreTabContent case.
+  yield BrowserTestUtils.loadURI(tab2.linkedBrowser, "http://example.com");
+  ok(tab2.linkedBrowser.isRemoteBrowser, "|tab2| should have a remote browser by now.");
+
+  // There is no good way to make sure that the parent received the histogram entries from the child processes.
+  // Let's stick to the ugly, spinning the event loop until we have a good approach (Bug 1357509).
+  yield BrowserTestUtils.waitForCondition(() => {
+    let s = histogram.snapshot();
+    return "WebNavigation:LoadURI" in s && "SessionStore:restoreTabContent" in s;
+  });
+
+  let s = histogram.snapshot();
+  let restoreTabSnapshot = s["SessionStore:restoreTabContent"];
+  ok(restoreTabSnapshot.sum > 0, "Zero delay for the restoreTabContent case is unlikely.");
+  ok(restoreTabSnapshot.sum < 10000, "More than 10 seconds delay for the restoreTabContent case is unlikely.");
+
+  let loadURISnapshot = s["WebNavigation:LoadURI"];
+  ok(loadURISnapshot.sum > 0, "Zero delay for the LoadURI case is unlikely.");
+  ok(loadURISnapshot.sum < 10000, "More than 10 seconds delay for the LoadURI case is unlikely.");
+
+  histogram.clear();
+
+  yield BrowserTestUtils.removeTab(tab2);
+  yield BrowserTestUtils.removeTab(tab1);
+});

toolkit/components/remotebrowserutils/RemoteWebNavigation.js

@@ -83,6 +83,7 @@ RemoteWebNavigation.prototype = {
       triggeringPrincipal: aTriggeringPrincipal
                            ? Utils.serializePrincipal(aTriggeringPrincipal)
                            : null,
+      requestTime: Services.telemetry.msSystemNow(),
     });
   },
   setOriginAttributesBeforeLoading(aOriginAttributes) {

toolkit/components/telemetry/Histograms.json

@@ -5293,6 +5293,16 @@
     "n_buckets": 20,
     "description": "Firefox: Time in ms spent on switching tabs in response to a tab click"
   },
+  "FX_TAB_REMOTE_NAVIGATION_DELAY_MS": {
+    "alert_emails": ["gkrizsanits@mozilla.com", "mconley@mozilla.com"],
+    "bug_numbers": [1352961],
+    "expires_in_version": "61",
+    "kind": "exponential",
+    "high": 4000,
+    "n_buckets": 100,
+    "keyed": true,
+    "description": "Time taken (in ms) from the point of the parent sending the naviagion triggering message to the content and the content receiving it. This message can be either SessionStore:restoreTabContent or WebNavigation:LoadURI and these names are used as keys for this histogram. This is e10s only and recorded in the content process."
+  },
   "FX_BOOKMARKS_TOOLBAR_INIT_MS": {
     "expires_in_version": "never",
     "kind": "exponential",

toolkit/content/browser-child.js

@@ -264,6 +264,10 @@ var WebNavigation =  {
         this.gotoIndex(message.data.index);
         break;
       case "WebNavigation:LoadURI":
+        let histogram = Services.telemetry.getKeyedHistogramById("FX_TAB_REMOTE_NAVIGATION_DELAY_MS");
+        histogram.add("WebNavigation:LoadURI",
+                      Services.telemetry.msSystemNow() - message.data.requestTime);
+
         this.loadURI(message.data.uri, message.data.flags,
                      message.data.referrer, message.data.referrerPolicy,
                      message.data.postData, message.data.headers,