1439846 - Intermittent devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N)

Reporter

Description

•

6 years ago

treeherder

Filed by: csabou [at] mozilla.com

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

https://queue.taskcluster.net/v1/task/eIoVnqyQQAaNjiORXZv_BA/runs/1/artifacts/public/logs/live_backing.log

21:00:47     INFO -  37 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.js | detailEl should be visibled -
21:00:47     INFO -  38 INFO Checking animation detail visibility when choose node which has animations
21:00:47     INFO -  39 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  40 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  41 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  42 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  43 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  44 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  45 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  46 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  47 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  48 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  49 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  50 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  51 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  52 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  53 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  54 INFO Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/shared/base-loader.js -> resource://devtools/client/shared/vendor/react-dom-dev.js" line: 13001}]
21:00:47     INFO -  Buffered messages logged at 21:00:01
21:00:47     INFO -  55 INFO Selecting the node for '[Front for domnode/server1.conn4.child1/domnode32]'
21:00:47     INFO -  Buffered messages logged at 21:00:37
21:00:47     INFO -  56 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.js | detailEl should be unvisibled after choose html node -
21:00:47     INFO -  57 INFO Checking animation detail visibility when choose node which has an animation
21:00:47     INFO -  Buffered messages logged at 21:00:39
21:00:47     INFO -  58 INFO Selecting the node for '[Front for domnode/server1.conn4.child1/domnode37]'
21:00:47     INFO -  Buffered messages logged at 21:00:43
21:00:47     INFO -  59 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.js | detailEl should be visibled after choose .cssanimation-normal node -
21:00:47     INFO -  60 INFO Leaving test bound
21:00:47     INFO -  Buffered messages logged at 21:00:47
21:00:47     INFO -  61 INFO Removing tab.
21:00:47     INFO -  62 INFO Waiting for event: 'TabClose' on [object XULElement].
21:00:47     INFO -  63 INFO Got event: 'TabClose' on [object XULElement].
21:00:47     INFO -  64 INFO Tab removed and finished closing
21:00:47     INFO -  Buffered messages finished
21:00:47    ERROR -  65 INFO TEST-UNEXPECTED-FAIL | devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.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. -
21:00:47     INFO -  GECKO(2844) | MEMORY STAT | vsize 2347MB | vsizeMaxContiguous 130543455MB | residentFast 420MB | heapAllocated 108MB

Cosmin Sabou [:CosminS]

Comment 1

•

6 years ago

This has started to fail frequently on central. Could you please take a look? Thanks.

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=success&filter-classifiedState=unclassified&filter-searchStr=23d7cd54d3e5e0620bf782317364ef5ee5fa726d&noautoclassify&selectedJob=163284605

Flags: needinfo?(hikezoe)

Cosmin Sabou [:CosminS]

Comment 2

•

6 years ago

Please use this one. 

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=success&filter-searchStr=23d7cd54d3e5e0620bf782317364ef5ee5fa726d&noautoclassify&selectedJob=163384514

Hiroyuki Ikezoe (:hiro)

Comment 3

•

6 years ago

It seems to me the test is slow in the first place.

From a failure log;

