Add telemetry to collect how much time was spent in beforeunload and unload handler

RESOLVED FIXED in Firefox 52

Status

()

defect
RESOLVED FIXED
3 years ago
2 years ago

People

(Reporter: kanru, Assigned: kanru)

Tracking

(Blocks 1 bug)

unspecified
mozilla52
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox51-, firefox52 fixed)

Details

Attachments

(1 attachment)

For bug 1279293 we would like to know how much time was spent in beforeunload and unload handler during shutdown. If one tab using sync xhr takes 200ms then 25 tabs can easily make shutdown taking more than 5 seconds.
Attachment #8789664 - Flags: review?(benjamin)
Comment on attachment 8789664 [details]
Bug 1301346 - Add telemetry to collect how much time was spent in handling beforeunload and unload event.

https://reviewboard.mozilla.org/r/77798/#review76284

::: dom/events/EventDispatcher.cpp:500
(Diff revision 1)
>                   NS_ERROR_DOM_INVALID_STATE_ERR);
>  
> +  Maybe<Telemetry::AutoTimer<Telemetry::HANDLE_UNLOAD_MS>> unloadTelemetryTimer;
> +  Maybe<Telemetry::AutoTimer<Telemetry::HANDLE_BEFOREUNLOAD_MS>> beforeUnloadTelemetryTimer;
> +
> +  if (aDOMEvent) {

Did you actually test this, since we may not have aDOMEvent at all here, just aEvent, at least in case of unload:
http://searchfox.org/mozilla-central/rev/950e13cca1fda6507dc53c243295044e8eda4493/layout/base/nsDocumentViewer.cpp#1312,1321
And we don't want slow string comparisons here.
Could you put the telemetry  around the place where we dispatch those events (in DocumentViewer.cpp).
Attachment #8789664 - Flags: review?(bugs) → review-
(In reply to Olli Pettay [:smaug] from comment #2)
> Comment on attachment 8789664 [details]
> Bug 1301346 - Add telemetry to collect how much time was spent in
> beforeunload and unload handler.  data-review=bsmedberg
> 
> https://reviewboard.mozilla.org/r/77798/#review76284
> 
> ::: dom/events/EventDispatcher.cpp:500
> (Diff revision 1)
> >                   NS_ERROR_DOM_INVALID_STATE_ERR);
> >  
> > +  Maybe<Telemetry::AutoTimer<Telemetry::HANDLE_UNLOAD_MS>> unloadTelemetryTimer;
> > +  Maybe<Telemetry::AutoTimer<Telemetry::HANDLE_BEFOREUNLOAD_MS>> beforeUnloadTelemetryTimer;
> > +
> > +  if (aDOMEvent) {
> 
> Did you actually test this, since we may not have aDOMEvent at all here,
> just aEvent, at least in case of unload:
> http://searchfox.org/mozilla-central/rev/
> 950e13cca1fda6507dc53c243295044e8eda4493/layout/base/nsDocumentViewer.
> cpp#1312,1321

Yes, tested but I didn't expect that unload might come as a WidgetEvent.

> And we don't want slow string comparisons here.
> Could you put the telemetry  around the place where we dispatch those events
> (in DocumentViewer.cpp).

CreateEvent has a even longer string comparisons there so I thought this might be acceptable. I could put them around the place where events are dispatched.. there shouldn't be too many, right?
I mean you should put telemetry where we dispatch the events, so to DocumentViewer.cpp
remember that 'unload' for example is used in other cases too than just page unload.
Comment on attachment 8789664 [details]
Bug 1301346 - Add telemetry to collect how much time was spent in handling beforeunload and unload event.

https://reviewboard.mozilla.org/r/77798/#review77066
Attachment #8789664 - Flags: review?(benjamin)
Comment on attachment 8789664 [details]
Bug 1301346 - Add telemetry to collect how much time was spent in handling beforeunload and unload event.

https://reviewboard.mozilla.org/r/77798/#review86206

Just nit about the comment, since there can be event listeners and event handlers and dispatching an event call them all. So, it is about handling the event.

::: toolkit/components/telemetry/Histograms.json:10358
(Diff revision 2)
> +    "expires_in_version": "55",
> +    "kind": "exponential",
> +    "high": 10000,
> +    "n_buckets": 50,
> +    "bug_numbers": [1301346],
> +    "description": "The time spent in the unload event handler."

The time spent handling unload event.

::: toolkit/components/telemetry/Histograms.json:10367
(Diff revision 2)
> +    "expires_in_version": "55",
> +    "kind": "exponential",
> +    "high": 10000,
> +    "n_buckets": 50,
> +    "bug_numbers": [1301346],
> +    "description": "The time spent in the beforeunload event handler."

The time spent handling beforeunload event.
Attachment #8789664 - Flags: review?(bugs) → review+
Flags: needinfo?(benjamin)
Comment on attachment 8789664 [details]
Bug 1301346 - Add telemetry to collect how much time was spent in handling beforeunload and unload event.

https://reviewboard.mozilla.org/r/77798/#review87748

Also, this doesn't come with any automated tests. For a short-term exploratory measurement that's fine, although you should test this by hand. If you want to extend this to a long-term metric it should have an automated test.

::: toolkit/components/telemetry/Histograms.json:10358
(Diff revision 2)
> +    "expires_in_version": "55",
> +    "kind": "exponential",
> +    "high": 10000,
> +    "n_buckets": 50,
> +    "bug_numbers": [1301346],
> +    "description": "The time spent in the unload event handler."

If there are multiple handlers for the unload event, will this record a separate value for each handler, or will it record a single value across all handlers?

What documents does this measure? content/chrome or both? Presumably subframes are recorded separately?

Please document more of the details.
Attachment #8789664 - Flags: review?(benjamin) → review-
Comment on attachment 8789664 [details]
Bug 1301346 - Add telemetry to collect how much time was spent in handling beforeunload and unload event.

https://reviewboard.mozilla.org/r/77798/#review87748

I tested this by hand. I'm curious and for future references, how should one normally write tests for telemetry?

> If there are multiple handlers for the unload event, will this record a separate value for each handler, or will it record a single value across all handlers?
> 
> What documents does this measure? content/chrome or both? Presumably subframes are recorded separately?
> 
> Please document more of the details.

If there are multiple handlers for the unload event in a document, this will record a single value across all handlers. It measures all documents and subframes separately. As the intention is to collect the average time spent in handling unlload event and the possibilty of affecting content shutdown, I think it meets the needs.
Comment on attachment 8789664 [details]
Bug 1301346 - Add telemetry to collect how much time was spent in handling beforeunload and unload event.

https://reviewboard.mozilla.org/r/77798/#review88122
Attachment #8789664 - Flags: review?(benjamin) → review+
Pushed by kchen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/466b0de6dfcb
Add telemetry to collect how much time was spent in handling beforeunload and unload event. r=bsmedberg,smaug
Flags: needinfo?(benjamin)
https://hg.mozilla.org/mozilla-central/rev/466b0de6dfcb
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla52
Track 51+ as this can help get more data for bug 1279293.
Hi Kan-ru,
Can we uplift this to 51 aurora?
Flags: needinfo?(kchen)
(In reply to Gerry Chang [:gchang] from comment #16)
> Track 51+ as this can help get more data for bug 1279293.
> Hi Kan-ru,
> Can we uplift this to 51 aurora?

I think we don't need to uplift to 51 because ShutDownKill on Nightly represents about 50% of content crashes. Based on the current number collected by the probes I think the spent in the unload handler is hardly the main reason of the ShutDownKill.
Flags: needinfo?(kchen)
Thanks. Kan-Ru. 
Track 51- as no need to get data for 51 aurora.
Blocks: 1346161
You need to log in before you can comment on or make changes to this bug.