Closed Bug 1366603 Opened 7 years ago Closed 7 years ago

Intermittent dom/animation/test/mozilla/test_deferred_start.html | Starting an animation with a delay starts from the correct point - Starting an animation with a delay starts from the correct point: assert_equals: Got a valid transform matrix on the comp

Categories

(Core :: DOM: Animation, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla57
Tracking Status
firefox56 --- fixed
firefox57 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: mantaroh)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed])

Attachments

(1 file)

this failure started around August 5th- appears mostly on debug.

here is a recent windows 7 debug log:
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=124704962&lineNumber=11634

and the related screenshot:
https://public-artifacts.taskcluster.net/DdQzUf78RMC22fyuBjybdQ/0/public/test_info/mozilla-test-fail-screenshot_glhzab.png


here is data from the log to show the failure:
23:07:05     INFO -  536 INFO TEST-OK | dom/animation/test/mozilla/test_cubic_bezier_limits.html | took 413ms
23:07:05     INFO -  GECKO(5636) | ++DOMWINDOW == 57 (18D46000) [pid = 1860] [serial = 206] [outer = 17A08400]
23:07:05     INFO -  537 INFO None538 INFO TEST-START | dom/animation/test/mozilla/test_deferred_start.html
23:07:05     INFO -  GECKO(5636) | ++DOMWINDOW == 58 (015E9000) [pid = 1860] [serial = 207] [outer = 17A08400]
23:07:05     INFO -  GECKO(5636) | ++DOCSHELL 17AE6000 == 11 [pid = 1860] [id = {aaae6985-0749-47ca-b425-b1a8e8fe36f8}]
23:07:05     INFO -  GECKO(5636) | ++DOMWINDOW == 59 (17AE6400) [pid = 1860] [serial = 208] [outer = 00000000]
23:07:05     INFO -  GECKO(5636) | [Parent 5636] WARNING: [nsFrameLoader] ReallyStartLoadingInternal tried but couldn't show remote browser.
23:07:05     INFO -  GECKO(5636) | : file z:/build/build/src/dom/base/nsFrameLoader.cpp, line 794
23:07:05     INFO -  GECKO(5636) | ++DOMWINDOW == 60 (17B11000) [pid = 1860] [serial = 209] [outer = 17AE6400]
23:07:05     INFO -  GECKO(5636) | ++DOMWINDOW == 61 (17F8C000) [pid = 1860] [serial = 210] [outer = 17AE6400]
23:07:06     INFO -  TEST-INFO | started process screenshot
23:07:06     INFO -  TEST-INFO | screenshot: exit 0
23:07:06     INFO -  Buffered messages logged at 23:07:06
23:07:06     INFO -  539 INFO TEST-PASS | dom/animation/test/mozilla/test_deferred_start.html |  - : Elided 1 passes or known failures.
23:07:06     INFO -  Buffered messages finished
23:07:06    ERROR -  540 INFO TEST-UNEXPECTED-FAIL | dom/animation/test/mozilla/test_deferred_start.html | Starting an animation with a delay starts from the correct point - Starting an animation with a delay starts from the correct point: assert_equals: Got a valid transform matrix on the compositor (got: "") expected 6 but got 0
23:07:06     INFO -  541 INFO TEST-PASS | dom/animation/test/mozilla/test_deferred_start.html |  - : Elided 2 passes or known failures.
23:07:06     INFO -  GECKO(5636) | MEMORY STAT | vsize 548MB | vsizeMaxContiguous 906MB | residentFast 123MB | heapAllocated 25MB
23:07:06     INFO -  542 INFO TEST-OK | dom/animation/test/mozilla/test_deferred_start.html | took 844ms


