Kartikaya Gupta (email:kats@mozilla.staktrace.com) Reporter
	Description • 9 years ago

While trying to land bug 1226826 I got assertion failures (in code that I added) which I can reproduce locally. What's happening is that the timestamp passed to AsyncCompositionManager::TransformShadowTree can go backwards at times, which is unexpected and probably bad. The way it can happen (on Android anyway) is if ForceComposeToTarget gets called in the middle of a sequence of regular composites. ForceComposeToTarget sets mLastCompose to TimeStamp::Now(), which can be significantly (e.g. 100ms) ahead of the previous value of mLastCompose. Then, on the next vsync, mLastCompose gets reset backwards. For example, I added logging to see how much mLastCompose was moving forward by every time it was touched, and I got this:

01-14 14:56:55.215 I/Gecko   ( 2776): staktrace: Composite advancing by 183.333326
01-14 14:56:55.295 I/Gecko   ( 2776): staktrace: Composite advancing by 83.333330
01-14 14:56:55.395 I/Gecko   ( 2776): staktrace: Composite advancing by 83.190303
01-14 14:56:55.425 I/Gecko   ( 2776): staktrace: ForceCompose advancing by 124.548012
01-14 14:56:55.875 I/Gecko   ( 2776): staktrace: Composite advancing by -24.521002
01-14 14:56:55.955 I/Gecko   ( 2776): staktrace: Composite advancing by 483.180048
...
01-14 14:56:56.755 I/Gecko   ( 2776): staktrace: Composite advancing by 49.632502
01-14 14:56:56.805 I/Gecko   ( 2776): staktrace: Composite advancing by 50.367494
01-14 14:56:56.855 I/Gecko   ( 2776): staktrace: Composite advancing by 33.333332
01-14 14:56:56.905 I/Gecko   ( 2776): staktrace: Composite advancing by 66.666664
01-14 14:56:56.955 I/Gecko   ( 2776): staktrace: ForceCompose advancing by 85.747534
01-14 14:56:57.755 I/Gecko   ( 2776): staktrace: Composite advancing by -35.747536


These negative jumps are what triggered my assertion failure. I think in general we shouldn't have mLastCompose going backwards in time. Not sure what the right fix is though - any thoughts Mason?

	Kartikaya Gupta (email:kats@mozilla.staktrace.com) Reporter
	Comment 1 • 9 years ago

https://treeherder.mozilla.org/#/jobs?repo=try&revision=c645be0693f0

	Mason Chang [Inactive] [:mchang] Assignee
	Comment 2 • 9 years ago

