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)
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)
17.12 KB,
patch
|
bugzilla
:
review+
Sylvestre
:
approval-mozilla-aurora+
|
Details | Diff | Splinter Review |
3.22 KB,
patch
|
vladan
:
review+
Sylvestre
:
approval-mozilla-aurora+
|
Details | Diff | Splinter Review |
2.59 KB,
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•9 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•9 years ago
|
Keywords: leave-open
Comment 5•9 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•9 years ago
|
||
Addressed Vladan's comments. Carrying forward r+.
Attachment #8534502 -
Attachment is obsolete: true
Attachment #8535177 -
Flags: review+
Assignee | ||
Comment 7•9 years ago
|
||
https://hg.mozilla.org/integration/mozilla-inbound/rev/62a9e591e57d
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•9 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•9 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•9 years ago
|
Attachment #8536809 -
Flags: review?(vdjeric)
Attachment #8536809 -
Flags: review+
Attachment #8536809 -
Flags: approval-mozilla-aurora?
Assignee | ||
Comment 12•9 years ago
|
||
https://hg.mozilla.org/integration/mozilla-inbound/rev/f2f0d61c8acc
Updated•9 years ago
|
Attachment #8535177 -
Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Updated•9 years ago
|
Attachment #8536809 -
Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Comment 14•9 years ago
|
||
https://hg.mozilla.org/releases/mozilla-aurora/rev/740aa6b63465
status-firefox36:
--- → fixed
status-firefox37:
--- → affected
Assignee | ||
Comment 15•9 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•9 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•9 years ago
|
Keywords: leave-open
Assignee | ||
Comment 17•9 years ago
|
||
https://hg.mozilla.org/integration/mozilla-inbound/rev/076d1d47d601
Comment 18•9 years ago
|
||
Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/76d1641cf90b along with bug 998863.
Assignee | ||
Comment 19•9 years ago
|
||
Again: https://hg.mozilla.org/integration/mozilla-inbound/rev/54c85be89886
https://hg.mozilla.org/mozilla-central/rev/54c85be89886
Status: ASSIGNED → RESOLVED
Closed: 9 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
•