1233368 - tabbrowser.xml calls TelemetryStopwatch.finish() for FX_TAB_SWITCH_TOTAL_E10S_MS twice

Status: RESOLVED FIXED

(Firefox :: Tabbed Browser, defect, P1)

Description

[Iaroslav Sheptykin]

Attachment: tabbrowser-telemetry-stopwatch.log

While working on bug 1205898 we noticed that some code in tabbrowser.xml is calling TelemetryStopwatch.timeElapsed twice for the Histogram FX_TAB_SWITCH_TOTAL_E10S_MS, where as TelemetryStopwatch.start("FX_TAB_SWITCH_TOTAL_E10S_MS") is only called once. 

According to callstacks, here is the place where it happens: 
https://dxr.mozilla.org/mozilla-central/source/browser/base/content/tabbrowser.xml#3535

After the patch for bug 1205898 lands this will cause a similar message to appear in testing logs and possibly in browser console:

13:24:23     INFO -  3 INFO TEST-INFO | (browser-test.js) | Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_TOTAL_E10S_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 303}]

STR:
0. if bug 1205898 is still open modify 
https://dxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/TelemetryStopwatch.jsm#153
to include some debug output as for example:
dump("*** ERROR ***: TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: " + aHistogram + "\n");

1. ./mach test browser/base/content/test/ --e`0s | grep "TelemetryStopwatch"
2. Observe the error reports.

See the attached file for a sample output obtained by running:
./mach test browser/base/content/test/general/browser_action_keyword.js --e10s > tabbrowser-telemetry-stopwatch.log

Comment 1

[Iaroslav Sheptykin]

Hi Georg! Here is another bug related to our work on TelemetryStopwatch. Adding a needinfo for Jim because he worked on this code according to hg blame. (changeset https://hg.mozilla.org/mozilla-central/rev/3265c932f222). Jim, do you have an idea why we would see this happening?

Comment 2

[Georg Fritzsche [:gfritzsche]]

Waiting on whether Jim knows how to proceed here.

Comment 3

[Jim Mathies [:jimm]]

Looks like we end up calling finishTabSwitch more than once, and the check we do there passes multiple times. That's interesting since we also fire dom events in here. We should look at this.

Comment 4

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

I am unable to reproduce this on either my OS X machine or my Ubuntu VM using latest central (388bdc46ba51). Are you still seeing this?

Comment 5

[Iaroslav Sheptykin]

Attachment: telemetry-stopwatch-tabbrowser.log

Hey Mike! I pointed to the wrong place in STR, sorry. The code in tabbrowser calls timeElapsed directly thus timeElapsed has to be modified. Just insert some debug output before return -1 here:

https://dxr.mozilla.org/mozilla-central/rev/388bdc46ba51ee31da8b8abe977e0ca38d117434/toolkit/components/telemetry/TelemetryStopwatch.jsm#117

then:
./mach mochitest browser/base/content/test/general/browser_action_keyword.js --e10s

this produces the output as attached on my ubuntu machine. Does this work for you?

Comment 6

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

Yes, I'm seeing this now. Thank you!

Comment 7

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

Actually, putting back the needinfo so I can try to answer _why_ this is occurring.

Comment 9

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

Here are the stacks for calling finishTabSwitch twice:

First time:

_getSwitcher/switcher.finishTabSwitch@chrome://browser/content/tabbrowser.xml:3544:46
_getSwitcher/switcher.onLayersReady@chrome://browser/content/tabbrowser.xml:3413:15
_getSwitcher/switcher.handleEvent@chrome://browser/content/tabbrowser.xml:3506:17
EventListener.handleEvent*_getSwitcher/switcher.init@chrome://browser/content/tabbrowser.xml:3156:15
_getSwitcher@chrome://browser/content/tabbrowser.xml:3676:11
set_selectedIndex@chrome://browser/content/tabbrowser.xml:6499:11
set_selectedPanel@chrome://global/content/bindings/tabbox.xml:687:13
set_selectedIndex@chrome://global/content/bindings/tabbox.xml:403:15
set_selectedItem@chrome://global/content/bindings/tabbox.xml:435:34
set_selectedTab@chrome://global/content/bindings/tabbox.xml:114:15
set_selectedTab@chrome://browser/content/tabbrowser.xml:2813:11
_blurTab@chrome://browser/content/tabbrowser.xml:2437:13
_endRemoveTab@chrome://browser/content/tabbrowser.xml:2304:13
removeTab@chrome://browser/content/tabbrowser.xml:2146:15

Second time:

_getSwitcher/switcher.finishTabSwitch@chrome://browser/content/tabbrowser.xml:3546:47
_getSwitcher/switcher.spinnerHidden@chrome://browser/content/tabbrowser.xml:3564:15
_getSwitcher/switcher.updateDisplay@chrome://browser/content/tabbrowser.xml:3230:17
_getSwitcher/switcher.postActions@chrome://browser/content/tabbrowser.xml:3350:15
_getSwitcher/switcher.handleEvent@chrome://browser/content/tabbrowser.xml:3515:15
EventListener.handleEvent*_getSwitcher/switcher.init@chrome://browser/content/tabbrowser.xml:3156:15
_getSwitcher@chrome://browser/content/tabbrowser.xml:3676:11
set_selectedIndex@chrome://browser/content/tabbrowser.xml:6499:11
set_selectedPanel@chrome://global/content/bindings/tabbox.xml:687:13
set_selectedIndex@chrome://global/content/bindings/tabbox.xml:403:15
set_selectedItem@chrome://global/content/bindings/tabbox.xml:435:34
set_selectedTab@chrome://global/content/bindings/tabbox.xml:114:15
set_selectedTab@chrome://browser/content/tabbrowser.xml:2813:11
_blurTab@chrome://browser/content/tabbrowser.xml:2437:13
_endRemoveTab@chrome://browser/content/tabbrowser.xml:2304:13

Comment 10

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

Attachment: MozReview Request: Bug 1233368 - Be more careful about how we measure when an async tab switch has finished. r?billm

Now we only attempt to stop any measurements if we're sure a switch was in
progress.

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

Comment 12

[Jared Wein [:jaws] (please needinfo? me)]

https://reviewboard.mozilla.org/r/29655/#review26575

f+ from me, looks fine from a glance and thanks for fixing the console spam.

::: browser/base/content/tabbrowser.xml:3536
(Diff revision 1)
> +             * satisfies, and then records the tab switch as finished.

s/satifies/satified/

Comment 13

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

Comment on attachment 8704398 [details]
MozReview Request: Bug 1233368 - Be more careful about how we measure when an async tab switch has finished. r?billm

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

Comment 14

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

Thanks jared - do you feel confident to give an r?

Comment 15

[Jared Wein [:jaws] (please needinfo? me)]

Comment on attachment 8704398 [details]
MozReview Request: Bug 1233368 - Be more careful about how we measure when an async tab switch has finished. r?billm

https://reviewboard.mozilla.org/r/29655/#review26577

Yeah, this looks fine to me. I followed the code paths mentally but didn't pull it down and build it. Can you test how it works if you hold down Ctrl+Tab to rapidly switch tabs?

Comment 16

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

https://hg.mozilla.org/integration/fx-team/rev/e999b2a3a76618a30d2f81b09af7ed78bdc83610
Bug 1233368 - Be more careful about how we measure when an async tab switch has finished. r=jaws

Comment 17

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/e999b2a3a766

Comment 18

[Mayur Patil]

[bugday-20160323]

Status: RESOLVED,FIXED -> UNVERIFIED

Comments:
STR: Not clear.
Developer specific testing

Component: 
Name			Firefox
Version			46.0b9
Build ID		20160322075646
Update Channel	beta
User Agent		Mozilla/5.0 (Windows NT 6.1; WOW64; rv:46.0) Gecko/20100101 Firefox/46.0
OS				Windows 7 SP1 x86_64

Expected Results: 
Developer specific testing

Actual Results: 
As expected