Closed Bug 1363957 Opened 7 years ago Closed 6 years ago

Intermittent dom/animation/test/mozilla/test_deferred_start.html | Test timed out. - Test timed out.

Categories

(Core :: DOM: Animation, defect, P5)

Product:
Core
Component:
DOM: Animation
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME
Tracking Flags:
Tracking Status
firefox58 --- disabled
firefox59 --- disabled

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

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

That will be bug 1361260 to blame, and specifically the added playbackRate test:

https://hg.mozilla.org/mozilla-central/rev/fc0edea49a70
This seems to have a pretty low failure rate so I'm leaving it for now. It has only occurred twice in 4~5 days and both on Android. Perhaps it gets stuck waiting for paints?
I added a comment about how I think we should fix this in bug 1366603 comment 36 but I probably should have commented here instead.
Whiteboard: [stockwell needswork]
Waiting for updates from bug 1366603
In the last 7 days, there were 121 failures. They occur on android-4-3-armv7-api16 (debug).

A recent log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=143609495&lineNumber=1792


A relevant part of the log where the test failed:

[task 2017-11-10T09:22:02.641Z] 09:22:02     INFO -  66 INFO None67 INFO TEST-START | dom/animation/test/mozilla/test_deferred_start.html
1789
[task 2017-11-10T09:27:17.200Z] 09:27:17     INFO -  Buffered messages logged at 09:27:13
1790
[task 2017-11-10T09:27:17.200Z] 09:27:17     INFO -  68 INFO TEST-PASS | dom/animation/test/mozilla/test_deferred_start.html |  - : Elided 2 passes or known failures.
1791
[task 2017-11-10T09:27:17.200Z] 09:27:17     INFO -  Buffered messages finished
1792
[task 2017-11-10T09:27:17.200Z] 09:27:17     INFO -  69 INFO TEST-UNEXPECTED-FAIL | dom/animation/test/mozilla/test_deferred_start.html | Test timed out. - Test timed out.
1793
[task 2017-11-10T09:27:38.274Z] 09:27:38     INFO -  70 INFO TEST-UNEXPECTED-FAIL | dom/animation/test/mozilla/test_deferred_start.html | Timeout - Timeout: Test runner timed us out.
1794
[task 2017-11-10T09:27:38.275Z] 09:27:38     INFO -  71 INFO TEST-UNEXPECTED-FAIL | dom/animation/test/mozilla/test_deferred_start.html | Starting an animation with a playbackRate starts from the correct point - Starting an animation with a playbackRate starts from the correct point: Test timed out
1795
[task 2017-11-10T09:27:38.276Z] 09:27:38     INFO -  72 INFO TEST-UNEXPECTED-FAIL | dom/animation/test/mozilla/test_deferred_start.html | Finished test - Finished test: Status: 2
1796
[task 2017-11-10T09:27:38.277Z] 09:27:38     INFO -  73 INFO TEST-OK | dom/animation/test/mozilla/test_deferred_start.html | took 339632ms

:birtles, can you please take a look?
Flags: needinfo?(bbirtles)
Mantaroh is working on this in bug 1395971.
Flags: needinfo?(bbirtles) → needinfo?(mantaroh)
Pushed by jmaher@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c90922dbea36
Disable dom/animation/test/mozilla/test_deferred_start.html on android/debug and win10 for frequent failures. r=me, a=test-only
this has been disabled, please remember to enable it while working on a patch
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
https://hg.mozilla.org/mozilla-central/rev/c90922dbea36
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox59: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
I hit this phenomenon on bug 1419226 as well.
We can confirm this problem on Android of debug build. 

It seems like that IsDOMAfterPaintPending() returns true always. A mechanism of this failure is as follow:

--------------------------------------------------------------------------------------------------------------
1) test will check that gecko has a pending paint event. (i.e. calling the isMozAfterPaintPending.)
2) nsPresContext::IsDOMAfterPaintPending() returns true due to pres context has a pending flush of view manager, then pres context queued MozAfterPaint(e.g transaction id is 'X').
3) Notify invalidation rectangle. (e.g. transaction id is X + 1)
4) Notify invalidation rectangle. (e.g. transaction id is X + 2)
5) Received DidComposite from compositor(transaction id is X + 1), then gecko fired MozAfterPaint with transaction id[X / X+1].
   After this step, pres context has pending transaction is [X+2]
6) test will check that gecko has a pending paint event.
7) nsPresContext::IsDOMAfterPaintPending() returns true due to pres context has unfired paint event (i.e. X + 2)
8) Notify invalidation rectangle. (e.g. transaction id is X + 3)
9) Received DidComposite from compositor(transaction id is X + 2), then gecko fired MozAfterPaint with transaction id[X + 2].
   After this step, pres context has pending transaction is [X+3]
10) test will check that gecko has a pending paint event.
11) nsPresContext::IsDOMAfterPaintPending returns true due to pres context has unfired paint event (i.e. X + 3)
--------------------------------------------------------------------------------------------------------------
The gecko continues these steps.

Maybe,, I guess that the delay of DidComposite causes this bug, or calling NotifyInvalidation() twice will cause this bug.
I don't believe Mantaroh is working on this any more: clearing ni.
Flags: needinfo?(mantaroh)
Priority: -- → P5
Closing since the failure hasn't happened for four months.
Status: REOPENED → RESOLVED
Closed: 7 years ago → 6 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.