Closed Bug 1475441 Opened Last year Closed Last year

Intermittent devtools/client/inspector/animation/test/browser_animation_rewind-button.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort.

Categories

(DevTools :: Inspector: Animations, defect, P5)

defect

Tracking

(firefox63 fixed)

RESOLVED FIXED
Firefox 63
Tracking Status
firefox63 --- fixed

People

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

Details

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

Attachments

(1 file)

Filed by: toros [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=187939237&repo=mozilla-central

https://queue.taskcluster.net/v1/task/FtIX8B6HQVOMLX72YHM0Rg/runs/0/artifacts/public/logs/live_backing.log

23:49:19     INFO -  17 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_rewind-button.js | Rewind button should exist -
23:49:19     INFO -  18 INFO Checking rewind button makes animations to rewind to zero
23:49:19     INFO -  19 INFO Click on rewind button
23:49:19     INFO -  Buffered messages logged at 23:48:45
23:49:19     INFO -  20 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_rewind-button.js | Current time of animations should be 0 -
23:49:19     INFO -  21 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_rewind-button.js | All animations should be paused -
23:49:19     INFO -  22 INFO Checking rewind button makes animations after clicking scrubber
23:49:19     INFO -  23 INFO Click 61.5 on scrubber controller
23:49:19     INFO -  Buffered messages logged at 23:48:58
23:49:19     INFO -  24 INFO Click on rewind button
23:49:19     INFO -  Buffered messages logged at 23:49:09
23:49:19     INFO -  25 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_rewind-button.js | Current time of animations should be 0 -
23:49:19     INFO -  26 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_rewind-button.js | All animations should be paused -
23:49:19     INFO -  27 INFO Leaving test bound
23:49:19     INFO -  Buffered messages logged at 23:49:19
23:49:19     INFO -  28 INFO Removing tab.
23:49:19     INFO -  29 INFO Waiting for event: 'TabClose' on [object XULElement].
23:49:19     INFO -  30 INFO Got event: 'TabClose' on [object XULElement].
23:49:19     INFO -  31 INFO Tab removed and finished closing
23:49:19     INFO -  Buffered messages finished
23:49:19    ERROR -  32 INFO TEST-UNEXPECTED-FAIL | devtools/client/inspector/animation/test/browser_animation_rewind-button.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
23:49:19     INFO -  GECKO(4304) | MEMORY STAT | vsize 2341MB | vsizeMaxContiguous 131549489MB | residentFast 392MB | heapAllocated 115MB
23:49:19     INFO -  33 INFO TEST-OK | devtools/client/inspector/animation/test/browser_animation_rewind-button.js | took 135466ms
23:49:19     INFO -  GECKO(4304) | ++DOCSHELL 0000023AEDF67800 == 1 [pid = 536] [id = {7a1b7fcb-5188-4ec0-b511-fad186a1f6f6}]
23:49:19     INFO -  GECKO(4304) | ++DOMWINDOW == 1 (0000023AEDF29200) [pid = 536] [serial = 1] [outer = 0000000000000000]
23:49:20     INFO -  34 INFO checking window state
23:49:20     INFO -  GECKO(4304) | ++DOMWINDOW == 22 (00000282465DB400) [pid = 4304] [serial = 30] [outer = 000002824CC04800]
23:49:20     INFO -  GECKO(4304) | ++DOMWINDOW == 2 (0000023AF20E1000) [pid = 536] [serial = 2] [outer = 0000023AEDF29200]
23:49:20     INFO -  GECKO(4304) | ++DOMWINDOW == 23 (0000028247677400) [pid = 4304] [serial = 31] [outer = 000002824CC04800]
23:49:21     INFO -  GECKO(4304) | --DOCSHELL 000001F3A825E000 == 0 [pid = 4548] [id = {567e1836-d7da-4c1d-891b-5d9320d969b7}]
23:49:21     INFO -  GECKO(4304) | --DOCSHELL 0000023EB3A4F800 == 0 [pid = 3016] [id = {a2432f96-8ee0-426d-aed5-2244484dcd00}]
23:49:21     INFO -  GECKO(4304) | --DOMWINDOW == 1 (000001F3A8205800) [pid = 4548] [serial = 4] [outer = 0000000000000000] [url = about:blank]
23:49:21     INFO -  GECKO(4304) | --DOMWINDOW == 0 (000001F3A82C4C00) [pid = 4548] [serial = 5] [outer = 0000000000000000] [url = about:blank]
23:49:21     INFO -  GECKO(4304) | --DOCSHELL 000001D06496F800 == 0 [pid = 8140] [id = {037864ee-527d-4cf2-be82-ab57c0271474}]
23:49:22     INFO -  GECKO(4304) | --DOMWINDOW == 1 (0000023EAD827E00) [pid = 3016] [serial = 5] [outer = 0000000000000000] [url = about:newtab]
23:49:22     INFO -  GECKO(4304) | --DOMWINDOW == 0 (0000023EB3AC3400) [pid = 3016] [serial = 7] [outer = 0000000000000000] [url = about:newtab]
23:49:22     INFO -  GECKO(4304) | --DOMWINDOW == 1 (000001D064927C00) [pid = 8140] [serial = 1] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/inspector/animation/test/doc_multi_timings.html]
23:49:22     INFO -  GECKO(4304) | --DOMWINDOW == 0 (000001D06AEAC400) [pid = 8140] [serial = 3] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/inspector/animation/test/doc_multi_timings.html]
23:49:25     INFO -  GECKO(4304) | --DOMWINDOW == 22 (00000282514B2800) [pid = 4304] [serial = 24] [outer = 0000000000000000] [url = about:blank]
23:49:28     INFO -  GECKO(4304) | --DOMWINDOW == 21 (000002823D523A00) [pid = 4304] [serial = 27] [outer = 0000000000000000] [url = chrome://devtools/content/inspector/markup/markup.xhtml]
23:49:28     INFO -  GECKO(4304) | --DOMWINDOW == 20 (0000028247026800) [pid = 4304] [serial = 21] [outer = 0000000000000000] [url = chrome://devtools/content/inspector/index.xhtml]
23:49:28     INFO -  GECKO(4304) | --DOMWINDOW == 19 (0000028247684C00) [pid = 4304] [serial = 29] [outer = 0000000000000000] [url = about:blank]
23:49:28     INFO -  GECKO(4304) | --DOMWINDOW == 18 (000002824CC09000) [pid = 4304] [serial = 18] [outer = 0000000000000000] [url = about:blank]
23:49:28     INFO -  GECKO(4304) | --DOMWINDOW == 17 (000002824FBB4C00) [pid = 4304] [serial = 20] [outer = 0000000000000000] [url = about:devtools-toolbox]
23:49:28     INFO -  GECKO(4304) | --DOMWINDOW == 16 (000002824E481400) [pid = 4304] [serial = 11] [outer = 0000000000000000] [url = about:blank]
23:49:28     INFO -  GECKO(4304) | --DOMWINDOW == 15 (00000282465DB400) [pid = 4304] [serial = 30] [outer = 0000000000000000] [url = about:blank]
23:49:28     INFO -  GECKO(4304) | --DOMWINDOW == 14 (000002824CB24000) [pid = 4304] [serial = 19] [outer = 0000000000000000] [url = about:blank]
23:49:30     INFO -  GECKO(4304) | Completed ShutdownLeaks collections in process 536
23:49:30     INFO -  GECKO(4304) | Completed ShutdownLeaks collections in process 4548
23:49:30     INFO -  GECKO(4304) | Completed ShutdownLeaks collections in process 2200
23:49:31     INFO -  GECKO(4304) | Completed ShutdownLeaks collections in process 3016
23:49:31     INFO -  GECKO(4304) | --DOMWINDOW == 13 (000002824E480C00) [pid = 4304] [serial = 28] [outer = 0000000000000000] [url = chrome://devtools/content/inspector/markup/markup.xhtml]
23:49:31     INFO -  GECKO(4304) | --DOMWINDOW == 12 (000002825255C000) [pid = 4304] [serial = 22] [outer = 0000000000000000] [url = about:blank]
23:49:31     INFO -  GECKO(4304) | Completed ShutdownLeaks collections in process 8140
23:49:34     INFO -  35 INFO Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
23:49:35     INFO -  GECKO(4304) | [Parent 4304, Lazy Idle] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/widget/windows/WinUtils.cpp, line 1470
23:49:42     INFO -  GECKO(4304) | Completed ShutdownLeaks collections in process 4304
23:49:42     INFO -  36 INFO TEST-START | Shutdown
23:49:42     INFO -  37 INFO Browser Chrome Test Summary
23:49:42     INFO -  38 INFO Passed:  5
23:49:42  WARNING -  39 INFO Failed:  1
23:49:42  WARNING -  One or more unittests failed.
23:49:42     INFO -  40 INFO Todo:    0
23:49:42     INFO -  41 INFO Mode:    e10s
23:49:42     INFO -  42 INFO *** End BrowserChrome Test Results ***
This failure seems to have been introduced with https://bugzilla.mozilla.org/show_bug.cgi?id=1468475 

https://hg.mozilla.org/integration/autoland/rev/12b86e5e0725#l4.2

This has also a tier1 failure here: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=99ac85a273af610206c5077fed6a5841d9678291&selectedJob=188766819 but it's intermittent not perma. 


:mantaroh can you please give your input here?
Flags: needinfo?(mantaroh)
Summary: Perma fail [tier 2] devtools/client/inspector/animation/test/browser_animation_rewind-button.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. → Intermittent devtools/client/inspector/animation/test/browser_animation_rewind-button.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort.
There have been 32 failures in the last 7 days, all of them on Linux x64 CCov debug.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=190638415&repo=mozilla-central&lineNumber=46759

[task 2018-07-28T00:45:13.733Z] 00:45:13     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2018-07-28T00:45:13.733Z] 00:45:13     INFO - Got event: 'TabClose' on [object XULElement].
[task 2018-07-28T00:45:13.734Z] 00:45:13     INFO - Tab removed and finished closing
[task 2018-07-28T00:45:13.734Z] 00:45:13     INFO - Buffered messages finished
[task 2018-07-28T00:45:13.734Z] 00:45:13     INFO - TEST-UNEXPECTED-FAIL | devtools/client/inspector/animation/test/browser_animation_rewind-button.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - 
[task 2018-07-28T00:45:13.735Z] 00:45:13     INFO - GECKO(2308) | MEMORY STAT | vsize 2475MB | residentFast 754MB | heapAllocated 242MB
[task 2018-07-28T00:45:13.735Z] 00:45:13     INFO - TEST-OK | devtools/client/inspector/animation/test/browser_animation_rewind-button.js | took 118354ms
Whiteboard: [stockwell needswork]
(In reply to Andreea Pavel [:apavel] from comment #3)
> This failure seems to have been introduced with
> https://bugzilla.mozilla.org/show_bug.cgi?id=1468475 
> 
> https://hg.mozilla.org/integration/autoland/rev/12b86e5e0725#l4.2
> 
> This has also a tier1 failure here:
> https://treeherder.mozilla.org/#/
> jobs?repo=autoland&revision=99ac85a273af610206c5077fed6a5841d9678291&selected
> Job=188766819 but it's intermittent not perma. 
> 
> 
> :mantaroh can you please give your input here?

Thanks apavel,

Sorry for my late reply. I'll look into this intermittent bug.
Component: Inspector → Animation Inspector
Flags: needinfo?(mantaroh)
As far as I can see the test failure, test looks passing. However, mochitest didn't finished. So we might need to add the equestLongerTimeout.

WIP: https://treeherder.mozilla.org/#/jobs?repo=try&revision=40c7b4fc5d773af0282270116f06f7a2e46cc166
(In reply to Mantaroh Yoshinaga[:mantaroh] from comment #8)
> Now, I'm going to try to separate this test:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=9b4e213db810f76ca2b2c9a5a51d2b741601dadb

Try result looks failed due to timeout, because, this test remove the animated element after animation inspector is opened. So this test will render twice. I'll try changing this removing code to before the opening the animation inspector.
I've been able to (so far) reliably reproduce an error similar to this while trying to disable telemetry on the linux64-ccov build: https://treeherder.mozilla.org/#/jobs?repo=try&revision=094e5accd4569f41dd0dd8351803132c5a217984&filter-searchStr=dt4

Here are the changes I made: https://hg.mozilla.org/try/rev/fb6a68e2ac69b6f597da4f2ae6309b7ca354853d
This test removed the animations after opening the animation inspector.
This removing animation code is unnecessary since the target document has not
these animation class. As a result of it, that test will take the long times.
However, this test will timeout even if removing that code. So this patch will
add requestLongerTimeout(2) for intermittent failure of the ccov test.
Comment on attachment 8999829 [details]
Bug 1475441 - Add requestLongerTimeout(2) and remove unnecessary code of removing animations. r?daisuke

Daisuke Akatsuka (:daisuke) has approved the revision.
Attachment #8999829 - Flags: review+
Pushed by mantaroh@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/e6584141d581
Add requestLongerTimeout(2) and remove unnecessary code of removing animations. r=daisuke
Assignee: nobody → mantaroh
https://hg.mozilla.org/mozilla-central/rev/e6584141d581
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → Firefox 63
You need to log in before you can comment on or make changes to this bug.