Add Telemetry probe to measure async tab performance

RESOLVED FIXED in Firefox 40

Status

()

Firefox
Tabbed Browser
RESOLVED FIXED
3 years ago
2 months ago

People

(Reporter: mconley, Assigned: jimm)

Tracking

(Blocks: 3 bugs)

unspecified
Firefox 40
x86
All
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(e10sm6+, firefox40 fixed)

Details

Attachments

(2 attachments, 2 obsolete attachments)

I'll probably want to consult with the Perf team to figure out just what kind of numbers we want to gather here, but I think we should try to get a sense of the sluggishness our user population is facing when switching tabs with e10s enabled.

It'd also be good to get a measure of how often the user is seeing a spinner.

Perf goals would then be to drive both numbers down.
tracking-e10s: ? → m6+
Let's make sure we measure both e10s and non-e10s comparably
Assignee: nobody → jmathies
(Assignee)

Updated

3 years ago
Blocks: 1131167
(Assignee)

Comment 2

3 years ago
We already have a couple of probes, one of which I think I can steal for this - 

FX_TAB_SWITCH_UPDATE_MS - Measures the time spent in tabbrowser.updateCurrentBrowser(), which updates the chrome during a tab switch.

FX_TAB_SWITCH_TOTAL_MS - Measures the time between a call to nsIDOMWindowUtils beginTabSwitch(), which currently happens at the top of tabbrowser.updateCurrentBrowser(), to the first call to Present by a layer subsystem.

The second probe doesn't include presenting the tab's layer tree updates. I think this is obsolete w/e10s, so I'm going to steal it for this work.
(Assignee)

Comment 3

3 years ago
Created attachment 8596166 [details] [diff] [review]
patch

I ended up leaving the old probes alone since we still collect data for both. 

I've added two new probes:

FX_TAB_SWITCH_TOTAL_E10S_MS - a measurement between tabbrowser's requestTab and the first MozAfterPaint after we receive MozLayerTreeReady.

FX_TAB_SWITCH_SPINNER_VISIBLE_MS - if we have to display the spiner, measures the amount of time we display it for.
(Assignee)

Comment 4

3 years ago
Assuming we trust MozAfterPaint, and afaict we can based on what I'm seeing here, this is ready to go.
Depends on: 1157423
(Assignee)

Comment 5

3 years ago
Created attachment 8596178 [details] [diff] [review]
patch v.2

Fixes a bug where if we display the spinner, we don't get an onPaint event. The tab switch metric was left unfinished.
Attachment #8596166 - Attachment is obsolete: true
(Assignee)

Updated

3 years ago
No longer depends on: 1157423
(Assignee)

Comment 6

3 years ago
Created attachment 8596668 [details] [diff] [review]
toolkit changes v.1

TelemetryStopwatch changes plus the two new probes.
Attachment #8596178 - Attachment is obsolete: true
Attachment #8596668 - Flags: review?(felipc)
(Assignee)

Comment 7

3 years ago
Created attachment 8596670 [details] [diff] [review]
browser front end changes v.1

Bill this looks like your work, would you mind reviewing these changes?

I've added two new probes described in comment 3. I've disabled FX_TAB_SWITCH_TOTAL_MS for e10s, which we discussed the other day, it basically doesn't work. I've kept FX_TAB_SWITCH_UPDATE_MS which is a front end chrome probe tied to chrome painting.
Attachment #8596670 - Flags: review?(wmccloskey)
Attachment #8596668 - Flags: review?(felipc) → review+
Comment on attachment 8596670 [details] [diff] [review]
browser front end changes v.1

Review of attachment 8596670 [details] [diff] [review]:
-----------------------------------------------------------------

This doesn't really work if the user switches tabs more than once in 300ms. But there will always be weird corner cases here, so maybe that's fine.

::: browser/base/content/tabbrowser.xml
@@ +2995,5 @@
>              STATE_LOADING: 1,
>              STATE_LOADED: 2,
>              STATE_UNLOADING: 3,
>  
> +            logging: Services.prefs.getBoolPref("browser.tabs.remote.logSwitchTiming"),

