1340842 - Instrument tab closing time from click to tab being gone

Status: RESOLVED FIXED

(Toolkit :: Performance Monitoring, defect)

Description

[:Harald Kirschner :digitarald]

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.

Comment 1

[Mike Conley (:mconley) (:⚙️)]

Attachment: Bug 1340842 - Add FX_TAB_CLOSE_TIME_ probes to measure how long it takes for tabs to close. , data-review=liuche

Review commit: https://reviewboard.mozilla.org/r/121168/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/121168/

Comment 2

[Mike Conley (:mconley) (:⚙️)]

Attachment: 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

Review commit: https://reviewboard.mozilla.org/r/121170/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/121170/

Comment 3

[Mike Conley (:mconley) (:⚙️)]

Hey liuche, got time for two more data reviews? (Each of these two patches)

Comment 4

[Dão Gottwald [:dao]]

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

[Dave Townsend [:mossop]]

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

Comment 6

[Mike Conley (:mconley) (:⚙️)]

Attachment: Bug 1340842 - Add argument to TelemetryStopwatch that allows us to suppress warnings when finishing previously canceled stopwatches.

Review commit: https://reviewboard.mozilla.org/r/121446/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/121446/

Comment 7

[Mike Conley (:mconley) (:⚙️)]

Attachment: Bug 1340842 - Allow BrowserTestUtils.removeTab to pass options along to tabbrowser's removeTab method.

There were options already being passed to BrowserTestUtils.removeTab, with only
a single property being observed, "dontRemove". This caused BrowserTestUtils.removeTab
to return a Promise once a tab is removed, but didn't actually remove the tab (as the
calling test would be responsible for that themselves). This patch removes that option,
and adds a method to BrowserTestUtils called tabRemoved to use for that case instead.

The options being passed to removeTab are now forwarded along directly to tabbrowser's
removeTab method.

Review commit: https://reviewboard.mozilla.org/r/121448/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/121448/

Comment 8

[Mike Conley (:mconley) (:⚙️)]

Attachment: Bug 1340842 - Add tests for FX_TAB_CLOSE_TIME_ANIM_MS and FX_TAB_CLOSE_TIME_NO_ANIM_MS probes.

Review commit: https://reviewboard.mozilla.org/r/121450/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/121450/

Comment 9

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121168/diff/1-2/

Comment 10

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121170/diff/1-2/

Comment 11

[Mike Conley (:mconley) (:⚙️)]

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.

Comment 12

[Mike Conley (:mconley) (:⚙️)]

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.

Comment 13

[Mike Conley (:mconley) (:⚙️)]

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 14

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121168/diff/2-3/

Comment 15

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121448/diff/1-2/

Comment 16

[Mike Conley (:mconley) (:⚙️)]

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.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121450/diff/1-2/

Comment 17

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121170/diff/2-3/

Comment 18

[Dave Townsend [:mossop]]

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.

Comment 19

[Dave Townsend [:mossop]]

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

Comment 20

[Alessio Placitelli [:Dexter]]

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}

Comment 21

[Dave Townsend [:mossop]]

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

Comment 22

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121446/diff/1-2/

Comment 23

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121168/diff/3-4/

Comment 24

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121448/diff/2-3/

Comment 25

[Mike Conley (:mconley) (:⚙️)]

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.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121450/diff/2-3/

Comment 26

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121170/diff/3-4/

Comment 27

[Mike Conley (:mconley) (:⚙️)]

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

[Chenxia Liu [:liuche]]

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

[Chenxia Liu [:liuche]]

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

Comment 30

[Chenxia Liu [:liuche]]

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

Comment 31

[Alessio Placitelli [:Dexter]]

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!

Comment 32

[Pulsebot]

Pushed by [e-mail]:
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

Comment 33

[Carsten Book [:Tomcat]]

Hi Mike, sorry had to back this out for test failures like https://treeherder.mozilla.org/logviewer.html#?job_id=85647650&repo=autoland

Comment 34

[Pulsebot]

Backout by [e-mail]:
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 35

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121446/diff/2-3/

Comment 36

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121168/diff/4-5/

Comment 37

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121448/diff/3-4/

Comment 38

[Mike Conley (:mconley) (:⚙️)]

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.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121450/diff/3-4/

Comment 39

[Mike Conley (:mconley) (:⚙️)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121170/diff/4-5/

Comment 40

[Pulsebot]

Pushed by [e-mail]:
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

Comment 41

[Mike Conley (:mconley) (:⚙️)]

Thanks for the backout! I believe I addressed the issue in the recent push.

Comment 42

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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

Comment 43

[tabmix.onemen]

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

Comment 44

[Dão Gottwald [:dao]]

(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

Comment 45

[Ryan VanderMeulen [:RyanVM]]

(In reply to Wes Kocher (:KWierso) from comment #42)
> https://hg.mozilla.org/mozilla-central/rev/4e837efa27f6

I uplifted this changeset to Beta to fix bustage from another uplift where the test expected BrowserTestUtils.tabRemoved to exist:
https://hg.mozilla.org/releases/mozilla-beta/rev/0241994e3aad