1138502 - 6% Talos Regression on tresize PGO on OSX w/ Silk Enabled

Status: RESOLVED FIXED

(Core :: Graphics, defect)

Description

[Mason Chang [Inactive] [:mchang]]

From https://bugzilla.mozilla.org/show_bug.cgi?id=1128690#c8

There is a 6% talos regression on the tresize talos test. This occurs with just the vsync compositor (http://compare-talos.mattn.ca/dev/?oldBranch=Try&oldRevs=742011f28b13&newBranch=Try&newRev=55d3493940ba&submit=true). Find out why and fix.

Comment 1

[Mason Chang [Inactive] [:mchang]]

With vsync compositor - https://treeherder.mozilla.org/#/jobs?repo=try&revision=83cb4a12cda7

Base - https://treeherder.mozilla.org/#/jobs?repo=try&revision=36c6ba738947

One profile w/ vsync compositor - http://people.mozilla.org/~bgirard/cleopatra/?zippedProfile=http://mozilla-releng-blobs.s3.amazonaws.com/blobs/Try/sha512/5fda6478a6adaa4c7a3cc7517834c11b04288a5abc70dd5ea82485c7d196beba107ac92b0543e15055107f33a3d553b7d2dad4d03fb651e38add8c67fcc87516&pathInZip=profile_tresize/tresize/cycle_17.sps#report=56cf2a2213b084bfc777edf078f834c07dbbf0bc

From the profiles, the tresize test does not use ASAP mode. In addition, the test uses Forced sync composition. Essentially, the vsync callback on OS X takes up small amounts of CPU every resize, which adds up over the course of the test. I'm not sure there is much we can do about this, so I think we'll have to accept the regression. Closing as WONTFIX.

Comment 2

[Joel Maher ( :jmaher ) (UTC -8)]

I am not sure I see this regression:
http://graphs.mozilla.org/graph.html#tests=[[254,63,24],[254,63,21]]&sel=1424025209626.498,1425394930978.5178&displayrange=30&datatype=geo

is this a different platform maybe?  I wanted to ensure we annotated any alerts or other bugs to help us keep track of this.

Comment 3

[Mason Chang [Inactive] [:mchang]]

(In reply to Joel Maher (:jmaher) from comment #2)
> I am not sure I see this regression:
> http://graphs.mozilla.org/graph.html#tests=[[254,63,24],[254,63,
> 21]]&sel=1424025209626.498,1425394930978.5178&displayrange=30&datatype=geo
> 
> is this a different platform maybe?  I wanted to ensure we annotated any
> alerts or other bugs to help us keep track of this.

It's not on inbound yet, this is still on Try. I wanted to test the regressions before actually landing :)

Comment 4

[Mason Chang [Inactive] [:mchang]]

Markus found a nice thing in the profile where we keep enabling/disabling vsync, which causes the regressions. We should be able to fix this.

Comment 5

[Mason Chang [Inactive] [:mchang]]

Attachment: Reset unobserve counter on ForceComposites

Reset the unobserve count in the CompositorVsyncObserver on force composites, which will force vsync to stay enabled. Will wait on try then ask for review.

Comment 6

[Mason Chang [Inactive] [:mchang]]

With this patch, we go down to a 3% regression

http://compare-talos.mattn.ca/dev/?oldBranch=Try&oldRevs=b77ed0031ed6&newBranch=Try&newRev=c2ee333a0503&submit=true

Still trying to get a SPS profile, lots of crashes when running with the profiling option on talos.

Comment 7

[Joel Maher ( :jmaher ) (UTC -8)]

Mason, thanks for looking into this!  This is great progress:)

Comment 8

[Vladan Djeric (:vladan)]