TEST-INFO | screenshot: exit 0
Buffered messages logged at 07:12:03
15 INFO Entering test bound
16 INFO Adding a new tab with URL: http://example.com/browser/devtools/client/inspector/animation/test/doc_multi_timings.html
Buffered messages logged at 07:12:04
17 INFO Tab added and finished loading
18 INFO Loading the helper frame script chrome://mochitests/content/browser/devtools/client/inspector/animation/test/doc_frame_script.js
19 INFO Loading the helper frame script chrome://devtools/content/shared/frame-script-utils.js
20 INFO Opening the inspector
21 INFO Opening the toolbox
Buffered messages logged at 07:12:06
Buffered messages logged at 07:12:21
24 INFO Toolbox opened and focused
Buffered messages logged at 07:12:22
25 INFO Selecting the newanimationinspector sidebar
Buffered messages logged at 07:12:26
34 INFO Checking animation detail visibility if animation was unselected
35 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.js | The detail pane should be in the DOM -
36 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.js | detailEl should be unvisibled -
37 INFO Checking animation detail visibility if animation was selected by click
38 INFO Click on animation 0 in the timeline
Buffered messages logged at 07:12:52
39 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.js | detailEl should be visibled -
40 INFO Checking animation detail visibility when choose node which has animations
Buffered messages logged at 07:12:53
55 INFO Selecting the node for '[Front for domnode/server1.conn4.child1/domnode32]'
Buffered messages logged at 07:13:31
56 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.js | detailEl should be unvisibled after choose html node -
57 INFO Checking animation detail visibility when choose node which has an animation
Buffered messages logged at 07:13:33
58 INFO Selecting the node for '[Front for domnode/server1.conn4.child1/domnode37]'
Buffered messages logged at 07:13:38
59 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.js | detailEl should be visibled after choose .cssanimation-normal node -
60 INFO Leaving test bound
Buffered messages logged at 07:13:40
61 INFO Removing tab.
62 INFO Waiting for event: 'TabClose' on [object XULElement].
63 INFO Got event: 'TabClose' on [object XULElement].
64 INFO Tab removed and finished closing
Buffered messages finished
65 INFO TEST-UNEXPECTED-FAIL |

It took approximately 40s between 'Checking animation detail visibility when choose node which has animations' and "Selecting the node for '[Front for domnode/server1.conn4.child1/domnode32]'".  So I guess "await selectNodeAndWaitForAnimations(htmlNode, inspector);" [1] is something broken inside it.  I believe Daisuke knows something.
 
I can also see browser_animation_keyframes-graph_computed-value-path.js causes timeout as well. 

[1] https://hg.mozilla.org/mozilla-central/file/dd6caba14142/devtools/client/inspector/animation/test/browser_animation_animation-detail_visibility.js#l24
[2] https://treeherder.mozilla.org/logviewer.html#?job_id=163284605&repo=mozilla-central&lineNumber=2944

Flags: needinfo?(hikezoe) → needinfo?(dakatsuka)

Daisuke Akatsuka (:daisuke)

Assignee

Comment 4

•

6 years ago

Thanks, I'll take a look.

Comment hidden (Intermittent Failures Robot)

