Instrument tab closing time from click to tab being gone

RESOLVED FIXED in Firefox 55

Status

()

Toolkit
Performance Monitoring
RESOLVED FIXED
2 months ago
18 days ago

People

(Reporter: Harald, Assigned: mconley)

Tracking

(Blocks: 2 bugs)

unspecified
mozilla55
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox55 fixed)

Details

(Whiteboard: [qf:p1])

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(5 attachments)

(Reporter)

Description

2 months ago
Came up before as area of concern where unload events and other bits can bring tab closing to a grinding halt.

Shooting this over to Mike as he landed the metrics that correctly measure tab closing.
(Reporter)

Updated

2 months ago
Flags: needinfo?(mconley)
Blocks: 1336241
Flags: needinfo?(mconley)
Blocks: 1344302
No longer blocks: 1336241
Whiteboard: [qf:p1]
Assignee: nobody → mconley
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Hey liuche, got time for two more data reviews? (Each of these two patches)
Flags: needinfo?(liuche)

Comment 4

a month ago
mozreview-review
Comment on attachment 8848231 [details]
Bug 1340842 - Add FX_TAB_CLOSE_PERMIT_UNLOAD_TIME_MS probe to measure how long it takes to run permitUnload on a tab when asked to close. , data-review=liuche

https://reviewboard.mozilla.org/r/121170/#review123146

::: browser/base/content/tabbrowser.xml:2648
(Diff revision 1)
> +              TelemetryStopwatch.start("FX_TAB_PERMIT_UNLOAD_TIME_MS", aTab);
>                let {permitUnload, timedOut} = aTab.linkedPanel ?
>                    browser.permitUnload() : {permitUnload: true, timedOut: false};
> +              TelemetryStopwatch.finish("FX_TAB_PERMIT_UNLOAD_TIME_MS", aTab);
> +
>                delete aTab._pendingPermitUnload;

The _pendingPermitUnload stuff is crucial to the above code block while the telemetry stuff is secondary. Please group and split as follows:

>              TelemetryStopwatch.start("FX_TAB_PERMIT_UNLOAD_TIME_MS", aTab);
>
>              // We need to block while calling permitUnload() because it
>              // processes the event queue and may lead to another removeTab()
>              // call before permitUnload() returns.
>              aTab._pendingPermitUnload = true;
>              let {permitUnload, timedOut} = aTab.linkedPanel ?
>                  browser.permitUnload() : {permitUnload: true, timedOut: false};
>              delete aTab._pendingPermitUnload;
>
>              TelemetryStopwatch.finish("FX_TAB_PERMIT_UNLOAD_TIME_MS", aTab);

Comment 5

a month ago
mozreview-review
Comment on attachment 8848231 [details]
Bug 1340842 - Add FX_TAB_CLOSE_PERMIT_UNLOAD_TIME_MS probe to measure how long it takes to run permitUnload on a tab when asked to close. , data-review=liuche

https://reviewboard.mozilla.org/r/121170/#review123148
Attachment #8848231 - Flags: review?(dtownsend) → review+
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Hey gfritzsche,

So I'm proposing this change to TelemetryStopwatch because for these FX_TAB_CLOSE_TIME_ probes, I won't know which histogram I'll want to use until _after_ the point where I want to start measuring. So what I'm doing instead is starting stopwatches on two histograms, and then canceling the one I don't want once the decision has been made. Then, "finish"ing both stopwatches at the end of the window of time I care about.

This results in errors being tossed into the console for the stopwatch we cancelled. I want to make it possible to opt in to suppressing those warnings, because the lack of a running stopwatch is kinda expected.

The reason I can't choose the histogram earlier is because we _might_ cause a style flush when deciding which histogram to use, and I want to make sure we capture that in whichever histogram we end up choosing. So kinda chicken and egg there.

Holding off on the review request for the FX_TAB_CLOSE_TIME_ probes until I hear back from gfritzsche.
(Assignee)

Comment 12

a month ago
mozreview-review
Comment on attachment 8848547 [details]
Bug 1340842 - Add tests for FX_TAB_CLOSE_TIME_ANIM_MS and FX_TAB_CLOSE_TIME_NO_ANIM_MS probes.

https://reviewboard.mozilla.org/r/121450/#review123472