(In reply to Mason Chang [:mchang] from comment #6)
> Still trying to get a SPS profile, lots of crashes when running with the
> profiling option on talos.

This might be the crash I reported in bug 1139506. If so, it should be fixed in the next nightly

Comment 9

[Mason Chang [Inactive] [:mchang]]

(In reply to Vladan Djeric (:vladan) -- please needinfo! from comment #8)
> (In reply to Mason Chang [:mchang] from comment #6)
> > Still trying to get a SPS profile, lots of crashes when running with the
> > profiling option on talos.
> 
> This might be the crash I reported in bug 1139506. If so, it should be fixed
> in the next nightly

Yup, that fixed it, thanks! https://treeherder.mozilla.org/#/jobs?repo=try&revision=1793fc9aebef

Comment 10

[Mason Chang [Inactive] [:mchang]]

Here are two profiles of two runs:
https://people.mozilla.org/~bgirard/cleopatra/#report=46b785500be083729b169243a0021586c4b22e5f
https://people.mozilla.org/~bgirard/cleopatra/#report=d7cca21db9a1fb706411ba7264662340506f60e9

Sometimes we see that the vsync occurs right after the layer transaction but before the compositor thread gets to the sync RecvFlushRendering on the compositor thread, so we composite based on the vsync and the RecvFlushRendering is delayed due to the compositor thread being busy. This is fine, but is still a little extra overhead since the RecvFlushRendering should just return true.

We also have the other case where the RecvFlushRendering occurs first right at vsync. In these cases, we have to cancel the current composite task, which has to grab a lock and cancel the task. Finally, we also still have the overhead of the vsync callback. I can't really see these cases in the profiles, but that's where we do extra work now compared to pre-silk.

Comment 11

[Mason Chang [Inactive] [:mchang]]

Try on an older parent w/o vsync w/ SPS profile
https://treeherder.mozilla.org/#/jobs?repo=try&revision=71aab273077b

https://people.mozilla.org/~bgirard/cleopatra/#report=88168ef6c3df7624f7b10c37401d2c32dc0215c6

Comment 12

[Mason Chang [Inactive] [:mchang]]

Comment on attachment 8572168 [details] [diff] [review]
Reset unobserve counter on ForceComposites

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

From irc: We shouldn't hold up silk because of the 3% regression, which is 21.66 ms +- 0.7 to 22.33 +- 0.5 ms. Markus noticed a gap between the layer transaction and the composite which doesn't occur w/o vsync in the profiles. 

I will follow up with a local check to see what happens between a layer transaction the RecvFlushComposite, but this patch keeps vsync enabled, which was the major regression.

Comment 13

[Markus Stange [:mstange]]

Comment on attachment 8572168 [details] [diff] [review]
Reset unobserve counter on ForceComposites

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

::: gfx/layers/ipc/CompositorParent.cpp
@@ +348,5 @@
> +{
> +  /**
> +   * bug 1138502 - If we receive a ForceComposite, we no longer
> +   * need to composite on vsyncs. However, if we receive enough ForceComposites
> +   * in a row like in talos, we will keep unobserving from vsync then

This comment describes how things were before this patch, and might be confusing to readers who don't know the history of this code. Can you reformulate it so that it expresses that the bad behavior would only happen if this method didn't exist? Or express it as a behavior that we don't want, maybe?

I also suggest changing "like in talos" to ", e.g. during long-running window resizing" or something like that.

Comment 14

[Mason Chang [Inactive] [:mchang]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ecfaa4538984

Comment 15

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/ecfaa4538984

Comment 16

[Mason Chang [Inactive] [:mchang]]

Just a heads up, bug 1137905 is in mozilla-inbound, so we expect a few small decreases / improvements.

Comment 17

[Mason Chang [Inactive] [:mchang]]

So I figured out the last 0.5 ms. It's not really a regression in silk versus the previous timings were just lucky. While running the test, we schedule the next composite after we finish compositing. When the layer transaction occurs, we now need to composite but the next thing on the message loop is the scheduled composite task. This task then executes on the compositor thread BEFORE the sync RecvFlushRendering call occurs. Because of this, in the profiles, it looks like there is 0 gap between the LayerTransaction and the Composite. Even without vsync, there is ~0.5 ms latency between the LayerTransaction and the RecvFlushRendering.

With Silk, we don't schedule anything on the compositor loop, so we have to wait for the sync RecvFlushRendering to composite, which creates the gap in the profiles.

If you look at profiles on master w/o silk (https://people.mozilla.org/~bgirard/cleopatra/#report=efc3c742ef127d4573fda59d4dccb5d9a8b9d767&selection=0,1095), versus profiles with silk (https://people.mozilla.org/~bgirard/cleopatra/#report=49009d8f2a1f7450b6c3ce8a1b0482e4382e189d), the number of composites from RecvFlushComposites is much higher in Silk profiles versus non-silk profiles. 

We also sometimes get lucky with Silk where the vsync composite occurs before the RecvFlushRendering, in which case we get the same advantage. Overall though, the latency between a LayerTransaction and a RecvFlushRendering is ~0.5ms, which is the hit we're seeing here.