Closed Bug 1070755 Opened 10 years ago Closed 9 years ago

Telemetry for main thread blockage due to plugin initialization

Categories

(Core Graveyard :: Plug-ins, defect)

defect
Not set
normal

Tracking

(firefox36 fixed, firefox37 affected)

RESOLVED FIXED
mozilla37
Tracking Status
firefox36 --- fixed
firefox37 --- affected

People

(Reporter: bugzilla, Assigned: bugzilla)

References

Details

Attachments

(3 files, 2 obsolete files)

We should add some telemetry probes that will allow us to quantify the jank reduction when various plugin perf work lands.

- PluginModuleParent: CreateToolhelp32Snapshot + Child process launch + NP_Initialize
- NPP_New
- NPP_NewStream on a per-instance basis (i.e., it's more useful to me to know the total time spent blocked on NPP_NewStream for an entire instance than to know how long each NPP_NewStream call is taking individually).
- NPP_Destroy
Attached patch Telemetry patch (obsolete) — Splinter Review
These probes are tracking main thread blockage based on jank I saw in the profiler.

I've written the NPP_NewStream probe to accumulate all timings into one per-instance value that is then submitted to the histogram. I think that for the purposes of async plugin init it is more useful to me to track the total time blocked on NPP_NewStream *per instance* than to time each call individually.
Attachment #8492795 - Flags: review?(benjamin)
I'm surprised that aggregating it per-instance would be a useful measurement. What I think we really care about is whether NPP_NewStream takes more than 50ms. If it takes *less* than that, then it doesn't really matter at all, and the number of times it takes more than 50ms becomes the interesting number. If you aggregate it per-instance, you lose that information which seems to me like the most important bits.
Attachment #8492795 - Flags: review?(benjamin)
Just a note: I think that keyed histograms would be a really elegant way to measure/record this. See bug 1069874, which gfritzsche is working on currently since we need it to migrate other FHR data.
Depends on: 1069874
Depends on: 1096785
Attached patch Pre async init version (obsolete) — Splinter Review
This patch is the "before" variant that should be uplifted to Aurora.
Attachment #8492795 - Attachment is obsolete: true
Attachment #8534502 - Flags: review?(vdjeric)
Comment on attachment 8534502 [details] [diff] [review]
Pre async init version

Review of attachment 8534502 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/plugins/ipc/PluginModuleParent.cpp
@@ +1446,5 @@
> +        TimeStamp callNpInitEnd = TimeStamp::Now();
> +        mTimeBlocked += (callNpInitEnd - callNpInitStart);
> +        Telemetry::Accumulate(Telemetry::BLOCKED_ON_PLUGIN_MODULE_INIT_MS,
> +                              GetHistogramKey(),
> +                              static_cast<uint32_t>(mTimeBlocked.ToMilliseconds()));

- So this is time spent in Launch() + CallNP_Initialize? Document this please
- maybe reset mTimeBlocked = 0 just in case?

@@ +1512,5 @@
> +    // because mTimeBlocked is modified in that function.
> +    Telemetry::Accumulate(Telemetry::BLOCKED_ON_PLUGIN_MODULE_INIT_MS,
> +                          GetHistogramKey(),
> +                          static_cast<uint32_t>(mTimeBlocked.ToMilliseconds()));
> +

- So which methods is this reporting on? Is it PluginModuleChromeParent::LoadModule + CallNP_Initialize + InitializeInjector?
- Document all the operations being measured next to the Accumulate calls that use mTimeBlocked
Attachment #8534502 - Flags: review?(vdjeric) → review+
Addressed Vladan's comments. Carrying forward r+.
Attachment #8534502 - Attachment is obsolete: true
Attachment #8535177 - Flags: review+
Comment on attachment 8535177 [details] [diff] [review]
Pre async init version

Approval Request Comment
[Feature/regressing bug #]: Async plugin initialization
[User impact if declined]: We won't be able to quantify user impact of landing subsequent patches related to this feature.
[Describe test coverage new/current, TBPL]: On m-c, confirmed on nightly in about:telemetry.
[Risks and why]: None, just telemetry changes.
[String/UUID change made/needed]: None
Attachment #8535177 - Flags: approval-mozilla-aurora?
Attached patch Key fixSplinter Review
I noticed when reviewing data in about:telemetry that the module init key is missing. This is because we can't actually retrieve plugin info in the module init functions; it hasn't been initialized in the plugin host yet.

Unfortunately the only way to make this work in the plugin startup sequence is to handle it lazily in NPP_New.
Attachment #8536809 - Flags: review?(vdjeric)
Attachment #8536809 - Flags: review?(vdjeric)
Attachment #8536809 - Flags: review+
Attachment #8536809 - Flags: approval-mozilla-aurora?
Attachment #8535177 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #8536809 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
This patch adds a new histogram that will be measured after landing async init: How long we spend waiting in PluginAsyncSurrogate::WaitForInit (i.e. a synchronous call came in that we absolutely must wait on the plugin to process).
Attachment #8538175 - Flags: review?(vdjeric)
Comment on attachment 8538175 [details] [diff] [review]
Telemetry for PluginAsyncSurrogate::WaitForInit

Review of attachment 8538175 [details] [diff] [review]:
-----------------------------------------------------------------

Shouldn't this be on the other bug?
Attachment #8538175 - Flags: review?(vdjeric) → review+
https://hg.mozilla.org/mozilla-central/rev/54c85be89886
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla37
Depends on: 1117883
Product: Core → Core Graveyard
You need to log in before you can comment on or make changes to this bug.