Bug 1331684: Record time spent blocked on shouldLoad shims per add-on. r=billm data-r?bsmedberg
MozReview-Commit-ID: K6bYourTigx
--- 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"]
},