::: browser/base/content/tabbrowser.xml:2878
(Diff revision 1)
> -            TelemetryStopwatch.finish("FX_TAB_CLOSE_TIME_ANIM_MS", aTab);
> -            TelemetryStopwatch.finish("FX_TAB_CLOSE_TIME_NO_ANIM_MS", aTab);
> +            TelemetryStopwatch.finish("FX_TAB_CLOSE_TIME_ANIM_MS", aTab,
> +                                      true /* aCanceledOkay */);
> +            TelemetryStopwatch.finish("FX_TAB_CLOSE_TIME_NO_ANIM_MS", aTab,
> +                                      true /* aCanceledOkay */);

Sorry, these should have been in an earlier patch.
(Assignee)

Comment 13

a month ago
mozreview-review-reply
Comment on attachment 8848231 [details]
Bug 1340842 - Add FX_TAB_CLOSE_PERMIT_UNLOAD_TIME_MS probe to measure how long it takes to run permitUnload on a tab when asked to close. , data-review=liuche

https://reviewboard.mozilla.org/r/121170/#review123146

> The _pendingPermitUnload stuff is crucial to the above code block while the telemetry stuff is secondary. Please group and split as follows:
> 
> >              TelemetryStopwatch.start("FX_TAB_PERMIT_UNLOAD_TIME_MS", aTab);
> >
> >              // We need to block while calling permitUnload() because it
> >              // processes the event queue and may lead to another removeTab()
> >              // call before permitUnload() returns.
> >              aTab._pendingPermitUnload = true;
> >              let {permitUnload, timedOut} = aTab.linkedPanel ?
> >                  browser.permitUnload() : {permitUnload: true, timedOut: false};
> >              delete aTab._pendingPermitUnload;
> >
> >              TelemetryStopwatch.finish("FX_TAB_PERMIT_UNLOAD_TIME_MS", aTab);

Thanks, done.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 18

a month ago
mozreview-review
Comment on attachment 8848546 [details]
Bug 1340842 - Allow BrowserTestUtils.removeTab to pass options along to tabbrowser's removeTab method.

https://reviewboard.mozilla.org/r/121448/#review123574

I love that we had a function called removeTab which could be set to not remove a tab.
Attachment #8848546 - Flags: review?(dtownsend) → review+

Comment 19

a month ago
mozreview-review
Comment on attachment 8848547 [details]
Bug 1340842 - Add tests for FX_TAB_CLOSE_TIME_ANIM_MS and FX_TAB_CLOSE_TIME_NO_ANIM_MS probes.

https://reviewboard.mozilla.org/r/121450/#review123578
Attachment #8848547 - Flags: review?(dtownsend) → review+
Attachment #8848545 - Flags: review?(gfritzsche) → review?(alessio.placitelli)

Comment 20

a month ago
mozreview-review
Comment on attachment 8848545 [details]
Bug 1340842 - Add argument to TelemetryStopwatch that allows us to suppress warnings when finishing previously canceled stopwatches.

https://reviewboard.mozilla.org/r/121446/#review124506

This looks good with the changes below, thanks!

