Filed by: philringnalda [at] gmail.com https://treeherder.mozilla.org/logviewer.html#?job_id=100750353&repo=autoland https://archive.mozilla.org/pub/firefox/tinderbox-builds/autoland-macosx64/autoland_yosemite_r7_test-mochitest-1-bm106-tests1-macosx-build299.txt.gz

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?

Mantaroh will look at this. If he hasn't made progress in a day or two I will take over.

(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

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.

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.

(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'.

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

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?

(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).