From b007d78f5dbec97d92719efc081fee2030965d0b Mon Sep 17 00:00:00 2001 From: Gabor Krizsanits Date: Tue, 25 Apr 2017 17:11:12 +0200 Subject: [PATCH] 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. --- .../components/sessionstore/SessionStore.jsm | 2 +- .../content/content-sessionStore.js | 5 ++ .../responsive.html/browser/web-navigation.js | 1 + dom/ipc/tests/browser.ini | 2 + ...owser_remote_navigation_delay_telemetry.js | 52 +++++++++++++++++++ .../remotebrowserutils/RemoteWebNavigation.js | 1 + toolkit/components/telemetry/Histograms.json | 10 ++++ toolkit/content/browser-child.js | 4 ++ 8 files changed, 76 insertions(+), 1 deletion(-) create mode 100644 dom/ipc/tests/browser_remote_navigation_delay_telemetry.js diff --git a/browser/components/sessionstore/SessionStore.jsm b/browser/components/sessionstore/SessionStore.jsm index d75b11ddc457..aeec881d2233 100644 --- a/browser/components/sessionstore/SessionStore.jsm +++ b/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()}); }, /** diff --git a/browser/components/sessionstore/content/content-sessionStore.js b/browser/components/sessionstore/content/content-sessionStore.js index 284a872d9dc6..02ef95b3db87 100644 --- a/browser/components/sessionstore/content/content-sessionStore.js +++ b/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": diff --git a/devtools/client/responsive.html/browser/web-navigation.js b/devtools/client/responsive.html/browser/web-navigation.js index 582b3a1a5b60..c86de60c7a47 100644 --- a/devtools/client/responsive.html/browser/web-navigation.js +++ b/devtools/client/responsive.html/browser/web-navigation.js @@ -79,6 +79,7 @@ BrowserElementWebNavigation.prototype = { triggeringPrincipal: triggeringPrincipal ? Utils.serializePrincipal(triggeringPrincipal) : null, + requestTime: Services.telemetry.msSystemNow(), }); }, diff --git a/dom/ipc/tests/browser.ini b/dom/ipc/tests/browser.ini index 3d36c450d983..9b5e308da79c 100644 --- a/dom/ipc/tests/browser.ini +++ b/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. diff --git a/dom/ipc/tests/browser_remote_navigation_delay_telemetry.js b/dom/ipc/tests/browser_remote_navigation_delay_telemetry.js new file mode 100644 index 000000000000..04a9aced76b8 --- /dev/null +++ b/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); +}); diff --git a/toolkit/components/remotebrowserutils/RemoteWebNavigation.js b/toolkit/components/remotebrowserutils/RemoteWebNavigation.js index 7b864117c559..08722245db09 100644 --- a/toolkit/components/remotebrowserutils/RemoteWebNavigation.js +++ b/toolkit/components/remotebrowserutils/RemoteWebNavigation.js @@ -83,6 +83,7 @@ RemoteWebNavigation.prototype = { triggeringPrincipal: aTriggeringPrincipal ? Utils.serializePrincipal(aTriggeringPrincipal) : null, + requestTime: Services.telemetry.msSystemNow(), }); }, setOriginAttributesBeforeLoading(aOriginAttributes) { diff --git a/toolkit/components/telemetry/Histograms.json b/toolkit/components/telemetry/Histograms.json index bb66f9fd313c..f6511d91b6a3 100644 --- a/toolkit/components/telemetry/Histograms.json +++ b/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", diff --git a/toolkit/content/browser-child.js b/toolkit/content/browser-child.js index 5a2a25308e02..bfc1f2b2d5b6 100644 --- a/toolkit/content/browser-child.js +++ b/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,