Add telemetry for time spent injecting content scripts

RESOLVED FIXED in Firefox 56

Status

()

Toolkit
WebExtensions: General
P1
normal
RESOLVED FIXED
4 months ago
2 months ago

People

(Reporter: bsilverberg, Assigned: bsilverberg)

Tracking

(Blocks: 1 bug)

51 Branch
mozilla56
Points:
---

Firefox Tracking Flags

(firefox56 fixed)

Details

(Whiteboard: [metrics] triaged)

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment)

(Assignee)

Description

4 months ago
This is a bug to add a probe for time spent injecting content scripts.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 5

3 months ago
mozreview-review
Comment on attachment 8863736 [details]
Bug 1356323 - Add telemetry for time spent injecting content scripts,

https://reviewboard.mozilla.org/r/135518/#review147150

::: toolkit/components/extensions/extension-process-script.js:437
(Diff revision 4)
>        }
>      }
>    },
>  
>    injectWindowScripts(window) {
> +    TelemetryStopwatch.start(contentScriptInjectionHistogram, this);

This won't work for several reasons. What we need to measure is the amount of per-script time actually injecting the scripts into the global:

http://searchfox.org/mozilla-central/rev/c195cc1698da2d3116fd8594db44614bb1304719/toolkit/components/extensions/ExtensionContent.jsm#322-330

This won't actually measure anything, since the injectInto function is asynchronous. Even if it weren't, it would measure the time injecting all static extension scripts (not dynamically-injected ones). And the `this` object also wouldn't work as a context object, since the same instance is used to inject scripts into every window and frame.
Attachment #8863736 - Flags: review?(kmaglione+bmo)
Comment hidden (mozreview-request)
(Assignee)

Comment 7

3 months ago
mozreview-review-reply
Comment on attachment 8863736 [details]
Bug 1356323 - Add telemetry for time spent injecting content scripts,

https://reviewboard.mozilla.org/r/135518/#review147150

> This won't work for several reasons. What we need to measure is the amount of per-script time actually injecting the scripts into the global:
> 
> http://searchfox.org/mozilla-central/rev/c195cc1698da2d3116fd8594db44614bb1304719/toolkit/components/extensions/ExtensionContent.jsm#322-330
> 
> This won't actually measure anything, since the injectInto function is asynchronous. Even if it weren't, it would measure the time injecting all static extension scripts (not dynamically-injected ones). And the `this` object also wouldn't work as a context object, since the same instance is used to inject scripts into every window and frame.

I made a number of changes which I hope are close to what is required. I wasn't sure if you wanted it to be more granular and include timings separately for each script injected at http://searchfox.org/mozilla-central/rev/c195cc1698da2d3116fd8594db44614bb1304719/toolkit/components/extensions/ExtensionContent.jsm#324-326.

I also added a mochitest for dynamic content scripts, although it's currently failing and I'm not sure why. Based on my debugging, and the fact that the message is being sent from the content script, I can see that the content script is being run, and that the places where I start and stop the TelemetryStopwatch in `handleExtensionExecute` are being hit. The test completes without timing out, but my final assertion about the telemetry being recorded fails.

Please take a look at my latest commit and let me know how it looks.
(Assignee)

Comment 8

3 months ago
Oh, I also changed the histogram to report only for the "main" process, which I think is correct.

Comment 9

2 months ago
mozreview-review
Comment on attachment 8863736 [details]
Bug 1356323 - Add telemetry for time spent injecting content scripts,

https://reviewboard.mozilla.org/r/135518/#review152074

r=me with corrections

::: toolkit/components/extensions/ExtensionContent.jsm:328
(Diff revision 5)
>      for (let script of scripts) {
>        result = script.executeInGlobal(context.cloneScope);
>      }
>  
>      if (this.options.jsCode) {
>        result = Cu.evalInSandbox(this.options.jsCode, context.cloneScope, "latest");
>      }
> +    TelemetryStopwatch.finish(CONTENT_SCRIPT_INJECTION_HISTOGRAM, context);

Any of these executions can throw. We need a try-finally block to make sure the stopwatch is always finalized.

::: toolkit/components/extensions/ExtensionContent.jsm:719
(Diff revision 5)
> +    TelemetryStopwatch.start(CONTENT_SCRIPT_INJECTION_HISTOGRAM, script);
>      let result = await Promise.all(promises);
> +    TelemetryStopwatch.finish(CONTENT_SCRIPT_INJECTION_HISTOGRAM, script);

Please remove these. We're already timing these scripts with the timer above. This adds a second, somewhat different time for each of them.

::: toolkit/components/telemetry/Histograms.json:13261
(Diff revision 5)
>      "high": 60000,
>      "n_buckets": 100,
>      "description": "The amount of time it takes to load a WebExtensions background page, from when the build function is called to when the page has finished processing the onload event."
>    },
> +  "WEBEXT_CONTENT_SCRIPT_INJECTION_MS": {
> +    "record_in_processes": ["main"],

We need this in content processes too.
Attachment #8863736 - Flags: review?(kmaglione+bmo) → review+
Comment hidden (mozreview-request)
(Assignee)

Comment 11

2 months ago
Thanks for the review, Kris. I have made the changes you requested, but they do not address the problem I had with the mochitest I added for a dynamic content script. Do you have any suggestions for what the problem might be (which I discussed in comment #7), or should I just remove that test for now? Your r+ means this is good to land, but it cannot land with that failing test.
Flags: needinfo?(kmaglione+bmo)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Updated

2 months ago
Flags: needinfo?(kmaglione+bmo)
(Assignee)

Comment 14

2 months ago
Comment on attachment 8863736 [details]
Bug 1356323 - Add telemetry for time spent injecting content scripts,

Requesting data review for a new temporary telemetry probe to gather information about the time it takes to inject content scripts. This information will be used to help with design decisions about the implementation.
Attachment #8863736 - Flags: feedback?(benjamin)

Comment 15

2 months ago
mozreview-review
Comment on attachment 8863736 [details]
Bug 1356323 - Add telemetry for time spent injecting content scripts,

https://reviewboard.mozilla.org/r/135518/#review156370

data-r=me
Attachment #8863736 - Flags: review+

Updated

2 months ago
Attachment #8863736 - Flags: feedback?(benjamin)

Comment 16

2 months ago
Pushed by bsilverberg@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2bcf04b9b40b
Add telemetry for time spent injecting content scripts, r=bsmedberg,kmag

Comment 17

2 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/2bcf04b9b40b
Status: NEW → RESOLVED
Last Resolved: 2 months ago
status-firefox56: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
You need to log in before you can comment on or make changes to this bug.