1481704 - FX_TAB_SWITCH_TOTAL_E10S_MS doesn't include time to composite the new tab.

Status: RESOLVED FIXED

(Firefox :: Tabbed Browser, enhancement, P1)

Description

[Matt Woodrow (:mattwoodrow)]

I believe this is intentional, but it would be really nice to have a measurement that records the total time until we actually make the new tab visible to the user.

This will be particularly useful as a measurement for comparing the performance of WR/Gecko, since most of the relevant rendering work with WR happens during the 'composite'.

Comment 1

[Matt Woodrow (:mattwoodrow)]

Attachment: tab-switch-composite

Does this make sense Mike?

Profile captured with it: https://perfht.ml/2vrRocb

We can see that AsyncTabSwitch::Start/Finish fire almost directly after each other (since the tab was already preloaded), but AsyncTabSwitch::Composite is significantly later.

On the main thread we see all the tab switch work, followed by a paint. Directly after that we can see the compositor thread receive the transaction (0.44ms), then a really long wait (for vsync) and then a composite. Pretty soon after that the AsyncTabSwitch::Composite event fires.

It looks like the marker is a bit late because the main thread was in the middle of doing another paint. Hard to fix for the marker, but we could fix the telemetry value by using the 'paintTimeStamp' member of the MozAfterPaint event to know when the composite actually finished.

Comment 2

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

Comment on attachment 8998412 [details] [diff] [review]
tab-switch-composite

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

Yeah, I'm pretty certain we intentionally avoided the composite time in the measurement since we didn't want to factor in compositor jank (since we were focusing more on main-thread things to improve tab switch time).

::: browser/modules/AsyncTabSwitcher.jsm
@@ +104,5 @@
>      // True if we're in the midst of switching tabs.
>      this.switchInProgress = false;
>  
> +    // Transaction id for the composite that will show our
> +    // new tab for the first time.

"show our new tab" -> "show the requested tab for the first tab after a tab switch".

Should probably also mention what -1 means.

@@ +410,5 @@
>      }
>  
>      // Switch to the tab we've decided to make visible.
>      if (this.visibleTab !== showTab) {
> +      if (showTab == this.requestedTab) {

There's a showTab == this.requestedTab conditional down below[1] - could we fold this into that?

https://searchfox.org/mozilla-central/rev/f0c15db995198a1013e1c5f5b5bea54ef83f1049/browser/modules/AsyncTabSwitcher.jsm#421

@@ +420,5 @@
> +        } else {
> +          // We're making the tab visible even though we haven't yet got layers for it.
> +          // It's hard to know which composite the layers will first be available in (and
> +          // the parent process might not even get MozAfterPaint delivered for it), so just
> +          // give up measuring this for now. :(

For sluggish tabs, we'll eventually get a MozLayerTreeReady event though, and then do the switch - at that point, I think we'll know that the next composite should present the tab contents to the user. Won't we?

So perhaps we should set this switchPaintId when we get the MozLayerTreeReady event?

::: toolkit/components/telemetry/Histograms.json
@@ +5827,5 @@
> +    "high": 1000,
> +    "n_buckets": 20,
> +    "bug_numbers": [1156592],
> +    "releaseChannelCollection": "opt-out",
> +    "description": "Firefox: Time in ms between tab selection and tab content paint in e10s windows"

This will need data review, naturally. Also, we'll probably want to distinguish between this and the old probe with a new description. I think we might want to keep the old probe around for the non-WebRender case.

Comment 3

[Matt Woodrow (:mattwoodrow)]

(In reply to Mike Conley (:mconley) (:⚙️) from comment #2)
> 
> https://searchfox.org/mozilla-central/rev/
> f0c15db995198a1013e1c5f5b5bea54ef83f1049/browser/modules/AsyncTabSwitcher.
> jsm#421
> 
> @@ +420,5 @@
> > +        } else {
> > +          // We're making the tab visible even though we haven't yet got layers for it.
> > +          // It's hard to know which composite the layers will first be available in (and
> > +          // the parent process might not even get MozAfterPaint delivered for it), so just
> > +          // give up measuring this for now. :(
> 
> For sluggish tabs, we'll eventually get a MozLayerTreeReady event though,
> and then do the switch - at that point, I think we'll know that the next
> composite should present the tab contents to the user. Won't we?

My understanding of this code was that we are making the tab visible at this point, even though the layers aren't yet available in the compositor. The first composite that would actually display the new tab would be the first composite after the tab sends the layers to the composite, so would probably happen roughly the same time as the MozLayerTreeReady event gets delivered to the parent process.

I think the only way to truly get a measurement here is to ask the child process to get a time for the MozAfterPaint response for its layers (if it needed to build any, i.e. not pre-warmed tabs), and then use that as the end time if we took this branch.

Comment 4

[Matt Woodrow (:mattwoodrow)]

Attachment: tab-switch-data.txt

Comment 5

[Matt Woodrow (:mattwoodrow)]

Attachment: Add FX_TAB_SWITCH_COMPOSITE_E10S_MS to measure total time it takes to present a tab during tab-switch.

Comment 6

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

Comment on attachment 8998706 [details] [diff] [review]
Add FX_TAB_SWITCH_COMPOSITE_E10S_MS to measure total time it takes to present a tab during tab-switch.

Looks good! Would you mind filing a follow-up bug to research ways to capture that one form of the measurement when we flip to a tab despite the layers not being ready?

Comment 7

[François Marier [:francois]]

Comment on attachment 8998705 [details]
tab-switch-data.txt

1) Is there or will there be **documentation** that describes the schema for the ultimate data set available publicly, complete and accurate?

Yes, in Histograms.json.

2) Is there a control mechanism that allows the user to turn the data collection on and off?

Yes, telemetry setting.

3) If the request is for permanent data collection, is there someone who will monitor the data over time?**

Yes, Matt Woodrow.

4) Using the **[category system of data types](https://wiki.mozilla.org/Firefox/Data_Collection)** on the Mozilla wiki, what collection type of data do the requested measurements fall under?  **

Category 1.

5) Is the data collection request for default-on or default-off?

Default ON.

6) Does the instrumentation include the addition of **any *new* identifiers** (whether anonymous or otherwise; e.g., username, random IDs, etc.  See the appendix for more details)?

No.

7) Is the data collection covered by the existing Firefox privacy notice?

Yes.

8) Does there need to be a check-in in the future to determine whether to renew the data?

No, permanent.

Comment 8

[Matt Woodrow (:mattwoodrow)]

(In reply to Mike Conley (:mconley) (:⚙️) from comment #6)
> Comment on attachment 8998706 [details] [diff] [review]
> Add FX_TAB_SWITCH_COMPOSITE_E10S_MS to measure total time it takes to
> present a tab during tab-switch.
> 
> Looks good! Would you mind filing a follow-up bug to research ways to
> capture that one form of the measurement when we flip to a tab despite the
> layers not being ready?

Sure! Filed bug 1482614.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/39473d98f6e1
Add FX_TAB_SWITCH_COMPOSITE_E10S_MS to measure total time it takes to present a tab during tab-switch. r=mconley, data-review=francois

Comment 10

[Andrei Ciure[:aciure]]

https://hg.mozilla.org/mozilla-central/rev/39473d98f6e1

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2ac7fbfce247
Add missing hunk that got lost during rebasing.

Comment 12

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/2ac7fbfce247