1233576 - Vsync timestamps are not monotonic (Windows 10)

Status: RESOLVED FIXED

(Core :: Graphics, defect)

Description

[Kartikaya Gupta (email:[e-mail])]

While investigating bug 1222190 I found a problem with the vsync timestamps on windows. To repro, build m-c with the following patch, which logs the time delta between consecutive vsync timestamps.

diff --git a/gfx/thebes/gfxWindowsPlatform.cpp b/gfx/thebes/gfxWindowsPlatform.cpp
index 64c1a31..8b66569 100755
--- a/gfx/thebes/gfxWindowsPlatform.cpp
+++ b/gfx/thebes/gfxWindowsPlatform.cpp
@@ -2887,6 +2887,10 @@ public:
           // Large parts of gecko assume that the refresh driver timestamp
           // must be <= Now() and cannot be in the future.
           MOZ_ASSERT(vsync <= TimeStamp::Now());
+static TimeStamp lastsync = vsync;
+printf_stderr("vsync delta %f %f\n", (vsync - lastsync).ToMilliseconds(),
+(TimeStamp::Now() - vsync).ToMilliseconds());
+lastsync = vsync;
           Display::NotifyVsync(vsync);

           // DwmComposition can be dynamically enabled/disabled

The output that I got is like this:

vsync delta 29211.678826 0.002415
vsync delta -29178.324157 29197.131846
vsync delta 29211.362205 0.333782
vsync delta 16.700367 1.760108
vsync delta 16.791071 0.909661
vsync delta 16.727641 0.272365
vsync delta 16.710950 0.646087
vsync delta 16.732464 0.599236
vsync delta 16.701010 1.199634
vsync delta 16.676389 1.316924
vsync delta 16.797283 0.504336
vsync delta 16.697694 0.482595
vsync delta 16.713161 0.523871
vsync delta 16.746834 0.788056
vsync delta 16.736019 0.711691
vsync delta 16.640654 0.683601
vsync delta 180.083829 0.001811
vsync delta -146.581049 150.912740
vsync delta 167.151306 0.974095
vsync delta 16.773642 0.531682

Those negative deltas shouldn't be there.

Comment 1

[Mason Chang [Inactive] [:mchang]]

Attachment: Ensure vsync timestamps on windows 10 are monotonic

The problem with the log occurred only when we enabled vsync. On Windows 10, since DWMGetCompositionTimingInfo returns the upcoming vsync timestamp in the future, we always used the previous vsync timestamp to actually tick the refresh driver / compositor. When we enable vsync, we'd tick with TimeStamp::Now(), then the previous vsync timestamp that happened before we disabled vsync for the second tick, then the third tick would use the proper vsync timestamp. 

This patch sets the previous timestamp to Now() + 16 ms when we enable vsync. Thus the first iteration of the loop will use Now(), the second Now() + 16, the third will use the actual vsync timestamp.

Comment 2

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 8699767 [details] [diff] [review]
Ensure vsync timestamps on windows 10 are monotonic

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

SGTM

Comment 3

[Kartikaya Gupta (email:[e-mail])]

/cc vlad as fyi

Comment 4

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/4cad80316bc9

Comment 5

[Mason Chang [Inactive] [:mchang]]

Comment on attachment 8699767 [details] [diff] [review]
Ensure vsync timestamps on windows 10 are monotonic

Approval Request Comment
[Feature/regressing bug #]: Project Silk
[User impact if declined]: Windows 10 users may get jankier animations / scrolling when coming from an idle state.
[Describe test coverage new/current, TreeHerder]: Manual / treeherder
[Risks and why]: Low - This fixes a bug on Windows 10 where we would ignore a vsync timestamp, causing jank when coming from an idle state.
[String/UUID change made/needed]: None

Comment 6

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/4cad80316bc9

Comment 7

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8699767 [details] [diff] [review]
Ensure vsync timestamps on windows 10 are monotonic

Improve the behavior of our product on Windows 10, taking it.

Comment 8

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

https://hg.mozilla.org/releases/mozilla-aurora/rev/8e41d75f63fa