16 failures in 124 pushes (0.129 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-central: 15
* try: 1

Platform breakdown:
* windows10-64-ccov: 16

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1439846&startday=2018-02-21&endday=2018-02-21&tree=all

Hiroyuki Ikezoe (:hiro)

Updated

•

6 years ago

Comment 7

•

6 years ago

Umm, I tried with debug print at last week, could not reproduce,,
* https://treeherder.mozilla.org/#/jobs?repo=try&revision=3ba8610a04bdd468f36f7400e6e5d1428c7fc1aa
* https://treeherder.mozilla.org/#/jobs?repo=try&revision=0acdfd21824df899b4479ee72f11dd4b5f133537

However, it is taking too long time for windows10-64-ccov debug in above try, anyway.
* windows10-64-ccov debug: about 8 ~ 9sec
* Windows 10 x64 debug: about 1.5sec

Please let me think to reduce the time again.

Daisuke Akatsuka (:daisuke)

Assignee

Comment 8

•

6 years ago

If we introduce bug 1438755, though actually the time of graphs rendering reduce to about 2/3, it could not be a fundamental resolving. Of course, the graph rendering is one of reasons, but opening the inspector (even without graph) as well is taking a long time.
So, please let me add requestLongerTimeout at this time. 
(The test for previous animation inspector as well is calling requestLongerTimeout.)

Thanks.

Flags: needinfo?(dakatsuka)

Comment hidden (mozreview-request)

Review commit: https://reviewboard.mozilla.org/r/224202/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/224202/

Daisuke Akatsuka (:daisuke)

Assignee

Comment 10

•

6 years ago

try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=3a4c0f24574a169b843d32d003b3318178e8b324

Hiroyuki Ikezoe (:hiro)

Comment 11

•

6 years ago

I am wondering DAMP includes animation inspector as well?

http://docs.firefox-dev.tools/tests/performance-tests.html

Daisuke Akatsuka (:daisuke)

Assignee

Comment 12

•

6 years ago

Oh, thanks Hiro, let me try!

Gabriel Luong [:gl] (ΦωΦ)

Comment 13

•

6 years ago

mozreview-review

Comment on attachment 8955026 [details]
Bug 1439846: Add requestLongerTimeout to browser_animation_animation-detail_visibility.

https://reviewboard.mozilla.org/r/224202/#review230370

Attachment #8955026 - Flags: review?(gl) → review+

Gabriel Luong [:gl] (ΦωΦ)

Comment 14

•

6 years ago

mozreview-review

Comment on attachment 8955026 [details]
Bug 1439846: Add requestLongerTimeout to browser_animation_animation-detail_visibility.

https://reviewboard.mozilla.org/r/224202/#review230372

::: commit-message-52975:1
(Diff revision 1)
> +Bug 1439846: Add requestLongerTimeout to this test. r?gl

Add requestLongerTimeout to browser_animation_animation-detail_visibility.

Comment hidden (Intermittent Failures Robot)

57 failures in 831 pushes (0.069 failures/push) were associated with this bug in the last 7 days. 

This is the #24 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* mozilla-central: 49
* try: 8

Platform breakdown:
* windows10-64-ccov: 55
* linux64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1439846&startday=2018-02-26&endday=2018-03-04&tree=all

Comment hidden (mozreview-request)

Comment on attachment 8955026 [details]
Bug 1439846: Add requestLongerTimeout to browser_animation_animation-detail_visibility.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224202/diff/1-2/

Joel Maher ( :jmaher ) (UTC -8)

Updated

•

6 years ago

Whiteboard: [stockwell needswork]

Daisuke Akatsuka (:daisuke)

Assignee

Comment 17

•

6 years ago

I'm sorry for delay.

I have tried DAMP test[1]. This is the result[2].
The time for inspector.animationinspector.open and inspector.oldanimation.open is that opened a html which includes 22 animations, then opened the inspector, then selected the animation inspector.

The results are:
inspector.animationinspector.open: 769.33 ± 0.61%
inspector.oldanimationinspector.open: 905.00 ± 0.51% 

The new animation inspector did not so slow against previous one.

So, how we should address this bug.
I think we can choice two ways.

1. Add requestLongerTimeout.
2. Disable this test for windows10-64-ccov since a debugger test have disabled for windows10-64-ccov recently with same reason in bug 1424154.
Gabriel, how do you think?

[1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=b12d6ee626bd23a93750c47f711c97c94978f120&selectedJob=166408346
[2] https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=mozilla-central&newProject=try&newRevision=b12d6ee626bd23a93750c47f711c97c94978f120&originalSignature=f79b6a4f1f8f53326d3056f6c8008c0ff4de0a94&newSignature=f79b6a4f1f8f53326d3056f6c8008c0ff4de0a94&framework=1&selectedTimeRange=172800

Flags: needinfo?(gl)

Gabriel Luong [:gl] (ΦωΦ)

Comment 18

•

6 years ago

Yes #1 sounds fine and that's what we have reviewed already.

Flags: needinfo?(gl)

Daisuke Akatsuka (:daisuke)

Assignee

Comment 19

•

6 years ago

Okay, thanks.
I'll land it.

Daisuke Akatsuka (:daisuke)

Assignee

Updated

•

6 years ago

Assignee: nobody → dakatsuka

Pulsebot

Comment 20

•

6 years ago

Pushed by dakatsuka@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d55b703721d2
Add requestLongerTimeout to browser_animation_animation-detail_visibility. r=gl

Cosmin Sabou [:CosminS]

Comment 21

•

6 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/d55b703721d2

Status: NEW → RESOLVED

Closed: 6 years ago

status-firefox60: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → Firefox 60

Comment hidden (Intermittent Failures Robot)

22 failures in 747 pushes (0.029 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 19
* try: 3

Platform breakdown:
* windows10-64-ccov: 22

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1439846&startday=2018-03-05&endday=2018-03-11&tree=all

Joel Maher ( :jmaher ) (UTC -8)

Updated

•

6 years ago

Whiteboard: [stockwell needswork] → [stockwell fixed:other]

BMO Automation

Updated

•

6 years ago

Product: Firefox → DevTools