1473586 - Intermittent devtools/client/inspector/animation/test/browser_animation_summary-graph_compositor.js | This test exceeded the timeout threshold. It should be rewritten or split up.

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: aciure [at] mozilla.com

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

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

13:55:17     INFO -  501 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_summary-graph_compositor.js | The element should not have the compositor css class after rewinding -
13:55:17     INFO -  502 INFO Click on pause/resume button
13:55:17     INFO -  Buffered messages logged at 13:54:26
13:55:17     INFO -  503 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_summary-graph_compositor.js | The element should have the compositor css class after resuming -
13:55:17     INFO -  504 INFO Check compositor sign after setting the current time
13:55:17     INFO -  505 INFO Click 70 on scrubber controller
13:55:17     INFO -  Buffered messages logged at 13:54:46
13:55:17     INFO -  506 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_summary-graph_compositor.js | The element should not have the compositor css class after setting the current time -
13:55:17     INFO -  507 INFO Click on pause/resume button
13:55:17     INFO -  Buffered messages logged at 13:55:03
13:55:17     INFO -  508 INFO TEST-PASS | devtools/client/inspector/animation/test/browser_animation_summary-graph_compositor.js | The element should have the compositor css class after resuming -
13:55:17     INFO -  509 INFO Leaving test bound
13:55:17     INFO -  Buffered messages logged at 13:55:17
13:55:17     INFO -  510 INFO Removing tab.
13:55:17     INFO -  511 INFO Waiting for event: 'TabClose' on [object XULElement].
13:55:17     INFO -  512 INFO Got event: 'TabClose' on [object XULElement].
13:55:17     INFO -  513 INFO Tab removed and finished closing
13:55:17     INFO -  Buffered messages finished
13:55:17    ERROR -  514 INFO TEST-UNEXPECTED-FAIL | devtools/client/inspector/animation/test/browser_animation_summary-graph_compositor.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. -
13:55:17     INFO -  GECKO(4976) | MEMORY STAT | vsize 2596MB | vsizeMaxContiguous 131079109MB | residentFast 618MB | heapAllocated 238MB
13:55:17     INFO -  515 INFO TEST-OK | devtools/client/inspector/animation/test/browser_animation_summary-graph_compositor.js | took 173812ms
13:55:17     INFO -  GECKO(4976) | ++DOCSHELL 00000272B575F000 == 2 [pid = 5648] [id = {cf98637b-b94a-4146-9bb4-76fb31e42e82}]
13:55:17     INFO -  GECKO(4976) | ++DOMWINDOW == 3 (00000272BBB2F600) [pid = 5648] [serial = 122] [outer = 0000000000000000]
13:55:17     INFO -  GECKO(4976) | ++DOMWINDOW == 4 (00000272B9751400) [pid = 5648] [serial = 123] [outer = 00000272BBB2F600]
13:55:17     INFO -  516 INFO checking window state

Comment 1

[Joel Maher ( :jmaher ) (UTC -8)]

this test failure reproduced on test-verify as well as the previous push:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&filter-searchStr=cov%20win%20verify&tochange=085cdfb90903d4985f0de1dc7786522d9fb45596&fromchange=1dad493abb2dc49890a5d6a23340afa0719efd96&selectedJob=186634123

Comment 2

[Intermittent Failures Robot]