Would you kindly also update the API [docs](http://searchfox.org/mozilla-central/source/toolkit/components/telemetry/docs/collection/measuring-time.rst)?

::: commit-message-3945f:1
(Diff revision 1)
> +Bug 1340842 - Add argument to TelemetryStopwatch that allows us to suppress warnings when finishing previously canceled stopwatches. r?gfritzsche

Could you please update the commit message to reflect the fact that I'm reviewing this now? (r?dexter)

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:171
(Diff revision 1)
>     *                              throw.
>     *
>     * @param (Object) aObj - Optional parameter which associates the histogram
>     *                        timer with the given object.
>     *
> +   * @param {bool} aCanceledOkay - Optional parameter which will suppress any

nit: could you change {bool} to {Boolean} for consistency with the rest of the doc strings in this file?

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:194
(Diff revision 1)
>     * @param {String} aHistogram - a string which must be a valid histogram name.
>     *
>     * @param {Object} aObj - Optional parameter which associates the histogram
>     *                        timer with the given object.
>     *
> +   * @param {bool} aCanceledOkay - Optional parameter which will suppress any

nit: {Boolean}

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:265
(Diff revision 1)
>     *                        the elapsed time.
>     *
>     * @return {Integer} time in milliseconds or -1 if the stopwatch was not
>     *                   found.
>     */
> -  timeElapsedKeyed(aHistogram, aKey, aObj) {
> +  timeElapsedKeyed(aHistogram, aKey, aObj, aCanceledOkay) {

Please update the docs for this function to account for the optional aCanceledOkay.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:282
(Diff revision 1)
>     * @param {String} aKey - a string which must be a valid histgram key.
>     *
>     * @param {Object} aObj - optional parameter which associates the histogram
>     *                        timer with the given object.
>     *
> +   * @param {bool} aCanceledOkay - Optional parameter which will suppress any

nit: {Boolean}
Attachment #8848545 - Flags: review?(alessio.placitelli)
Attachment #8848545 - Flags: review?(gfritzsche)
Attachment #8848230 - Flags: review?(dtownsend)
Attachment #8848545 - Flags: review?(gfritzsche)

Comment 21

a month ago
mozreview-review
Comment on attachment 8848230 [details]
Bug 1340842 - Add FX_TAB_CLOSE_TIME_ probes to measure how long it takes for tabs to close. , data-review=liuche

https://reviewboard.mozilla.org/r/121168/#review124530
Attachment #8848230 - Flags: review?(dtownsend) → review+
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Comment 27

a month ago
mozreview-review-reply
Comment on attachment 8848545 [details]
Bug 1340842 - Add argument to TelemetryStopwatch that allows us to suppress warnings when finishing previously canceled stopwatches.

https://reviewboard.mozilla.org/r/121446/#review124506

Thanks for reminding me about the docs! Is what I wrote sufficient?

Comment 28

a month ago
mozreview-review
Comment on attachment 8848230 [details]
Bug 1340842 - Add FX_TAB_CLOSE_TIME_ probes to measure how long it takes for tabs to close. , data-review=liuche

https://reviewboard.mozilla.org/r/121168/#review124598

Sorry for the delay - this probe looks good to me, especially the extra detail clarifying usage of these probes. Histogram entries are detailed and have time units, r+ on datareview.

Comment 29

a month ago
mozreview-review
Comment on attachment 8848230 [details]
Bug 1340842 - Add FX_TAB_CLOSE_TIME_ probes to measure how long it takes for tabs to close. , data-review=liuche

https://reviewboard.mozilla.org/r/121168/#review124600
Attachment #8848230 - Flags: review+

Comment 30

a month ago
mozreview-review
Comment on attachment 8848231 [details]
Bug 1340842 - Add FX_TAB_CLOSE_PERMIT_UNLOAD_TIME_MS probe to measure how long it takes to run permitUnload on a tab when asked to close. , data-review=liuche

https://reviewboard.mozilla.org/r/121170/#review124602

r+ on datareview
Attachment #8848231 - Flags: review+

Updated

a month ago
Flags: needinfo?(liuche)

Comment 31

a month ago
mozreview-review
Comment on attachment 8848545 [details]
Bug 1340842 - Add argument to TelemetryStopwatch that allows us to suppress warnings when finishing previously canceled stopwatches.

https://reviewboard.mozilla.org/r/121446/#review124844

Thank you very much, looks great now!
Attachment #8848545 - Flags: review?(alessio.placitelli) → review+

Comment 32

a month ago
Pushed by mconley@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6a68273665f6
Add argument to TelemetryStopwatch that allows us to suppress warnings when finishing previously canceled stopwatches. r=Dexter
https://hg.mozilla.org/integration/autoland/rev/a983c5ce4bc3
Add FX_TAB_CLOSE_TIME_ probes to measure how long it takes for tabs to close. r=liuche,mossop, data-review=liuche
https://hg.mozilla.org/integration/autoland/rev/b3abd0e89699
Allow BrowserTestUtils.removeTab to pass options along to tabbrowser's removeTab method. r=mossop
https://hg.mozilla.org/integration/autoland/rev/57ae2dd78f79
Add tests for FX_TAB_CLOSE_TIME_ANIM_MS and FX_TAB_CLOSE_TIME_NO_ANIM_MS probes. r=mossop
https://hg.mozilla.org/integration/autoland/rev/d24bb78a585c
Add FX_TAB_CLOSE_PERMIT_UNLOAD_TIME_MS probe to measure how long it takes to run permitUnload on a tab when asked to close. r=liuche,mossop, data-review=liuche
Hi Mike, sorry had to back this out for test failures like https://treeherder.mozilla.org/logviewer.html#?job_id=85647650&repo=autoland
Flags: needinfo?(mconley)

Comment 34

a month ago
Backout by cbook@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8113c3fc510e
Backed out changeset d24bb78a585c 
https://hg.mozilla.org/integration/autoland/rev/8c3f7e925453
Backed out changeset 57ae2dd78f79 
https://hg.mozilla.org/integration/autoland/rev/61395a7b774c
Backed out changeset b3abd0e89699 
https://hg.mozilla.org/integration/autoland/rev/c8c5e3975b97
Backed out changeset a983c5ce4bc3 
https://hg.mozilla.org/integration/autoland/rev/514deb92f427
Backed out changeset 6a68273665f6 for test failures in browser_bookmark_all_tabs.js
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 40

a month ago
Pushed by mconley@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/bb91f4c70703
Add argument to TelemetryStopwatch that allows us to suppress warnings when finishing previously canceled stopwatches. r=Dexter
https://hg.mozilla.org/integration/autoland/rev/042b0a4596ac
Add FX_TAB_CLOSE_TIME_ probes to measure how long it takes for tabs to close. r=liuche,mossop, data-review=liuche
https://hg.mozilla.org/integration/autoland/rev/4e837efa27f6
Allow BrowserTestUtils.removeTab to pass options along to tabbrowser's removeTab method. r=mossop
https://hg.mozilla.org/integration/autoland/rev/b4f0b770d50f
Add tests for FX_TAB_CLOSE_TIME_ANIM_MS and FX_TAB_CLOSE_TIME_NO_ANIM_MS probes. r=mossop
https://hg.mozilla.org/integration/autoland/rev/a11220e3fc9c
Add FX_TAB_CLOSE_PERMIT_UNLOAD_TIME_MS probe to measure how long it takes to run permitUnload on a tab when asked to close. r=liuche,mossop, data-review=liuche
Thanks for the backout! I believe I addressed the issue in the recent push.
Flags: needinfo?(mconley)

Comment 42

a month ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/bb91f4c70703
https://hg.mozilla.org/mozilla-central/rev/042b0a4596ac
https://hg.mozilla.org/mozilla-central/rev/4e837efa27f6
https://hg.mozilla.org/mozilla-central/rev/b4f0b770d50f
https://hg.mozilla.org/mozilla-central/rev/a11220e3fc9c
Status: NEW → RESOLVED
Last Resolved: a month ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Depends on: 1349787

Comment 43

18 days ago
This patch causing TelemetryStopwatch error when underflow call tabbrowser.removeTab for all tabbrowser._removingTabs

TelemetryStopwatch: key "FX_TAB_CLOSE_TIME_ANIM_MS" was already initialized TelemetryStopwatch.jsm:299
	start resource://gre/modules/TelemetryStopwatch.jsm:299:7
	start resource://gre/modules/TelemetryStopwatch.jsm:136:12
	removeTab chrome://browser/content/tabbrowser.xml:2549:13
	onxblunderflow chrome://browser/content/tabbrowser.xml:5631:11
	permitUnload chrome://global/content/bindings/remote-browser.xml:357:13
	_beginRemoveTab chrome://browser/content/tabbrowser.xml:2645:46
	removeTab chrome://browser/content/tabbrowser.xml:2570:18
	removeTabsToTheEndFrom chrome://browser/content/tabbrowser.xml:2490:17
	oncommand
(In reply to tabmix.onemen from comment #43)
> This patch causing TelemetryStopwatch error when underflow call
> tabbrowser.removeTab for all tabbrowser._removingTabs
> 
> TelemetryStopwatch: key "FX_TAB_CLOSE_TIME_ANIM_MS" was already initialized
> TelemetryStopwatch.jsm:299
> 	start resource://gre/modules/TelemetryStopwatch.jsm:299:7
> 	start resource://gre/modules/TelemetryStopwatch.jsm:136:12
> 	removeTab chrome://browser/content/tabbrowser.xml:2549:13
> 	onxblunderflow chrome://browser/content/tabbrowser.xml:5631:11
> 	permitUnload chrome://global/content/bindings/remote-browser.xml:357:13
> 	_beginRemoveTab chrome://browser/content/tabbrowser.xml:2645:46
> 	removeTab chrome://browser/content/tabbrowser.xml:2570:18
> 	removeTabsToTheEndFrom chrome://browser/content/tabbrowser.xml:2490:17
> 	oncommand

filed bug 1354800
Depends on: 1354800
You need to log in before you can comment on or make changes to this bug.