(In reply to Kartikaya Gupta (email:kats@mozilla.com) from comment #0)
> While trying to land bug 1226826 I got assertion failures (in code that I
> added) which I can reproduce locally. What's happening is that the timestamp
> passed to AsyncCompositionManager::TransformShadowTree can go backwards at
> times, which is unexpected and probably bad. The way it can happen (on
> Android anyway) is if ForceComposeToTarget gets called in the middle of a
> sequence of regular composites. ForceComposeToTarget sets mLastCompose to
> TimeStamp::Now(), which can be significantly (e.g. 100ms) ahead of the
> previous value of mLastCompose. Then, on the next vsync, mLastCompose gets
> reset backwards. For example, I added logging to see how much mLastCompose
> was moving forward by every time it was touched, and I got this:
> 
> 01-14 14:56:55.215 I/Gecko   ( 2776): staktrace: Composite advancing by
> 183.333326
> 01-14 14:56:55.295 I/Gecko   ( 2776): staktrace: Composite advancing by
> 83.333330
> 01-14 14:56:55.395 I/Gecko   ( 2776): staktrace: Composite advancing by
> 83.190303
> 01-14 14:56:55.425 I/Gecko   ( 2776): staktrace: ForceCompose advancing by
> 124.548012
> 01-14 14:56:55.875 I/Gecko   ( 2776): staktrace: Composite advancing by
> -24.521002
> 01-14 14:56:55.955 I/Gecko   ( 2776): staktrace: Composite advancing by
> 483.180048
> ...
> 01-14 14:56:56.755 I/Gecko   ( 2776): staktrace: Composite advancing by
> 49.632502
> 01-14 14:56:56.805 I/Gecko   ( 2776): staktrace: Composite advancing by
> 50.367494
> 01-14 14:56:56.855 I/Gecko   ( 2776): staktrace: Composite advancing by
> 33.333332
> 01-14 14:56:56.905 I/Gecko   ( 2776): staktrace: Composite advancing by
> 66.666664
> 01-14 14:56:56.955 I/Gecko   ( 2776): staktrace: ForceCompose advancing by
> 85.747534
> 01-14 14:56:57.755 I/Gecko   ( 2776): staktrace: Composite advancing by
> -35.747536
> 
> 
> These negative jumps are what triggered my assertion failure. I think in
> general we shouldn't have mLastCompose going backwards in time. Not sure
> what the right fix is though - any thoughts Mason?

The values by which composites are advancing are quite high. I wonder why those intervals are so high rather than being closer to 16.6ms. Is the Software Vsync source that behind [3]? Or is the main thread really busy?

I'm leaning towards skipping the whole composite step at [1], and on force composites, also dispatch touch / vr events like we do at [2]. We could just force ComposeToTarget to call CompositorVsyncScheduler::Composite(TimeStamp::Now()). Then if a vsync comes in that's a previous timestamp, we'll alter the timestamp to now(), like your patch does in comment 1. We already do this on Windows 10 because we sometimes get negative timestamps as well.

[1] https://dxr.mozilla.org/mozilla-central/source/gfx/layers/ipc/CompositorParent.cpp?case=true&from=CompositorParent.cpp#435
[2] https://dxr.mozilla.org/mozilla-central/source/gfx/layers/ipc/CompositorParent.cpp?case=true&from=CompositorParent.cpp#435
[3] https://dxr.mozilla.org/mozilla-central/source/gfx/thebes/SoftwareVsyncSource.cpp?case=true&from=SoftwareVsyncSource.cpp#108

	Kartikaya Gupta (email:kats@mozilla.staktrace.com) Reporter
	Comment 3 • 9 years ago

(In reply to Mason Chang [:mchang] from comment #2)
> The values by which composites are advancing are quite high. I wonder why
> those intervals are so high rather than being closer to 16.6ms. Is the
> Software Vsync source that behind [3]? Or is the main thread really busy?

This is on Fennec, so yes - I believe that's software vsync.

> I'm leaning towards skipping the whole composite step at [1], and on force
> composites, also dispatch touch / vr events like we do at [2]. We could just
> force ComposeToTarget to call
> CompositorVsyncScheduler::Composite(TimeStamp::Now()). Then if a vsync comes
> in that's a previous timestamp, we'll alter the timestamp to now(), like
> your patch does in comment 1. We already do this on Windows 10 because we
> sometimes get negative timestamps as well.

Sounds reasonable. I don't know how much that will affect vlad's refactoring of vsync though - he should probably weigh in. Also fyi I found a different solution to my problem so this isn't blocking me any more.

	Mason Chang [Inactive] [:mchang] Assignee
	Comment 4 • 9 years ago

This works locally, but I don't have an android setup. Can you also see if this fixes your problem on android kats? Thanks!

	Kartikaya Gupta (email:kats@mozilla.staktrace.com) Reporter
	Comment 5 • 9 years ago

Comment on attachment 8708471 [details] [diff] [review]
Normalize composite timestamps to now if timestamp is in the past.

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

::: gfx/layers/ipc/CompositorParent.cpp
@@ +480,3 @@
>    OnForceComposeToTarget();
> +  SetNeedsComposite();
> +  Composite(TimeStamp::Now());

aren't we losing the drawtarget and rect here?

	Kartikaya Gupta (email:kats@mozilla.staktrace.com) Reporter
	Comment 7 • 9 years ago

Comment on attachment 8708559 [details] [diff] [review]
Normalize composite timestamps to now if timestamp is in the past.

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

Yup, this fixes the issue I was seeing locally.

	Pulsebot
	Comment 8 • 9 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/415f713d58b0

	Carsten Book [:Tomcat]
	Comment 9 • 9 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/415f713d58b0

	Kartikaya Gupta (email:kats@mozilla.staktrace.com) Reporter
	Comment 10 • 9 years ago

This patch may also have perma-busted Android 4.3 debug R34. See https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&tochange=10d4e8736dbb&fromchange=52b41d0b5edb&filter-searchStr=Reftest%20R%28R34%29 - I triggered a couple of jobs to whittle down the regression range but this bug is the most likely candidate.

	Carsten Book [:Tomcat]
	Comment 11 • 9 years ago

(In reply to Kartikaya Gupta (email:kats@mozilla.com) from comment #10)
> This patch may also have perma-busted Android 4.3 debug R34. See
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-
> inbound&tochange=10d4e8736dbb&fromchange=52b41d0b5edb&filter-
> searchStr=Reftest%20R%28R34%29 - I triggered a couple of jobs to whittle
> down the regression range but this bug is the most likely candidate.

backed out also now from central since the pushes showed that the test failure started with this changes from this bug

	Pulsebot
	Comment 12 • 9 years ago

Backout:
https://hg.mozilla.org/mozilla-central/rev/66e07ef46853

	Joel Maher ( :jmaher ) (UTC -8)
	Comment 13 • 8 years ago

as a note, this has a 4% winxp webgl terrain e10s regression:
http://alertmanager.allizom.org:8080/alerts.html?rev=415f713d58b0803cf143f0a605ed79409d57fc1d&showAll=1&testIndex=0&platIndex=0#

that was fixed when this was backed out.

	Mason Chang [Inactive] [:mchang] Assignee
	Comment 14 • 8 years ago

Can you please try these builds to see if they reproduce the issues you filed in bug 1241363 and bug 1241387?

Thanks!

https://archive.mozilla.org/pub/firefox/try-builds/mchang@mozilla.com-e1072d701dba593b8efa1198671bb951fa62cb91/

	Alice0775 White
	Comment 15 • 8 years ago

(In reply to Mason Chang [:mchang] from comment #14)
> Can you please try these builds to see if they reproduce the issues you
> filed in bug 1241363 and bug 1241387?
> 
> Thanks!
> 
> https://archive.mozilla.org/pub/firefox/try-builds/mchang@mozilla.com-
> e1072d701dba593b8efa1198671bb951fa62cb91/

I tested the bug 1241387, and the try build worked fine for me.
https://hg.mozilla.org/try/rev/e1072d701dba593b8efa1198671bb951fa62cb91
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:46.0) Gecko/20100101 Firefox/46.0 ID:20160130165630

	Mason Chang [Inactive] [:mchang] Assignee
	Comment 16 • 8 years ago

The first time we create a widget and composite it, we don't have a default render target in Compositor D3D11. This causes us to hit this path at [1]. Since we don't have a default render target, we don't resize the buffer of the swap chain to the invalid region we need to composite. We then create a default render target that is the size of the back buffer at [2], which in the first composite, will not be equal to mSize [3]. Thus the bug 1241363 and bug 1241387 were composites of texture that was in the back buffer scaled up to the invalid size instead of the appropriate invalid region. This patch resizes the back buffer to the invalid region if we don't have a default render target yet. Then the newly created render target will be the appropriate size.

[1] https://dxr.mozilla.org/mozilla-central/source/gfx/layers/d3d11/CompositorD3D11.cpp?case=true&from=CompositorD3D11.cpp#1235
[2] https://dxr.mozilla.org/mozilla-central/source/gfx/layers/d3d11/CompositorD3D11.cpp?case=true&from=CompositorD3D11.cpp#1324
[3] https://dxr.mozilla.org/mozilla-central/source/gfx/layers/d3d11/CompositorD3D11.cpp?case=true&from=CompositorD3D11.cpp#1325

	Bas Schouten (:bas.schouten)
	Comment 17 • 8 years ago

This is actually just a consequence of me being silly in https://hg.mozilla.org/mozilla-central/diff/6899517c16a2/gfx/layers/d3d11/CompositorD3D11.cpp#l1263. Can we just lift the ResizeBuffers call back out of the if (mDefaultRT) statement? Also, mSize ought to be the client rect and not the invalid region that you're sizing to?

	Mason Chang [Inactive] [:mchang] Assignee
	Comment 18 • 8 years ago

Updated with feedback from comment 17.

	Mason Chang [Inactive] [:mchang] Assignee
	Comment 19 • 8 years ago

I've been thinking about this more, and I actually think it's better just to skip a past vsync notification due to force composites. If we dispatched touch/vr events at force compose timestamps, it'd dispatch non-uniform events. Instead, it's probably better to just halve the frame rate but at least be uniform in this case.

	Pulsebot
	Comment 20 • 8 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/9d1a4ca0fe8d
https://hg.mozilla.org/integration/mozilla-inbound/rev/59ae52ad5880

	Phil Ringnalda (:philor)
	Comment 21 • 8 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/9d1a4ca0fe8d
https://hg.mozilla.org/mozilla-central/rev/59ae52ad5880

	Mason Chang [Inactive] [:mchang] Assignee
	Comment 23 • 8 years ago

Comment on attachment 8715544 [details] [diff] [review]
Properly resize DXGI swap chain buffer size

Approval Request Comment
[Feature/regressing bug #]: Bug 1229533, accidental failure to resize swap chain buffers sometimes. This patch reverts a small change from bug 122953 to what it was in Gecko 44 and before.
[User impact if declined]: Some random rendering artifacts, see bug 1241364.
[Describe test coverage new/current, TreeHerder]: Manual, treeherder
[Risks and why]: Low, this properly resizes our buffers to the client region.
[String/UUID change made/needed]: None

Requesting uplift to beta since that's when bug 1229533 landed.

	Sylvestre Ledru [:Sylvestre]
	Comment 24 • 8 years ago

Comment on attachment 8715544 [details] [diff] [review]
Properly resize DXGI swap chain buffer size

Fix artifact, taking it.
Should be in 45 beta 5.

	Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)
	Comment 25 • 8 years ago
bugherder uplift

https://hg.mozilla.org/releases/mozilla-aurora/rev/015aca9bee9b
https://hg.mozilla.org/releases/mozilla-aurora/rev/d9e3fdf3afe2

	Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)
	Comment 26 • 8 years ago
bugherder uplift

https://hg.mozilla.org/releases/mozilla-beta/rev/60fb51fe943e
https://hg.mozilla.org/releases/mozilla-beta/rev/9d2e23450a2b