:birtles, I see you are the triage owner for the dom:animation component- can you help find someone to look into this frequent intermittent sometime in the next 2 weeks?
Flags: needinfo?(bbirtles)
Whiteboard: [stockwell needswork]
Mantaroh will look at this. If he hasn't made progress in a day or two I will take over.
Assignee: nobody → mantaroh
Status: NEW → ASSIGNED
Flags: needinfo?(bbirtles)
(In reply to Brian Birtles (:birtles) from comment #13)
> Mantaroh will look at this. If he hasn't made progress in a day or two I
> will take over.

I think that the Gecko couldn't find AnimationValue from Compositor's animated values. i.e. compositor didn't store target animation yet.
I added logging code around where storing/getting animation values. Log is here: https://pastebin.mozilla.org/9030336 

Furthermore, if we wait one tick using by rAF, we can't reproduce this bug.
I added IPC message log: https://pastebin.mozilla.org/9030342
It looks like this test will try calling getOMTAStyle() before vsync(i.e. tick).

I tried logging into paint_listener.js. DOMWindowUtils.isMozAfterPaintPending[1] is false, so wait waitForPaints() execute the callback immediately.
[1] http://searchfox.org/mozilla-central/rev/48ea452803907f2575d81021e8678634e8067fc2/testing/mochitest/tests/SimpleTest/paint_listener.js#60
(In reply to Mantaroh Yoshinaga[:mantaroh] from comment #15)
> I added IPC message log: https://pastebin.mozilla.org/9030342
> It looks like this test will try calling getOMTAStyle() before vsync(i.e.
> tick).
> 
> I tried logging into paint_listener.js.
> DOMWindowUtils.isMozAfterPaintPending[1] is false, so wait waitForPaints()
> execute the callback immediately.
> [1]
> http://searchfox.org/mozilla-central/rev/
> 48ea452803907f2575d81021e8678634e8067fc2/testing/mochitest/tests/SimpleTest/
> paint_listener.js#60

I'm really not sure that Element.animate() of transform will occur paint process immediately. 
I think that this test expected that 'waitForPaint()' wait to end of painting the transform animation, but it will not.

If layout.frame_rate is 10(i.e. 10fps), we can reproduce this phenomenon always.
(In reply to Mantaroh Yoshinaga[:mantaroh] from comment #16)
> (In reply to Mantaroh Yoshinaga[:mantaroh] from comment #15)
> > I added IPC message log: https://pastebin.mozilla.org/9030342
> > It looks like this test will try calling getOMTAStyle() before vsync(i.e.
> > tick).
> > 
> > I tried logging into paint_listener.js.
> > DOMWindowUtils.isMozAfterPaintPending[1] is false, so wait waitForPaints()
> > execute the callback immediately.
> > [1]
> > http://searchfox.org/mozilla-central/rev/
> > 48ea452803907f2575d81021e8678634e8067fc2/testing/mochitest/tests/SimpleTest/
> > paint_listener.js#60
> 
> I'm really not sure that Element.animate() of transform will occur paint
> process immediately. 
> I think that this test expected that 'waitForPaint()' wait to end of
> painting the transform animation, but it will not.
> 
> If layout.frame_rate is 10(i.e. 10fps), we can reproduce this phenomenon
> always.

I think that this test had better to wait Animation.ready and MozAfterPaint.

Try: (Note: ontain the test code which dropping the FPS.)
 https://treeherder.mozilla.org/#/jobs?repo=try&revision=e923b2862be00e256e79ae6d3be3cb248d84a016
Depends on: 1168759
I think the reason why the MozAfterPaint event fails to catch the painting the animation on the compositor is bug 1341294.
Failing this test means that we received a redundant (or delayed) MozAfterPaint event there. I am wondering why it happens frequently in these days.  There must be a trigger commit.  It's worth investigating.
(In reply to Hiroyuki Ikezoe (:hiro) from comment #18)
> I think the reason why the MozAfterPaint event fails to catch the painting
> the animation on the compositor is bug 1341294.
> Failing this test means that we received a redundant (or delayed)
> MozAfterPaint event there. I am wondering why it happens frequently in these
> days.  There must be a trigger commit.  It's worth investigating.

Thank you for your information.

Umm, As far as I can see, I think that this test failure related with changing to Web Animations(Element.animate) from CSS Animations. [1] After this changing, this test will fail on treeherder[2] and my environment. But I think that probability depends on rate of tick. i.e. FPS.
In my environment, If use previous tests file(before [1]), I can't reproduce this phenomenon with any FPS value.

[1] https://hg.mozilla.org/mozilla-central/annotate/4317e4c26505/dom/animation/test/mozilla/file_deferred_start.html#l101
[2] https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1366603&endday=2017-08-24&startday=2017-05-01&tree=trunk

Previous test:
 1. Add transform animation keyframe to CSS (div.style.animation = 'animTransform 100s -50s forwards';)
 2. Getting Animation object. (var animation = div.getAnimations()[0];)
 3. Waiting the MozAfterPaint (waitForPaints())

Current test:
 1. Create Animation object. (var animation = div.animate({ transform: [..., ...] }, { duration:..., delay: ...}); )
 2. Waiting the MozAfterPaint (waitForPaints())
(In reply to Mantaroh Yoshinaga[:mantaroh] from comment #19)
> (In reply to Hiroyuki Ikezoe (:hiro) from comment #18)
> > I think the reason why the MozAfterPaint event fails to catch the painting
> > the animation on the compositor is bug 1341294.
> > Failing this test means that we received a redundant (or delayed)
> > MozAfterPaint event there. I am wondering why it happens frequently in these
> > days.  There must be a trigger commit.  It's worth investigating.
> 
> Thank you for your information.
> 
> Umm, As far as I can see, I think that this test failure related with
> changing to Web Animations(Element.animate) from CSS Animations. [1] After
> this changing, this test will fail on treeherder[2] and my environment. But
> I think that probability depends on rate of tick. i.e. FPS.
> In my environment, If use previous tests file(before [1]), I can't reproduce
> this phenomenon with any FPS value.
> 
> [1]
> https://hg.mozilla.org/mozilla-central/annotate/4317e4c26505/dom/animation/
> test/mozilla/file_deferred_start.html#l101
> [2]
> https://brasstacks.mozilla.com/orangefactor/
> ?display=Bug&bugid=1366603&endday=2017-08-24&startday=2017-05-01&tree=trunk
> 
> Previous test:
>  1. Add transform animation keyframe to CSS (div.style.animation =
> 'animTransform 100s -50s forwards';)
>  2. Getting Animation object. (var animation = div.getAnimations()[0];)
>  3. Waiting the MozAfterPaint (waitForPaints())
> 
> Current test:
>  1. Create Animation object. (var animation = div.animate({ transform: [...,
> ...] }, { duration:..., delay: ...}); )
>  2. Waiting the MozAfterPaint (waitForPaints())

It might be. But the point here is that why the animation is not on the compositor after MozAfterPaint event was received.  MozAfterPaint is fired when the main thread receives DidComposite from the compositor, the DidComposite is sent when we paint something on the compositor.  So, if we get the event, there are something painted. In this failure case, it's not for the animation, so, for what?
(In reply to Mantaroh Yoshinaga[:mantaroh] from comment #19)
> Umm, As far as I can see, I think that this test failure related with
> changing to Web Animations(Element.animate) from CSS Animations. [1]

...

> [1]
> https://hg.mozilla.org/mozilla-central/annotate/4317e4c26505/dom/animation/
> test/mozilla/file_deferred_start.html#l101

That changeset is not about changing from Web Animations to CSS Animations -- it is making the test actually run!

A previous changeset completely disabled the test and [1] simply made the test run again. That's why we started getting failures again.

If you read the description of [1] there's a description of what the change was. Specifically in [2] from bug 1168759 we changed:

 return animation.ready.then(function() {

to:

 return waitForPaints(function() {

but waitForPaints returns a promise. What we really wanted was:

 return waitForPaints().then(function() {

So basically the test didn't run at all. Then at the beginning of May I fixed it to run again and the intermittent failures resumed. Presumably no-one filed a bug for it until the end of May however.

Since then it's become more frequent but there's no particularly sudden jump. It may simply be that perf improvements elsewhere make it more likely to happen now.

[2] https://hg.mozilla.org/mozilla-central/rev/986b18fdfdba
(In reply to Hiroyuki Ikezoe (:hiro) from comment #20)
> It might be. But the point here is that why the animation is not on the
> compositor after MozAfterPaint event was received.  MozAfterPaint is fired
> when the main thread receives DidComposite from the compositor, the
> DidComposite is sent when we paint something on the compositor.  So, if we
> get the event, there are something painted. In this failure case, it's not
> for the animation, so, for what?

Thanks Hiro.

I have a question about compositor, composite procedure of compositor thread rely on vsync?

The main process fired a vsync message after calling getOMTASyle(). After received vsync message, DidComposite occurred from Compositor. This DidComposite has never appeared in the log before receiving vsync.

Is my understanding correct?

I think that this test will need to wait for that compositor receive vsync.
Flags: needinfo?(hikezoe)
Though I think those question should be replied by a graphics guy.

(In reply to Mantaroh Yoshinaga[:mantaroh] from comment #22)
> (In reply to Hiroyuki Ikezoe (:hiro) from comment #20)
> > It might be. But the point here is that why the animation is not on the
> > compositor after MozAfterPaint event was received.  MozAfterPaint is fired
> > when the main thread receives DidComposite from the compositor, the
> > DidComposite is sent when we paint something on the compositor.  So, if we
> > get the event, there are something painted. In this failure case, it's not
> > for the animation, so, for what?
> 
> Thanks Hiro.
> 
> I have a question about compositor, composite procedure of compositor thread
> rely on vsync?

Sure.

> The main process fired a vsync message after calling getOMTASyle(). After
> received vsync message, DidComposite occurred from Compositor. This
> DidComposite has never appeared in the log before receiving vsync.

Could you elaborate this more?  I don't quite why you are watching getOMTAStyle() call. I think what we need to check is waitForPaints() call here.

My wild guess from what you are talking about is that we received a MozAfterPaint event which was actually sent from the compositor before Element.animate(). Anyway, it's due to bug 1341294, I guess.
Flags: needinfo?(hikezoe)
(In reply to Hiroyuki Ikezoe (:hiro) from comment #23)

> Could you elaborate this more?  I don't quite why you are watching
> getOMTAStyle() call. 

*quite understand*
(In reply to Hiroyuki Ikezoe (:hiro) from comment #23)
> > The main process fired a vsync message after calling getOMTASyle(). After
> > received vsync message, DidComposite occurred from Compositor. This
> > DidComposite has never appeared in the log before receiving vsync.
> 
> Could you elaborate this more?  I don't quite why you are watching
> getOMTAStyle() call. I think what we need to check is waitForPaints() call
> here.
> 
> My wild guess from what you are talking about is that we received a
> MozAfterPaint event which was actually sent from the compositor before
> Element.animate(). Anyway, it's due to bug 1341294, I guess.

As discussed with hiro, I decided that I will fix this bug as workaround.
Actually, this test doesn't wait for MozAfterPaint after creating Element.animate() since DOMWindowUtils.IsMozAfterPaintPending will return false. (i.e. MozAfterPaint event has not been queued yet)[1].

[1] http://searchfox.org/mozilla-central/rev/5696c3e525fc8222674eed6a562f5fcbe804c4c7/testing/mochitest/tests/SimpleTest/paint_listener.js#60

If bug 1341294 fixed, gecko can receive MozAfterPaint corresponded to own paint, so this check code of DOMWindowUtils.IsAfterPaintPending will not be necessary.
Comment on attachment 8901015 [details]
Bug 1366603 - Wait for rAF before waiting the MozAfterPaint in test_deferred_start.html.

https://reviewboard.mozilla.org/r/172490/#review178228

I think waiting for an rAF is fine, but comments should be revised.

::: commit-message-f0abd:3
(Diff revision 1)
> +Bug 1366603 - Wait for rAF before waiting the MozAfterPaint in test_deferred_start.html. r?hiro
> +
> +This test will call waitForPaints() before creating animation, but gecko will

Nit: before created animation is sent to the compositor.

Oops, wrong.  This sentence is somewhat confusing.
Actually we called waitForPaints() right after Element.animte() (i.e. creating the animation), but the waitForPaints() did not actually wait for a MozAfterPaint event because DOMWindowUtils.isMozAfterPaintPending which is checked in waitForPaints is false at the moment, right?  As a result, we processed the next micro task for getOMTAStyle call before the animation is sent to the compositor, right?

::: commit-message-f0abd:7
(Diff revision 1)
> +
> +This test will call waitForPaints() before creating animation, but gecko will
> +return false in DOMWindowUtils.IsMozAfterPaintPending, so this waitForPaint()
> +doesn't work for expected.[1] (i.e. this test doesn't wait for MozAfterPaint)
> +
> +This is related with bug 1341294. If gecko can receive MozAfterPaint

Nit: related to.

::: commit-message-f0abd:7
(Diff revision 1)
> +
> +This test will call waitForPaints() before creating animation, but gecko will
> +return false in DOMWindowUtils.IsMozAfterPaintPending, so this waitForPaint()
> +doesn't work for expected.[1] (i.e. this test doesn't wait for MozAfterPaint)
> +
> +This is related with bug 1341294. If gecko can receive MozAfterPaint

receive a MozAfterPaint.

::: commit-message-f0abd:8
(Diff revision 1)
> +This test will call waitForPaints() before creating animation, but gecko will
> +return false in DOMWindowUtils.IsMozAfterPaintPending, so this waitForPaint()
> +doesn't work for expected.[1] (i.e. this test doesn't wait for MozAfterPaint)
> +
> +This is related with bug 1341294. If gecko can receive MozAfterPaint
> +corresponded to own paint, waitForPaint() does not necessary check that

does not need to check.

::: commit-message-f0abd:9
(Diff revision 1)
> +return false in DOMWindowUtils.IsMozAfterPaintPending, so this waitForPaint()
> +doesn't work for expected.[1] (i.e. this test doesn't wait for MozAfterPaint)
> +
> +This is related with bug 1341294. If gecko can receive MozAfterPaint
> +corresponded to own paint, waitForPaint() does not necessary check that
> +MozAfterPaint event has been quequed.

Is that mean the check for isMozAfterPaintingPending, right?

::: commit-message-f0abd:11
(Diff revision 1)
> +
> +This is related with bug 1341294. If gecko can receive MozAfterPaint
> +corresponded to own paint, waitForPaint() does not necessary check that
> +MozAfterPaint event has been quequed.
> +
> +This patch is workaround until resolve bug 1341294.

is a workaround until bug 1341294 is resolved.

::: dom/animation/test/mozilla/file_deferred_start.html:110
(Diff revision 1)
> +    // This waitForFrame() uses Promise, but bug 1193394 will be using same
> +    // handling of  microtask, so if landed bug 1193394 this test might be failure.

I read the patch for bug 1193394.
To be more clear, if I understand the patch for bug 1193394 correctly,
after bug 1193394 is fixed, the source of the micro task (i.e. the callback of MozAfterPaint) is processed after paint process on the main thread because the callback for the event is processed there. That means above div.animate() is processed at that moment (i.e. after paint). So if we wait for an rAF, the callback for the rAF is processed in the next tick before styling, and the micro task for waitForFrame() is also processed at the same time, that means we have no chance to paint the animation. Then if waitForPaints() did not actually wait for a MozAfterPaint event due to the mislabelled isMozAfterPaintPending flag, getOMTAStyle in the next micro task will be processed without painting the animation.

::: dom/animation/test/mozilla/file_deferred_start.html:156
(Diff revision 1)
> -  }).then(() => {
> +    // TODO: Current waitForPaint() will not wait for
> +    // MozAfterPaint(Bug 1341294), so this waiting code is workaround for it.
> +    // This waitForFrame() uses Promise, but bug 1193394 will be using same
> +    // handling of  microtask, so if landed bug 1193394 this test might be failure.

We don't need to repeat the same comment here. We can just say, 'As the above test case, we should fix bug 131294 before bug 1193394 lands'.
Attachment #8901015 - Flags: review?(hikezoe) → review+
Comment on attachment 8901015 [details]
Bug 1366603 - Wait for rAF before waiting the MozAfterPaint in test_deferred_start.html.

https://reviewboard.mozilla.org/r/172490/#review178228

Thank you for review.

I brushed up the comment.

> Nit: before created animation is sent to the compositor.
> 
> Oops, wrong.  This sentence is somewhat confusing.
> Actually we called waitForPaints() right after Element.animte() (i.e. creating the animation), but the waitForPaints() did not actually wait for a MozAfterPaint event because DOMWindowUtils.isMozAfterPaintPending which is checked in waitForPaints is false at the moment, right?  As a result, we processed the next micro task for getOMTAStyle call before the animation is sent to the compositor, right?

Yes, Correctlly, I mean that `after creating an animation`. sorry.
Pushed by mantaroh@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/859f3f5bfb3d
Wait for rAF before waiting the MozAfterPaint in test_deferred_start.html. r=hiro
https://hg.mozilla.org/mozilla-central/rev/859f3f5bfb3d
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
https://hg.mozilla.org/releases/mozilla-beta/rev/bc8f7e510cc8
Flags: in-testsuite+
Whiteboard: [stockwell needswork] → [stockwell fixed]
I think the fix in this bug was incorrect since it changed the meaning of the test by waiting an extra frame. As a result, if we fail to pass the animation to the compositor in the paint corresponding to *this* animation frame and instead pass it to the compositor in the *next* animation frame, the test will still pass, whereas it should fail.

I think we need to back out this change, fix the underlying bug involving ignoring unrelated DidComposite messages, then add some way to ignore MozAfterPaint events generated by the timer in EnsureEventualDidPaintEvent (unless we can remove that timer altogether).
Oh right, indeed.  Should we also make the values for assert_between_inclusive() stricter?  Though I don't think we can check the values on the compositor side more reliable, but it would be good to avoid this kind of mistakes.
Is this fix going to be backed out?
Flags: needinfo?(bbirtles)
(In reply to Andrei Ciure[:andrei_ciure_] from comment #38)
> Is this fix going to be backed out?

Not until the other steps suggested in comment 36 are also implemented (in bug 1341294 and either bug 1395971 or bug 1363957 I expect).
Flags: needinfo?(bbirtles)
Depends on: 1426017
No longer depends on: 1426017
You need to log in before you can comment on or make changes to this bug.