7 failures in 622 pushes (0.011 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 5
* mozilla-inbound: 1
* autoland: 1

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1473586&startday=2018-07-02&endday=2018-07-08&tree=trunk

Comment 3

[Intermittent Failures Robot]

5 failures in 623 pushes (0.008 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 5

Platform breakdown:
* windows10-64-ccov: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1473586&startday=2018-07-09&endday=2018-07-15&tree=trunk

Comment 4

[Intermittent Failures Robot]

22 failures in 117 pushes (0.188 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 8
* autoland: 8
* mozilla-central: 5
* try: 1

Platform breakdown:
* linux64: 19
* linux64-ccov: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1473586&startday=2018-07-20&endday=2018-07-20&tree=trunk

Comment 5

[Intermittent Failures Robot]

47 failures in 653 pushes (0.072 failures/push) were associated with this bug in the last 7 days. 

This is the #13 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: 18
* mozilla-inbound: 13
* autoland: 13
* try: 3

Platform breakdown:
* linux64: 34
* windows10-64-ccov: 6
* linux64-ccov: 6
* windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1473586&startday=2018-07-16&endday=2018-07-22&tree=trunk

Comment 6

[Tiberius Oros[:tiberius_oros]]

There have been 46 failures in the last week:
- linux64 /debug: 34
- windows10-64-ccov / debug: 6
- linux64-ccov / debug: 6

Recent log file and snippet with the failure:
https://treeherder.mozilla.org/logviewer.html#?job_id=189435627&repo=autoland&lineNumber=54007

[task 2018-07-22T23:09:14.135Z] 23:09:14     INFO - TEST-PASS | devtools/client/inspector/animation/test/browser_animation_summary-graph_compositor.js | The element should have the compositor css class after resuming - 
[task 2018-07-22T23:09:14.136Z] 23:09:14     INFO - Leaving test bound 
[task 2018-07-22T23:09:14.139Z] 23:09:14     INFO - Buffered messages logged at 23:09:13
[task 2018-07-22T23:09:14.140Z] 23:09:14     INFO - Removing tab.
[task 2018-07-22T23:09:14.141Z] 23:09:14     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2018-07-22T23:09:14.141Z] 23:09:14     INFO - Got event: 'TabClose' on [object XULElement].
[task 2018-07-22T23:09:14.143Z] 23:09:14     INFO - Tab removed and finished closing
[task 2018-07-22T23:09:14.144Z] 23:09:14     INFO - Buffered messages finished
[task 2018-07-22T23:09:14.145Z] 23:09:14     INFO - TEST-UNEXPECTED-FAIL | devtools/client/inspector/animation/test/browser_animation_summary-graph_compositor.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-22T23:09:14.146Z] 23:09:14     INFO - GECKO(1950) | MEMORY STAT | vsize 2340MB | residentFast 539MB | heapAllocated 206MB
[task 2018-07-22T23:09:14.147Z] 23:09:14     INFO - TEST-OK | devtools/client/inspector/animation/test/browser_animation_summary-graph_compositor.js | took 102539ms
[task 2018-07-22T23:09:14.150Z] 23:09:14     INFO - GECKO(1950) | ++DOCSHELL 0x7f9ff1c59800 == 2 [pid = 2077] [id = {863aee85-f8ae-464a-913a-872701c27cc2}]
[task 2018-07-22T23:09:14.151Z] 23:09:14     INFO - GECKO(1950) | ++DOMWINDOW == 6 (0x7f9ff5ab7200) [pid = 2077] [serial = 122] [outer = (nil)]
[task 2018-07-22T23:09:14.151Z] 23:09:14     INFO - GECKO(1950) | ++DOMWINDOW == 7 (0x7f9ff024e800) [pid = 2077] [serial = 123] [outer = 0x7f9ff5ab7200]
[task 2018-07-22T23:09:14.152Z] 23:09:14     INFO - checking window state

:jgraham, would you please have a look? Thank you.

Comment 7

[James Graham [:jgraham]]

I'm pretty sure that I'm not the right person to look at this. Maybe sole can redirect to someone on the devtools team?

Comment 8

[Intermittent Failures Robot]

22 failures in 126 pushes (0.175 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-central: 8
* mozilla-inbound: 7
* autoland: 4
* try: 3

Platform breakdown:
* linux64: 17
* linux64-ccov: 3
* windows10-64-msvc: 1
* osx-10-10: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1473586&startday=2018-07-23&endday=2018-07-23&tree=trunk

Comment 9

[Intermittent Failures Robot]

27 failures in 152 pushes (0.178 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 9
* autoland: 9
* mozilla-central: 6
* try: 3

Platform breakdown:
* linux64: 26
* linux64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1473586&startday=2018-07-24&endday=2018-07-24&tree=trunk

Comment 10

[Daisuke Akatsuka (:daisuke)]

Thanks, I'll take a look.

Comment 11

[Daisuke Akatsuka (:daisuke)]

Attachment: Bug 1473586: Reduce testing time and add requestLongerTimeout.

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

Comment 12

[Daisuke Akatsuka (:daisuke)]

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

I have tried to reduce the testing time.
It could reduce about 18% compare with previous way in my local environment.
And, added requestLongerTimeout, just to be safe.

Comment 13

[Gabriel Luong [:gl] (ΦωΦ)]

Comment on attachment 8994734 [details]
Bug 1473586: Reduce testing time and add requestLongerTimeout.

https://reviewboard.mozilla.org/r/259254/#review266244

Comment 14

[Daisuke Akatsuka (:daisuke)]

Thanks, Gabriel!
Will make the patch to land if the try was green.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a3f6db75bb07
Reduce testing time and add requestLongerTimeout. r=gl

Comment 16

[Andreea Pavel [:apavel]]

Backed out for failing talos headless at  ts_paint_heavy 

Push that started the failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=a3f6db75bb07da37512f032485af29f99649dd67

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=189980910&repo=autoland&lineNumber=797

Backout: https://hg.mozilla.org/integration/autoland/rev/9bce60d444985d38f4cd049870c5431cfeb87cfd

Comment 17

[Daisuke Akatsuka (:daisuke)]

Hi Andreea, thank you the information.

However, I don't think this failure was occurred by this patch, since the error message is below.
```
TEST-UNEXPECTED-ERROR | ts_paint_heavy | 404 Client Error: Not Found for url: https://queue.taskcluster.net/v1/task/XIvF6qscStuH1ZCEDabRhg/artifacts/public%2Ftoday-simple.tgz
```
Could you check again??

Comment 18

[Andreea Pavel [:apavel]]

:daisuke sure, will take a closed look at it and get back to you.

Comment 19

[Andreea Pavel [:apavel]]

This failed on the backout too, so it's not from here. I apologize for that. Can you reland it or should i? 

Again, sorry for the confusion.

Comment 20

[Daisuke Akatsuka (:daisuke)]

Thank you for the checking!
If possible, could you re-land, please?

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2876ce49557d
Reduce testing time and add requestLongerTimeout. r=gl

Comment 22

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/2876ce49557d

Comment 23

[Intermittent Failures Robot]

65 failures in 760 pushes (0.086 failures/push) were associated with this bug in the last 7 days. 

This is the #25 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-inbound: 21
* autoland: 16
* mozilla-central: 15
* try: 13

Platform breakdown:
* linux64: 58
* linux64-ccov: 3
* windows7-32: 2
* windows10-64-msvc: 1
* osx-10-10: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1473586&startday=2018-07-23&endday=2018-07-29&tree=trunk

Comment 24

[meck93]

We are trying to build a tool to automatically classify intermittent failures, which would provide a starting point for fixing the bug, reducing the manual work for the developers.
We are collecting some feedback on the results, to see if they’re good enough and where we need to improve.
    
For this bug, the tool says that the intermittent failure is most likely a:
Test Timeout: This includes test failures in which a single test case or the whole test suite timed out. This might be due to an unresponsive or slow target system (e.g. either the system that executes the tests or the os itself), a test suite which has grown too large causing intermittent-timeouts or a timeout threshold for a process, thread, function call which was set too small/too large.


Once you’re done investigating and/or fixing the bug, could you tell me:
- Did the tool correctly recognize the type of intermittent failure?
- Did the information from the tool help your analysis, the bug fixing process, or anything in the process? (please also let us know how the tool was useful and/or what would improve the tool's usefulness for you)