Bug 1331684: Record time spent blocked on shouldLoad shims per add-on. r=billm data-r?bsmedberg draft
authorKris Maglione <maglione.k@gmail.com>
Tue, 24 Jan 2017 16:29:53 -0800
changeset 485486 888163c226dc219fade9967a6ec9549de8d4da40
parent 482481 fd808fa77e801cb6185993c95497999b4161cee7
child 546030 bf13bfc12472489b35021a4e79fa6f6801e21486
push id45745
push usermaglione.k@gmail.com
push dateThu, 16 Feb 2017 19:26:41 +0000
reviewersbillm
bugs1331684
milestone54.0a1
Bug 1331684: Record time spent blocked on shouldLoad shims per add-on. r=billm data-r?bsmedberg MozReview-Commit-ID: K6bYourTigx
toolkit/components/addoncompat/RemoteAddonsChild.jsm
toolkit/components/telemetry/Histograms.json
--- a/toolkit/components/addoncompat/RemoteAddonsChild.jsm
+++ b/toolkit/components/addoncompat/RemoteAddonsChild.jsm
@@ -19,16 +19,19 @@ XPCOMUtils.defineLazyModuleGetter(this, 
 
 XPCOMUtils.defineLazyServiceGetter(this, "SystemPrincipal",
                                    "@mozilla.org/systemprincipal;1", "nsIPrincipal");
 
 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_) {
   if (key in dict) {
     return dict[key];
   }
   dict[key] = default_;
   return default_;
@@ -150,53 +153,132 @@ var NotificationTracker = {
 // it runs, it notifies the parent that it needs to run its own
 // nsIContentPolicy list. If any policy in the parent rejects a
 // resource load, that answer is returned to the child.
 var ContentPolicyChild = {
   _classDescription: "Addon shim content policy",
   _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);
   },
 
   QueryInterface: XPCOMUtils.generateQI([Ci.nsIContentPolicy, Ci.nsIObserver,
                                          Ci.nsIChannelEventSink, Ci.nsIFactory,
                                          Ci.nsISupportsWeakReference]),
 
   track(path, register) {
     let catMan = Cc["@mozilla.org/categorymanager;1"].getService(Ci.nsICategoryManager);
     if (register) {
       catMan.addCategoryEntry("content-policy", this._contractID, this._contractID, false, true);
     } else {
       catMan.deleteCategoryEntry("content-policy", this._contractID, false);
     }
   },
 
+  // 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});
     cpows.node = node;
 
     let cpmm = Cc["@mozilla.org/childprocessmessagemanager;1"]
                .getService(Ci.nsISyncMessageSender);
     let rval = cpmm.sendRpcMessage("Addons:ContentPolicy:Run", {
       contentType,
       contentLocation: contentLocation.spec,
       requestOrigin: requestOrigin ? requestOrigin.spec : null,
       mimeTypeGuess,
       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;
     }
 
     return rval[0];
   },
 
   shouldProcess(contentType, contentLocation, requestOrigin, insecNode, mimeType, extra) {
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -23,16 +23,36 @@
   },
   "A11Y_UPDATE_TIME": {
     "expires_in_version": "default",
     "kind": "exponential",
     "high": 10000,
     "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",
     "description": "Recorded when the addon manager shows the modal upgrade UI. Should only be recorded once per upgrade.",
     "releaseChannelCollection": "opt-out",
     "bug_numbers": [1268548],
     "alert_emails": ["kev@mozilla.com"]
   },