Closed Bug 1356323 Opened 3 years ago Closed 2 years ago

Add telemetry for time spent injecting content scripts

Categories

(WebExtensions :: General, enhancement, P1)

51 Branch
enhancement

Tracking

(Not tracked)

RESOLVED FIXED
mozilla56

People

(Reporter: bsilverberg, Assigned: bsilverberg)

References

(Blocks 1 open bug)

Details

(Whiteboard: [metrics] triaged)

Attachments

(1 file)

This is a bug to add a probe for time spent injecting content scripts.
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 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.
Oh, I also changed the histogram to report only for the "main" process, which I think is correct.
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+
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)
Flags: needinfo?(kmaglione+bmo)
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 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+
Attachment #8863736 - Flags: feedback?(benjamin)
Pushed by bsilverberg@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2bcf04b9b40b
Add telemetry for time spent injecting content scripts, r=bsmedberg,kmag
https://hg.mozilla.org/mozilla-central/rev/2bcf04b9b40b
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
Depends on: 1425957
Product: Toolkit → WebExtensions
See Also: → 1476641
You need to log in before you can comment on or make changes to this bug.