Closed Bug 1156592 Opened 9 years ago Closed 9 years ago

Add Telemetry probe to measure async tab performance

Categories

(Firefox :: Tabbed Browser, defect)

x86
All
defect
Not set
normal

Tracking

()

RESOLVED FIXED
Firefox 40
Tracking Status
e10s m6+ ---
firefox40 --- fixed

People

(Reporter: mconley, Assigned: jimm)

References

(Blocks 1 open bug)

Details

Attachments

(2 files, 2 obsolete files)

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.
Let's make sure we measure both e10s and non-e10s comparably
Assignee: nobody → jmathies
Blocks: e10s-spinner
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.
Attached patch patch (obsolete) — Splinter Review
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.
Assuming we trust MozAfterPaint, and afaict we can based on what I'm seeing here, this is ready to go.
Depends on: 1157423
Attached patch patch v.2 (obsolete) — Splinter Review
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
No longer depends on: 1157423
TelemetryStopwatch changes plus the two new probes.
Attachment #8596178 - Attachment is obsolete: true
Attachment #8596668 - Flags: review?(felipc)
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+
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.
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
(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.
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.
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
(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.
Depends on: 1161148
See Also: → 1649955
See Also: → 1689258
You need to log in before you can comment on or make changes to this bug.