1244684 - FX_TAB_SWITCH_TOTAL_MS is broken

Status: RESOLVED FIXED

(Core :: General, defect)

Description

[Gabor Krizsanits (INACTIVE)]

We used to collect data about tab switch time in non-e10s mode with this, but it's not working any longer. See the telemetry dashboard and Bug 1198191 Comment 5.

Comment 1

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

Talked to gw280 over IRC, going to steal this one.

Comment 2

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

I bisected this on OS X to wayyyyyy back into 2013.

This got broken by turning on OMTC by default.

Comment 3

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

Attachment: MozReview Request: Bug 1244684 - Call PostPresent after ClientLayerManager::EndTransactionInternal to fix busted FX_TAB_SWITCH_TOTAL_MS probe. r?BenWa

Review commit: https://reviewboard.mozilla.org/r/35717/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/35717/

Comment 4

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

https://reviewboard.mozilla.org/r/35717/#review32367

I'm really not 100% certain this is the right place to put this, but it more or less mirrors where it's put inside BasicLayerManager.

Comment 5

[Markus Stange [:mstange]]

Comment on attachment 8721578 [details]
MozReview Request: Bug 1244684 - Call PostPresent after ClientLayerManager::EndTransactionInternal to fix busted FX_TAB_SWITCH_TOTAL_MS probe. r?BenWa

https://reviewboard.mozilla.org/r/35717/#review32689

This looks fine. Another option would be to put it in ClientLayerManager::EndTransaction after the call to ForwardTransaction so that you'd also capture the cost of sending the transaction to the compositor.

I should also mention that PostPresent is no longer a good name for this method, because "present" usually refers to actually pushing the pixels to the screen (e.g. through SwapBuffers) which, with OMTC, happens on the compositor thread. But before you try to fix that, I think you should decide what it is that you really want to measure here, because with OMTC and e10s we have two additional sources of asynchronicity that weren't a concern when the tab switch timing was written initially. With this patch, what you'll be measuring is the time it takes for the parent process to update its internal state to the new selected tab and paint the first frame of that change, which includes stuff like updating the forward button enabled state, but does *not* include any of the following: painting the contents of the new tab, painting the "tab" in the tab strip (because the old one will stay visuallyselected until the tab switch is complete), compositing the result of that first parent process paint.

Comment 6

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

Huh, okay, so I don't think this patch is exactly right yet. What we really want to do is capture the length of time between the start of the tab switch, and tab content being displayed. Because OMTC kind of changed the world here, we have to operate slightly differently.

I think the right move is to start the stopwatch as soon as the user has selected a tab, and then stop it at the next MozAfterPaint event on the window.

Comment 7

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

Attachment: MozReview Request: Bug 1244684 - Make FX_TAB_SWITCH_TOTAL_MS work for non-e10s in an OMTC world. r?mstange

Review commit: https://reviewboard.mozilla.org/r/36091/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/36091/

Comment 8

[Markus Stange [:mstange]]

Comment on attachment 8722551 [details]
MozReview Request: Bug 1244684 - Make FX_TAB_SWITCH_TOTAL_MS work for non-e10s in an OMTC world. r?mstange

https://reviewboard.mozilla.org/r/36091/#review32699

Looks good, but you should of course double-check that the numbers look fine.

Do you know how the telemetry stop watch deals with overlapping ranges? For example, if compositing is very slow, it could be possible that two tab switches are done before we're done compositing the first one, and then you'd have "start" "start" "end" "end".

Comment 9

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

https://reviewboard.mozilla.org/r/36091/#review32699

I think in that case, a pre-existing timer for that probe is cancelled and an error is displayed:

https://dxr.mozilla.org/mozilla-central/rev/789a12291942763bc1e3a89f97e0b82dc1c9d00b/toolkit/components/telemetry/TelemetryStopwatch.jsm#130

Comment 10

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

https://reviewboard.mozilla.org/r/36091/#review32699

Also, the numbers coming in for this probe while testing locally look sane.

Comment 11

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

https://hg.mozilla.org/integration/fx-team/rev/5edc2330c4cf536785b4019e5443f58e4b307c34
Bug 1244684 - Make FX_TAB_SWITCH_TOTAL_MS work for non-e10s in an OMTC world. r=mstange

Comment 12

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/5edc2330c4cf

Comment 13

[Chris Peterson [:cpeterson]]

Mike, should we uplift your FX_TAB_SWITCH_TOTAL_MS fix to Aurora 46?

Comment 14

[Gabor Krizsanits (INACTIVE)]

I would love this one to be uplifted (see bug 1198191 comment 14). Maybe even to beta?

Comment 15

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

Comment on attachment 8722551 [details]
MozReview Request: Bug 1244684 - Make FX_TAB_SWITCH_TOTAL_MS work for non-e10s in an OMTC world. r?mstange

Approval Request Comment
[Feature/regressing bug #]:

OMTC, back in 2013.

[User impact if declined]:

None, though it's going to make doing some e10s / non-e10s telemetry comparisons harder.

[Describe test coverage new/current, TreeHerder]:

Been in the mozilla-central for a few days with no ill effects.

[Risks and why]: 

Very low risk - this makes a telemetry probe work correctly after having been broken for about 3 years.

[String/UUID change made/needed]:

None.

Comment 16

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8722551 [details]
MozReview Request: Bug 1244684 - Make FX_TAB_SWITCH_TOTAL_MS work for non-e10s in an OMTC world. r?mstange

We ship 45 in a week, we only take important fixes and I am not sure this is important ;)

Comment 17

[Carsten Book [:Tomcat]]

landed by mike as https://hg.mozilla.org/releases/mozilla-aurora/rev/6aaf9904a81d setting flags

Comment 18

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

Ack! Sorry I didn't do that myself!

Comment 19

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

Attachment: Bugnotes

http://people.mozilla.org/~mconley2/bugnotes/bug-1244684.html

Comment 20

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

Attachment: Bugnotes

http://people.mozilla.org/~mconley2/bugnotes/bug-1244684.html