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

RESOLVED FIXED in Firefox 46

Status

()

Firefox
Tabbed Browser
P1
minor
RESOLVED FIXED
3 years ago
2 years ago

People

(Reporter: Iaroslav Sheptykin, Assigned: mconley)

Tracking

(Blocks: 2 bugs)

Trunk
Firefox 46
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(e10s+, firefox46 fixed)

Details

MozReview Requests

()

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

Attachments

(2 attachments, 1 obsolete attachment)

(Reporter)

Description

3 years ago
Created attachment 8699417 [details]
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
(Reporter)

Comment 1

3 years ago
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)
Blocks: 1105864

Comment 3

3 years ago
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)
(Reporter)

Comment 5

3 years ago
Created attachment 8701218 [details]
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?
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)

Updated

3 years ago
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: 1063169
tracking-e10s: ? → +
Priority: -- → P1
Created attachment 8704398 [details]
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/
Attachment #8704398 - Flags: review?(wmccloskey)
Duplicate of this bug: 1235554
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
Attachment #8704398 - Flags: review?(jaws) → review+
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 17

3 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/e999b2a3a766
Status: NEW → RESOLVED
Last Resolved: 3 years ago
status-firefox46: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 46

Comment 18

2 years ago
[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.