Closed
Bug 1070755
Opened 10 years ago
Closed 10 years ago
Telemetry for main thread blockage due to plugin initialization
Categories
(Core Graveyard :: Plug-ins, defect)
Core Graveyard
Plug-ins
Tracking
(firefox36 fixed, firefox37 affected)
RESOLVED
FIXED
mozilla37
People
(Reporter: bugzilla, Assigned: bugzilla)
References
Details
Attachments
(3 files, 2 obsolete files)
(deleted),
patch
|
bugzilla
:
review+
Sylvestre
:
approval-mozilla-aurora+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
vladan
:
review+
Sylvestre
:
approval-mozilla-aurora+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
vladan
:
review+
|
Details | Diff | Splinter Review |
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
Assignee | ||
Comment 1•10 years ago
|
||
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)
Comment 2•10 years ago
|
||
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.
Updated•10 years ago
|
Attachment #8492795 -
Flags: review?(benjamin)
Comment 3•10 years ago
|
||
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
Assignee | ||
Comment 4•10 years ago
|
||
This patch is the "before" variant that should be uplifted to Aurora.
Attachment #8492795 -
Attachment is obsolete: true
Attachment #8534502 -
Flags: review?(vdjeric)
Assignee | ||
Updated•10 years ago
|
Keywords: leave-open
Comment 5•10 years ago
|
||
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+
Assignee | ||
Comment 6•10 years ago
|
||
Addressed Vladan's comments. Carrying forward r+.
Attachment #8534502 -
Attachment is obsolete: true
Attachment #8535177 -
Flags: review+
Assignee | ||
Comment 7•10 years ago
|
||
I accidentally backed this out in https://hg.mozilla.org/integration/mozilla-inbound/rev/fabce979edd7 (I meant to back out bug 1108728 for bustage, but grabbed the wrong revision)
Relanded this in https://hg.mozilla.org/integration/mozilla-inbound/rev/8eea64db9552
Assignee | ||
Comment 10•10 years ago
|
||
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?
Assignee | ||
Comment 11•10 years ago
|
||
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)
Updated•10 years ago
|
Attachment #8536809 -
Flags: review?(vdjeric)
Attachment #8536809 -
Flags: review+
Attachment #8536809 -
Flags: approval-mozilla-aurora?
Assignee | ||
Comment 12•10 years ago
|
||
Comment 13•10 years ago
|
||
Updated•10 years ago
|
Attachment #8535177 -
Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Updated•10 years ago
|
Attachment #8536809 -
Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Comment 14•10 years ago
|
||
status-firefox36:
--- → fixed
status-firefox37:
--- → affected
Assignee | ||
Comment 15•10 years ago
|
||
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 16•10 years ago
|
||
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+
Assignee | ||
Updated•10 years ago
|
Keywords: leave-open
Assignee | ||
Comment 17•10 years ago
|
||
Comment 18•10 years ago
|
||
Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/76d1641cf90b along with bug 998863.
Assignee | ||
Comment 19•10 years ago
|
||
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla37
Updated•2 years ago
|
Product: Core → Core Graveyard
You need to log in
before you can comment on or make changes to this bug.
Description
•