This will throw an exception if the preference is not present or not a boolean (which will be the typical case).

Do we really need this anyway? It seems like a developer-only feature.

@@ +3104,5 @@
>                  this.spinnerTab.linkedBrowser.removeAttribute("pendingpaint");
>                  this.spinnerTab = null;
>                } else if (needSpinner && this.spinnerTab !== showTab) {
>                  if (this.spinnerTab) {
> +                  this.spinnerDisplayAborted();

I don't think we should do this. Why not just record the whole length of time the spinner is visible, even if the user switches tabs?

@@ +3368,5 @@
> +              if (this.requestedTab && this.getTabState(this.requestedTab) == this.STATE_LOADED) {
> +                let time = TelemetryStopwatch.timeElapsed("FX_TAB_SWITCH_TOTAL_E10S_MS", window);
> +                if (time != -1) {
> +                  this.log("DEBUG: tab switch time = " +
> +                            TelemetryStopwatch.timeElapsed("FX_TAB_SWITCH_TOTAL_E10S_MS", window));

Can you just use |time| instead of calling timeElapsed again?

@@ +3411,5 @@
>  
>              log: function(s) {
>                if (!this.logging)
>                  return;
> +              Services.console.logStringMessage(s);

Please don't remove the dump calls. They're useful to me.
Attachment #8596670 - Flags: review?(wmccloskey) → review+
(Assignee)

Comment 9

3 years ago
Comment on attachment 8596670 [details] [diff] [review]
browser front end changes v.1

Review of attachment 8596670 [details] [diff] [review]:
-----------------------------------------------------------------

::: browser/base/content/tabbrowser.xml
@@ +2995,5 @@
>              STATE_LOADING: 1,
>              STATE_LOADED: 2,
>              STATE_UNLOADING: 3,
>  
> +            logging: Services.prefs.getBoolPref("browser.tabs.remote.logSwitchTiming"),

I thought it would be useful for debugging tab switching issues since your debug output dumps a lot of diagnostic data. The pref is undefined (hidden) so that matches up with the developer nature of this. Want me to take it out? I found the output interesting but I really don't care either way.

@@ +3104,5 @@
>                  this.spinnerTab.linkedBrowser.removeAttribute("pendingpaint");
>                  this.spinnerTab = null;
>                } else if (needSpinner && this.spinnerTab !== showTab) {
>                  if (this.spinnerTab) {
> +                  this.spinnerDisplayAborted();

Ok, I'll change this from a cancel to a finish and keep the data.

@@ +3368,5 @@
> +              if (this.requestedTab && this.getTabState(this.requestedTab) == this.STATE_LOADED) {
> +                let time = TelemetryStopwatch.timeElapsed("FX_TAB_SWITCH_TOTAL_E10S_MS", window);
> +                if (time != -1) {
> +                  this.log("DEBUG: tab switch time = " +
> +                            TelemetryStopwatch.timeElapsed("FX_TAB_SWITCH_TOTAL_E10S_MS", window));

Yeah :) Nice catch.

@@ +3411,5 @@
>  
>              log: function(s) {
>                if (!this.logging)
>                  return;
> +              Services.console.logStringMessage(s);

I haven't turned this off, I'm just directing it to the console instead. You can view all this debug output in the console by setting that debug pref, assuming we keep it.
Attachment #8596670 - Flags: feedback?(wmccloskey)
> I thought it would be useful for debugging tab switching issues since your debug output dumps
> a lot of diagnostic data. The pref is undefined (hidden) so that matches up with the
> developer nature of this. Want me to take it out? I found the output interesting but I really
> don't care either way.

I'm fine keeping it, but then you'll have to wrap it in a try catch block somehow.

> Ok, I'll change this from a cancel to a finish and keep the data.

No, I think it's better to do nothing here. We shouldn't finish the timer until we actually hide the spinner. And, at this point, the spinner is still showing.

> I haven't turned this off, I'm just directing it to the console instead. You can view all
> this debug output in the console by setting that debug pref, assuming we keep it.

What I meant is that the logStringMessage isn't useful to me since I never look at the JavaScript console in Firefox (it's really slow in debug builds and hard to redirect to a file). I only look at stdout in the terminal. So please keep the dump() calls so that the output continues to go to stdout. It's fine to add logStringMessage calls if it helps you though.
Duplicate of this bug: 1075177
(Assignee)

Updated

3 years ago
Attachment #8596670 - Flags: feedback?(wmccloskey)
(In reply to Bill McCloskey (:billm) from comment #8)
> Comment on attachment 8596670 [details] [diff] [review]
> browser front end changes v.1
> 
> Review of attachment 8596670 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> This doesn't really work if the user switches tabs more than once in 300ms.
> But there will always be weird corner cases here, so maybe that's fine.

could be a problem for someone holding down Ctrl+Tab. I think it it doesn't measure it (instead of measuring it incorrectly and accumulating the wrong value), that should be fine
(Assignee)

Comment 13

3 years ago
(In reply to :Felipe Gomes from comment #12)
> (In reply to Bill McCloskey (:billm) from comment #8)
> > Comment on attachment 8596670 [details] [diff] [review]
> > browser front end changes v.1
> > 
> > Review of attachment 8596670 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > This doesn't really work if the user switches tabs more than once in 300ms.
> > But there will always be weird corner cases here, so maybe that's fine.
> 
> could be a problem for someone holding down Ctrl+Tab. I think it it doesn't
> measure it (instead of measuring it incorrectly and accumulating the wrong
> value), that should be fine

Do we want perf numbers from situations like this polluting normal tab selection stats?I don't think we do.
(In reply to Jim Mathies [:jimm] from comment #13)
> > could be a problem for someone holding down Ctrl+Tab. I think if it doesn't
> > measure it (instead of measuring it incorrectly and accumulating the wrong
> > value), that should be fine
> 
> Do we want perf numbers from situations like this polluting normal tab
> selection stats?I don't think we do.

No probably not. What I meant is just that we need to make sure that this situation is not incorrectly counted in the stats. Bill mentioned "This doesn't really work if the user switches tabs more than once in 300ms" but I'm not sure exactly how it doesn't work, so I thought I should mention.
(Assignee)

Comment 15

3 years ago
I was testing with ctrl-tab and could not get tabs to switch this fast, since ctrl-tab throws up a dialog which allows you to select the tab you want. The tab switch doesn't apply until your release the keyboard keys.
(Assignee)

Comment 16

3 years ago
Also while testing I am seeing tab switch times much less that 300msec being recorded. So I think generally we are getting what we want here.

sanity try push:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=35e2eab1f501
(In reply to Jim Mathies [:jimm] from comment #15)
> I was testing with ctrl-tab and could not get tabs to switch this fast,
> since ctrl-tab throws up a dialog which allows you to select the tab you
> want. The tab switch doesn't apply until your release the keyboard keys.

you probably have browser.ctrlTab.previews set to true, which is not the default
(Assignee)

Comment 18

3 years ago
(In reply to :Felipe Gomes from comment #17)
> (In reply to Jim Mathies [:jimm] from comment #15)
> > I was testing with ctrl-tab and could not get tabs to switch this fast,
> > since ctrl-tab throws up a dialog which allows you to select the tab you
> > want. The tab switch doesn't apply until your release the keyboard keys.
> 
> you probably have browser.ctrlTab.previews set to true, which is not the
> default

Ok with that disabled it still seems to work. Flipping through about five tabs I'm getting about 12 msec switch times repeatedly.
https://hg.mozilla.org/mozilla-central/rev/7ca295075203
https://hg.mozilla.org/mozilla-central/rev/37bab93f427e
https://hg.mozilla.org/mozilla-central/rev/3265c932f222
Status: NEW → RESOLVED
Last Resolved: 3 years ago
status-firefox40: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 40
(Assignee)

Updated

3 years ago
Depends on: 1161148
You need to log in before you can comment on or make changes to this bug.