Closed Bug 1233368 Opened 7 years ago Closed 7 years ago

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

Categories

(Firefox :: Tabbed Browser, defect, P1)

defect

Tracking

()

RESOLVED FIXED
Firefox 46
Tracking Status
e10s + ---
firefox46 --- fixed

People

(Reporter: yarik.sheptykin, Assigned: mconley)

References

(Blocks 1 open bug)

Details

Attachments

(2 files, 1 obsolete file)

Attached file tabbrowser-telemetry-stopwatch.log (obsolete) —
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
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?
Flags: needinfo?(jmathies)
Flags: needinfo?(georgehdd)
Waiting on whether Jim knows how to proceed here.
Flags: needinfo?(georgehdd)
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.
tracking-e10s: --- → ?
Flags: needinfo?(jmathies)
Flags: needinfo?(mconley)
Attachment #8699417 - Attachment mime type: text/x-log → text/plain
Flags: needinfo?(mconley)
Flags: needinfo?(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?
Flags: needinfo?(mconley) → needinfo?(yarik.sheptykin)
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?
Attachment #8699417 - Attachment is obsolete: true
Flags: needinfo?(yarik.sheptykin) → needinfo?(mconley)
Yes, I'm seeing this now. Thank you!
Flags: needinfo?(mconley)
Actually, putting back the needinfo so I can try to answer _why_ this is occurring.
Flags: needinfo?(mconley)
Duplicate of this bug: 1236959
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
Flags: needinfo?(mconley)
Assignee: nobody → mconley
Blocks: e10s-perf
Priority: -- → P1
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/
Attachment #8704398 - Flags: review?(wmccloskey)
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/
Attachment #8704398 - Flags: review?(wmccloskey) → review?(jaws)
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/
Thanks jared - do you feel confident to give an r?
Summary: tabbroswer.xml calls TelemetryStopwatch.finish() for FX_TAB_SWITCH_TOTAL_E10S_MS twice → tabbrowser.xml calls TelemetryStopwatch.finish() for FX_TAB_SWITCH_TOTAL_E10S_MS twice
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?
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
https://hg.mozilla.org/mozilla-central/rev/e999b2a3a766
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 46
[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
You need to log in before you can comment on or make changes to this bug.