Bug 1499418 - Add GeckoView page load and startup performance telemetry probes. r=snorp,chutten,jchen, a=RyanVM GECKOVIEW_64_RELBRANCH
authorEugen Sawin <esawin@mozilla.com>
Tue, 13 Nov 2018 15:39:11 +0100
branchGECKOVIEW_64_RELBRANCH
changeset 501451 348872e1c4fe
parent 501450 626d7b63b958
child 501452 26d700d8010a
push id1869
push userryanvm@gmail.com
push dateTue, 04 Dec 2018 21:33:30 +0000
treeherdermozilla-release@26d700d8010a [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerssnorp, chutten, jchen, RyanVM
bugs1499418
milestone64.0
Bug 1499418 - Add GeckoView page load and startup performance telemetry probes. r=snorp,chutten,jchen, a=RyanVM
mobile/android/chrome/geckoview/GeckoViewProgressContent.js
mobile/android/chrome/geckoview/geckoview.js
mobile/android/geckoview/src/main/java/org/mozilla/gecko/GeckoThread.java
mobile/android/modules/geckoview/GeckoViewTelemetry.jsm
mobile/android/modules/geckoview/moz.build
toolkit/components/telemetry/Histograms.json
--- a/mobile/android/chrome/geckoview/GeckoViewProgressContent.js
+++ b/mobile/android/chrome/geckoview/GeckoViewProgressContent.js
@@ -1,20 +1,25 @@
 /* -*- indent-tabs-mode: nil; js-indent-level: 2 -*- */
 /* 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/. */
 
 ChromeUtils.import("resource://gre/modules/GeckoViewContentModule.jsm");
 ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
+ChromeUtils.import("resource://gre/modules/GeckoViewTelemetry.jsm");
 
 XPCOMUtils.defineLazyModuleGetters(this, {
   Services: "resource://gre/modules/Services.jsm",
 });
 
+const PAGE_LOAD_PROGRESS_PROBE =
+  new HistogramStopwatch("GV_PAGE_LOAD_PROGRESS_MS", content);
+const PAGE_LOAD_PROBE = new HistogramStopwatch("GV_PAGE_LOAD_MS", content);
+
 class GeckoViewProgressContent extends GeckoViewContentModule {
   onInit() {
     debug `onInit`;
 
     ProgressTracker.onInit(this);
 
     const flags = Ci.nsIWebProgress.NOTIFY_PROGRESS |
                   Ci.nsIWebProgress.NOTIFY_STATE_NETWORK |
@@ -39,36 +44,45 @@ class GeckoViewProgressContent extends G
     debug `onStateChange: isTopLevel=${aWebProgress.isTopLevel},
                           flags=${aStateFlags}, status=${aStatus}`;
 
     if (!aWebProgress || !aWebProgress.isTopLevel) {
       return;
     }
 
     const uri = aRequest.QueryInterface(Ci.nsIChannel).URI.displaySpec;
+
+    if (aRequest.URI.schemeIs("about")) {
+      return;
+    }
+
     debug `onStateChange: uri=${uri}`;
 
     if (aStateFlags & Ci.nsIWebProgressListener.STATE_START) {
+      PAGE_LOAD_PROBE.start();
       ProgressTracker.start(uri);
     } else if ((aStateFlags & Ci.nsIWebProgressListener.STATE_STOP) &&
                !aWebProgress.isLoadingDocument) {
+      PAGE_LOAD_PROBE.finish();
       ProgressTracker.stop();
     } else if (aStateFlags & Ci.nsIWebProgressListener.STATE_REDIRECTING) {
+      PAGE_LOAD_PROBE.start();
       ProgressTracker.start(uri);
     }
   }
 
   onLocationChange(aWebProgress, aRequest, aLocationURI, aFlags) {
+    if (!aWebProgress || !aWebProgress.isTopLevel ||
+        !aLocationURI || aLocationURI.schemeIs("about")) {
+      return;
+    }
+
     debug `onLocationChange: location=${aLocationURI.displaySpec},
                              flags=${aFlags}`;
 
-    if (!aWebProgress || !aWebProgress.isTopLevel) {
-      return;
-    }
-
     if (aFlags & Ci.nsIWebProgressListener.LOCATION_CHANGE_ERROR_PAGE) {
       ProgressTracker.stop();
     } else {
       ProgressTracker.changeLocation(aLocationURI.displaySpec);
     }
   }
 }
 
@@ -77,16 +91,17 @@ const ProgressTracker = {
     this._module = aModule;
     this.clear();
   },
 
   start: function(aUri) {
     debug `ProgressTracker start ${aUri}`;
 
     if (this._tracking) {
+      PAGE_LOAD_PROGRESS_PROBE.cancel();
       this.stop();
     }
 
     addEventListener("MozAfterPaint", this,
                      { capture: false, mozSystemGroup: true });
     addEventListener("DOMContentLoaded", this,
                      { capture: false, mozSystemGroup: true });
     addEventListener("pageshow", this,
@@ -96,16 +111,18 @@ const ProgressTracker = {
     this.clear();
     let data = this._data;
 
     if (aUri === "about:blank") {
       data.uri = null;
       return;
     }
 
+    PAGE_LOAD_PROGRESS_PROBE.start();
+
     data.uri = aUri;
     data.pageStart = true;
     this.updateProgress();
   },
 
   changeLocation: function(aUri) {
     debug `ProgressTracker changeLocation ${aUri}`;
 
@@ -247,16 +264,18 @@ const ProgressTracker = {
     debug `ProgressTracker updateProgress`;
 
     let data = this._data;
 
     if (!this._tracking || !data.uri) {
       return;
     }
 
+    const now = content.performance.now();
+
     let progress = 0;
 
     if (data.pageStart) {
       progress += 10;
     }
     if (data.firstPaint) {
       progress += 15;
     }
@@ -267,17 +286,17 @@ const ProgressTracker = {
       progress += 15;
     }
     if (data.locationChange) {
       progress += 10;
     }
 
     data.totalReceived = 1;
     data.totalExpected = 1;
-    const channelOverdue = content.performance.now() - 300;
+    const channelOverdue = now - 300;
 
     for (let channel in data.channels) {
       if (data.channels[channel].max < 1 &&
           channelOverdue > data.channels[channel].lastUpdate) {
         data.channels[channel].expected = data.channels[channel].received;
       }
       data.totalReceived += data.channels[channel].received;
       data.totalExpected += data.channels[channel].expected;
@@ -291,26 +310,31 @@ const ProgressTracker = {
          data.totalReceived > minExpected &&
          data.totalReceived >= data.totalExpected)) {
       progress = 100;
     } else {
       const a = Math.min(1, (data.totalExpected / maxExpected)) * 30;
       progress += data.totalReceived / data.totalExpected * a;
     }
 
-    debug `ProgressTracker onProgressChangeUpdate ${this._debugData()} ${data.totalReceived}/${data.totalExpected} progress=${progress}`;
+    debug `ProgressTracker updateProgress data=${this._debugData()}
+           progress=${progress}`;
 
     if (data.prev >= progress) {
       return;
     }
 
     this.eventDispatcher.sendRequest({
       type: "GeckoView:ProgressChanged",
       progress,
     });
 
     data.prev = progress;
+
+    if (progress === 100) {
+      PAGE_LOAD_PROGRESS_PROBE.finish();
+    }
   },
 };
 
 
 let {debug, warn} = GeckoViewProgressContent.initLogging("GeckoViewProgress");
 let module = GeckoViewProgressContent.create(this);
--- a/mobile/android/chrome/geckoview/geckoview.js
+++ b/mobile/android/chrome/geckoview/geckoview.js
@@ -4,16 +4,17 @@
 
 "use strict";
 
 ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
 
 XPCOMUtils.defineLazyModuleGetters(this, {
   EventDispatcher: "resource://gre/modules/Messaging.jsm",
   GeckoViewUtils: "resource://gre/modules/GeckoViewUtils.jsm",
+  HistogramStopwatch: "resource://gre/modules/GeckoViewTelemetry.jsm",
   Services: "resource://gre/modules/Services.jsm",
 });
 
 XPCOMUtils.defineLazyGetter(this, "WindowEventDispatcher",
   () => EventDispatcher.for(window));
 
 /**
  * ModuleManager creates and manages GeckoView modules. Each GeckoView module
@@ -25,16 +26,21 @@ XPCOMUtils.defineLazyGetter(this, "Windo
  * initialization, change in enabled state, and change in settings.
  */
 var ModuleManager = {
   get _initData() {
     return window.arguments[0].QueryInterface(Ci.nsIAndroidView).initData;
   },
 
   init(aBrowser, aModules) {
+    const MODULES_INIT_PROBE =
+      new HistogramStopwatch("GV_STARTUP_MODULES_MS", aBrowser);
+
+    MODULES_INIT_PROBE.start();
+
     const initData = this._initData;
     this._browser = aBrowser;
     this._settings = initData.settings;
     this._frozenSettings = Object.freeze(Object.assign({}, this._settings));
 
     const self = this;
     this._modules = new Map((function* () {
       for (const module of aModules) {
@@ -67,16 +73,18 @@ var ModuleManager = {
     window.addEventListener("unload", () => {
       this.forEach(module => {
         module.enabled = false;
         module.onDestroy();
       });
 
       this._modules.clear();
     });
+
+    MODULES_INIT_PROBE.finish();
   },
 
   get window() {
     return window;
   },
 
   get browser() {
     return this._browser;
--- a/mobile/android/geckoview/src/main/java/org/mozilla/gecko/GeckoThread.java
+++ b/mobile/android/geckoview/src/main/java/org/mozilla/gecko/GeckoThread.java
@@ -1,15 +1,16 @@
 /* -*- Mode: Java; c-basic-offset: 4; tab-width: 4; indent-tabs-mode: nil; -*-
  * 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/. */
 
 package org.mozilla.gecko;
 
+import org.mozilla.gecko.TelemetryUtils;
 import org.mozilla.gecko.annotation.RobocopTarget;
 import org.mozilla.gecko.annotation.WrapForJNI;
 import org.mozilla.gecko.mozglue.GeckoLoader;
 import org.mozilla.gecko.process.GeckoProcessManager;
 import org.mozilla.gecko.util.GeckoBundle;
 import org.mozilla.gecko.util.FileUtils;
 import org.mozilla.gecko.util.ThreadUtils;
 import org.mozilla.geckoview.BuildConfig;
@@ -120,16 +121,18 @@ public class GeckoThread extends Thread 
 
     @WrapForJNI
     private static final ClassLoader clsLoader = GeckoThread.class.getClassLoader();
     @WrapForJNI
     private static MessageQueue msgQueue;
     @WrapForJNI
     private static int uiThreadId;
 
+    private static TelemetryUtils.Timer sInitTimer;
+
     // Main process parameters
     public static final int FLAG_DEBUGGING = 1 << 0; // Debugging mode.
     public static final int FLAG_PRELOAD_CHILD = 1 << 1; // Preload child during main thread start.
     public static final int FLAG_ENABLE_NATIVE_CRASHREPORTER = 1 << 2; // Enable native crash reporting
 
     /* package */ static final String EXTRA_ARGS = "args";
     private static final String EXTRA_PREFS_FD = "prefsFd";
     private static final String EXTRA_PREF_MAP_FD = "prefMapFd";
@@ -160,16 +163,18 @@ public class GeckoThread extends Thread 
                                       final int crashAnnotationFd) {
         ThreadUtils.assertOnUiThread();
         uiThreadId = android.os.Process.myTid();
 
         if (mInitialized) {
             return false;
         }
 
+        sInitTimer = new TelemetryUtils.UptimeTimer("GV_STARTUP_RUNTIME_MS");
+
         mProfile = profile;
         mArgs = args;
         mFlags = flags;
 
         mExtras = (extras != null) ? new Bundle(extras) : new Bundle(3);
         mExtras.putInt(EXTRA_PREFS_FD, prefsFd);
         mExtras.putInt(EXTRA_PREF_MAP_FD, prefMapFd);
         mExtras.putInt(EXTRA_IPC_FD, ipcFd);
@@ -585,16 +590,21 @@ public class GeckoThread extends Thread 
     }
 
     @WrapForJNI(calledFrom = "gecko")
     private static boolean checkAndSetState(final State expectedState,
                                             final State newState) {
         final boolean result = sNativeQueue.checkAndSetState(expectedState, newState);
         if (result) {
             Log.d(LOGTAG, "State changed to " + newState);
+
+            if (sInitTimer != null && isRunning()) {
+                sInitTimer.stop();
+                sInitTimer = null;
+            }
         }
         return result;
     }
 
     @WrapForJNI(stubName = "SpeculativeConnect")
     private static native void speculativeConnectNative(String uri);
 
     public static void speculativeConnect(final String uri) {
new file mode 100644
--- /dev/null
+++ b/mobile/android/modules/geckoview/GeckoViewTelemetry.jsm
@@ -0,0 +1,43 @@
+/* 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";
+
+var EXPORTED_SYMBOLS = ["HistogramStopwatch"];
+
+ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
+
+XPCOMUtils.defineLazyModuleGetters(this, {
+  TelemetryStopwatch: "resource://gre/modules/TelemetryStopwatch.jsm",
+});
+
+// A helper for histogram timer probes.
+class HistogramStopwatch {
+  constructor(aName, aAssociated) {
+    this._name = aName;
+    this._obj = aAssociated;
+  }
+
+  isRunning() {
+    return TelemetryStopwatch.running(this._name, this._obj);
+  }
+
+  start() {
+    if (this.isRunning()) {
+      this.cancel();
+    }
+    TelemetryStopwatch.start(this._name, this._obj);
+  }
+
+  finish() {
+    TelemetryStopwatch.finish(this._name, this._obj);
+  }
+
+  cancel() {
+    TelemetryStopwatch.cancel(this._name, this._obj);
+  }
+
+  timeElapsed() {
+    return TelemetryStopwatch.timeElapsed(this._name, this._obj, false);
+  }
+}
--- a/mobile/android/modules/geckoview/moz.build
+++ b/mobile/android/modules/geckoview/moz.build
@@ -13,13 +13,14 @@ EXTRA_JS_MODULES += [
     'GeckoViewContent.jsm',
     'GeckoViewContentModule.jsm',
     'GeckoViewModule.jsm',
     'GeckoViewNavigation.jsm',
     'GeckoViewProgress.jsm',
     'GeckoViewRemoteDebugger.jsm',
     'GeckoViewSettings.jsm',
     'GeckoViewTab.jsm',
+    'GeckoViewTelemetry.jsm',
     'GeckoViewTrackingProtection.jsm',
     'GeckoViewUtils.jsm',
     'LoadURIDelegate.jsm',
     'Messaging.jsm',
 ]
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -14196,10 +14196,62 @@
     "expires_in_version": "68",
     "bug_numbers": [1481716],
     "kind": "exponential",
     "high": 30000,
     "n_buckets": 30,
     "releaseChannelCollection": "opt-out",
     "alert_emails": ["ttung@mozilla.com"],
     "description": "Time (ms) for the QuotaManager to initialize repositories."
+  },
+  "GV_PAGE_LOAD_PROGRESS_MS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": [
+      "geckoview-team@mozilla.com",
+      "esawin@mozilla.com"
+    ],
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": 100000,
+    "n_buckets": 100,
+    "bug_numbers": [1499418],
+    "description": "GeckoView: The time between page load progress start (0) and completion (100) in ms."
+  },
+  "GV_PAGE_LOAD_MS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": [
+      "geckoview-team@mozilla.com",
+      "esawin@mozilla.com"
+    ],
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": 100000,
+    "n_buckets": 100,
+    "bug_numbers": [1499418],
+    "description": "GeckoView: Time taken to load a page in ms. This includes all static contents, no dynamic content. Loading of about: pages is not counted."
+  },
+  "GV_STARTUP_RUNTIME_MS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": [
+      "geckoview-team@mozilla.com",
+      "esawin@mozilla.com"
+    ],
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 50,
+    "bug_numbers": [1499418],
+    "description": "GeckoView: Time taken to initialize GeckoRuntime in ms."
+  },
+  "GV_STARTUP_MODULES_MS": {
+    "record_in_processes": ["main"],
+    "alert_emails": [
+      "geckoview-team@mozilla.com",
+      "esawin@mozilla.com"
+    ],
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": 5000,
+    "n_buckets": 50,
+    "bug_numbers": [1499418],
+    "description": "GeckoView: Time taken to initialize all GeckoView modules in ms."
   }
 }