Bug 1331684: Record time spent blocked on shouldLoad shims per add-on. r=billm data-r=bsmedberg

MozReview-Commit-ID: K6bYourTigx

--HG--
extra : rebase_source : 9bb33939ce1f30fc6e12fe664dd3e5fa8852d7c5

toolkit/components/addoncompat/RemoteAddonsChild.jsm

@@ -24,6 +24,9 @@ XPCOMUtils.defineLazyServiceGetter(this, "contentSecManager",
                                    "@mozilla.org/contentsecuritymanager;1",
                                    "nsIContentSecurityManager");
 
+const TELEMETRY_SHOULD_LOAD_LOADING_KEY = "ADDON_CONTENT_POLICY_SHIM_BLOCKING_LOADING_MS";
+const TELEMETRY_SHOULD_LOAD_LOADED_KEY = "ADDON_CONTENT_POLICY_SHIM_BLOCKING_LOADED_MS";
+
 // Similar to Python. Returns dict[key] if it exists. Otherwise,
 // sets dict[key] to default_ and returns default_.
 function setDefault(dict, key, default_) {
@@ -155,10 +158,17 @@ var ContentPolicyChild = {
   _classID: Components.ID("6e869130-635c-11e2-bcfd-0800200c9a66"),
   _contractID: "@mozilla.org/addon-child/policy;1",
 
+  // A weak map of time spent blocked in hooks for a given document.
+  // WeakMap[document -> Map[addonId -> timeInMS]]
+  timings: new WeakMap(),
+
   init() {
     let registrar = Components.manager.QueryInterface(Ci.nsIComponentRegistrar);
     registrar.registerFactory(this._classID, this._classDescription, this._contractID, this);
 
+    this.loadingHistogram = Services.telemetry.getKeyedHistogramById(TELEMETRY_SHOULD_LOAD_LOADING_KEY);
+    this.loadedHistogram = Services.telemetry.getKeyedHistogramById(TELEMETRY_SHOULD_LOAD_LOADED_KEY);
+
     NotificationTracker.watch("content-policy", this);
   },
 
@@ -175,8 +185,69 @@ var ContentPolicyChild = {
     }
   },
 
+  // Returns a map of cumulative time spent in shouldLoad hooks for a
+  // given add-on in the given node's document. May return null if
+  // telemetry recording is disabled, or the given context does not
+  // point to a document.
+  getTimings(context) {
+    if (!Services.telemetry.canRecordExtended) {
+      return null;
+    }
+
+    let doc;
+    if (context instanceof Ci.nsIDOMNode) {
+      doc = context.ownerDocument;
+    } else if (context instanceof Ci.nsIDOMDocument) {
+      doc = context;
+    } else if (context instanceof Ci.nsIDOMWindow) {
+      doc = context.document;
+    }
+
+    if (!doc) {
+      return null;
+    }
+
+    let map = this.timings.get(doc);
+    if (!map) {
+      // No timing object exists for this document yet. Create one, and
+      // set up a listener to record the final values at the right time.
+      map = new Map();
+      this.timings.set(doc, map);
+
+      // If the document is still loading, record aggregate pre-load
+      // timings when the load event fires. If it's already loaded,
+      // record aggregate post-load timings when the page is hidden.
+      let eventName = doc.readyState == "complete" ? "pagehide" : "load";
+
+      let listener = event => {
+        if (event.target == doc) {
+          event.currentTarget.removeEventListener(eventName, listener, true);
+          this.logTelemetry(doc, eventName);
+        }
+      };
+      doc.defaultView.addEventListener(eventName, listener, true);
+    }
+    return map;
+  },
+
+  // Logs the accumulated telemetry for the given document, into the
+  // appropriate telemetry histogram based on the DOM event name that
+  // triggered it.
+  logTelemetry(doc, eventName) {
+    let map = this.timings.get(doc);
+    this.timings.delete(doc);
+
+    let histogram = eventName == "load" ? this.loadingHistogram : this.loadedHistogram;
+
+    for (let [addon, time] of map.entries()) {
+      histogram.add(addon, time);
+    }
+  },
+
   shouldLoad(contentType, contentLocation, requestOrigin,
                        node, mimeTypeGuess, extra, requestPrincipal) {
+    let startTime = Cu.now();
+
     let addons = NotificationTracker.findSuffixes(["content-policy"]);
     let [prefetched, cpows] = Prefetcher.prefetch("ContentPolicy.shouldLoad",
                                                   addons, {InitNode: node});
@@ -192,6 +263,17 @@ var ContentPolicyChild = {
       requestPrincipal,
       prefetched,
     }, cpows);
+
+    let timings = this.getTimings(node);
+    if (timings) {
+      let delta = Cu.now() - startTime;
+
+      for (let addon of addons) {
+        let old = timings.get(addon) || 0;
+        timings.set(addon, old + delta);
+      }
+    }
+
     if (rval.length != 1) {
       return Ci.nsIContentPolicy.ACCEPT;
     }

toolkit/components/telemetry/Histograms.json

@@ -28,6 +28,26 @@
     "n_buckets": 50,
     "description": "time spent updating accessibility (ms)"
   },
+  "ADDON_CONTENT_POLICY_SHIM_BLOCKING_LOADING_MS": {
+    "expires_in_version": "58",
+    "kind": "exponential",
+    "high": 60000,
+    "n_buckets": 20,
+    "keyed": true,
+    "description": "The amount of time the content process blocked processing shouldLoad shims for an add-on (keyed by add-on ID) prior to the load event, for each document load.",
+    "bug_numbers": [1331684],
+    "alert_emails": ["kmaglione@mozilla.com"]
+  },
+  "ADDON_CONTENT_POLICY_SHIM_BLOCKING_LOADED_MS": {
+    "expires_in_version": "58",
+    "kind": "exponential",
+    "high": 60000,
+    "n_buckets": 20,
+    "keyed": true,
+    "description": "The amount of time the content process blocked processing shouldLoad shims for an add-on (keyed by add-on ID) after the load event, for each document load.",
+    "bug_numbers": [1331684],
+    "alert_emails": ["kmaglione@mozilla.com"]
+  },
   "ADDON_MANAGER_UPGRADE_UI_SHOWN": {
     "expires_in_version": "53",
     "kind": "count",