Closed
Bug 1442823
Opened 7 years ago
Closed 7 years ago
Linux jsdcov devtools tests timing out
Categories
(Testing :: Code Coverage, defect)
Tracking
(firefox60 fixed)
RESOLVED
FIXED
mozilla60
Tracking | Status | |
---|---|---|
firefox60 | --- | fixed |
People
(Reporter: gbrown, Assigned: jmaher)
References
(Blocks 1 open bug)
Details
(Keywords: leave-open, Whiteboard: [stockwell disabled])
Attachments
(1 file)
1.01 KB,
patch
|
sparky
:
review+
|
Details | Diff | Splinter Review |
Beginning with https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=9b1228043619f2f80b5fc60d4c081950bd21e9e9&filter-searchStr=jsdcov several jsdcov devtools tasks have started running over 90 minutes and timing out, as reported against bug 1411358. Prior to that push, these tasks were completing in less than 30 minutes. Now failures are very frequent. Test logs seem very long and "spammy" to me.
Assignee | ||
Comment 2•7 years ago
|
||
let me redirect to :sparky- I am not aware of any specific changes to jsdcov; maybe this is a tooling or a devtools thing
Flags: needinfo?(jmaher) → needinfo?(gmierz2)
Comment 3•7 years ago
|
||
There have been some recent changes to CoverageUtils.jsm: https://hg.mozilla.org/mozilla-central/rev/2b2b6233aa0b But those devtools chunks still ran at around 30 minutes. It looks like something is being printed over and over again to me. I think this function [1] might correspond to the section that starts with "get onanimationstart()": https://dxr.mozilla.org/mozilla-central/source/obj-x86_64-pc-linux-gnu/dom/bindings/XULElementBinding.cpp#7664
Flags: needinfo?(gmierz2)
Reporter | ||
Comment 4•7 years ago
|
||
It is now apparent that jsdcov dt8 and some other devtools tasks are perma-fail, with timeouts reported to bug 1411358. devtools tasks on other (non-jsdcov) platforms are okay and do not have the excessive logging apparent in the jsdcov logs. We need to fix this or stop running jsdcov devtools.
Reporter | ||
Comment 5•7 years ago
|
||
Example of start of excessive logging from the first failing revision: https://treeherder.mozilla.org/logviewer.html#?job_id=164820471&repo=mozilla-central https://taskcluster-artifacts.net/bUHJBstqS5OYXEci4ctXPA/0/public/logs/live_backing.log [task 2018-02-28T11:20:21.551Z] 11:20:21 INFO - *** Start BrowserChrome Test Results *** [task 2018-02-28T11:20:21.609Z] 11:20:21 INFO - checking window state [task 2018-02-28T11:20:21.634Z] 11:20:21 INFO - TEST-START | devtools/client/inspector/animation/test/browser_animation_animated-property-list.js [task 2018-02-28T11:20:24.239Z] 11:20:24 INFO - GECKO(1383) | console.log: "[DISPATCH]" "{\n \"type\": \"UPDATE_SIDEBAR_SIZE\",\n \"sidebarSize\": {\n \"width\": 350,\n \"height\": 350,\n \"splitSidebarWidth\": 350\n }\n}" [task 2018-02-28T11:20:27.223Z] 11:20:27 INFO - GECKO(1383) | console.log: "[DISPATCH]" ({type:"UPDATE_ANIMATIONS", animations:[{conn:{_transport:{on:function bound on() { [task 2018-02-28T11:20:27.223Z] 11:20:27 INFO - GECKO(1383) | [native code] [task 2018-02-28T11:20:27.223Z] 11:20:27 INFO - GECKO(1383) | }, off:function bound off() { [task 2018-02-28T11:20:27.223Z] 11:20:27 INFO - GECKO(1383) | [native code] [task 2018-02-28T11:20:27.223Z] 11:20:27 INFO - GECKO(1383) | }, once:function bound once() { [task 2018-02-28T11:20:27.223Z] 11:20:27 INFO - GECKO(1383) | [native code] [task 2018-02-28T11:20:27.224Z] 11:20:27 INFO - GECKO(1383) | }, emit:function bound emit() { [task 2018-02-28T11:20:27.225Z] 11:20:27 INFO - GECKO(1383) | [native code] [task 2018-02-28T11:20:27.225Z] 11:20:27 INFO - GECKO(1383) | }, other:{on:function bound on() { [task 2018-02-28T11:20:27.226Z] 11:20:27 INFO - GECKO(1383) | [native code] [task 2018-02-28T11:20:27.227Z] 11:20:27 INFO - GECKO(1383) | }, off:function bound off() { [task 2018-02-28T11:20:27.228Z] 11:20:27 INFO - GECKO(1383) | [native code] [task 2018-02-28T11:20:27.228Z] 11:20:27 INFO - GECKO(1383) | }, once:function bound once() { [task 2018-02-28T11:20:27.229Z] 11:20:27 INFO - GECKO(1383) | [native code] [task 2018-02-28T11:20:27.229Z] 11:20:27 INFO - GECKO(1383) | }, emit:function bound emit() { [task 2018-02-28T11:20:27.230Z] 11:20:27 INFO - GECKO(1383) | [native code] [task 2018-02-28T11:20:27.232Z] 11:20:27 INFO - GECKO(1383) | }, other:{}, hooks:{_prefix:"server1.conn0.", _transport:{}, _nextID:12, _actorPool:{conn:{}, _actors:{root:{conn:{}, _parameters:{tabList:{_connection:{}, _actorByBrowser:{}, _onListChanged:function bound onTabListChanged() { [task 2018-02-28T11:20:27.233Z] 11:20:27 INFO - GECKO(1383) | [native code] [task 2018-02-28T11:20:27.234Z] 11:20:27 INFO - GECKO(1383) | }, _mustNotify:true, _testing:false, _listeningForTabClose:true, _listeningToMediator:true, _foundCount:2, _listeningForTabOpen:true, _listeningForTitleChange:true}, addonList:{_connection:{}, _actorByAddonId:{}, _onListChanged:null}, workerList:{_conn:{}, _options:{}, _actors:{}, _onListChanged:null, _mustNotify:false, onRegister:function bound onRegister() { [task 2018-02-28T11:20:27.235Z] 11:20:27 INFO - GECKO(1383) | [native code] ... In the previous push, the same test is well-behaved: https://treeherder.mozilla.org/logviewer.html#?job_id=164724696&repo=mozilla-central&lineNumber=5136-5161 task 2018-02-27T23:35:54.310Z] 23:35:54 INFO - *** Start BrowserChrome Test Results *** [task 2018-02-27T23:35:54.358Z] 23:35:54 INFO - checking window state [task 2018-02-27T23:35:54.394Z] 23:35:54 INFO - TEST-START | devtools/client/inspector/animation/test/browser_animation_animated-property-list.js [task 2018-02-27T23:35:56.900Z] 23:35:56 INFO - GECKO(1374) | console.log: [DISPATCH] { [task 2018-02-27T23:35:56.901Z] 23:35:56 INFO - GECKO(1374) | "type": "UPDATE_SIDEBAR_SIZE", [task 2018-02-27T23:35:56.902Z] 23:35:56 INFO - GECKO(1374) | "sidebarSize": { [task 2018-02-27T23:35:56.904Z] 23:35:56 INFO - GECKO(1374) | "width": 350, [task 2018-02-27T23:35:56.905Z] 23:35:56 INFO - GECKO(1374) | "height": 350, [task 2018-02-27T23:35:56.906Z] 23:35:56 INFO - GECKO(1374) | "splitSidebarWidth": 350 [task 2018-02-27T23:35:56.908Z] 23:35:56 INFO - GECKO(1374) | } [task 2018-02-27T23:35:56.909Z] 23:35:56 INFO - GECKO(1374) | } [task 2018-02-27T23:35:56.967Z] 23:35:56 INFO - GECKO(1374) | console.log: [DISPATCH] {type:..,animations:.., } [task 2018-02-27T23:35:57.063Z] 23:35:57 INFO - GECKO(1374) | console.log: [DISPATCH] { [task 2018-02-27T23:35:57.065Z] 23:35:57 INFO - GECKO(1374) | "type": "UPDATE_SELECTED_ANIMATION", [task 2018-02-27T23:35:57.066Z] 23:35:57 INFO - GECKO(1374) | "selectedAnimation": null [task 2018-02-27T23:35:57.066Z] 23:35:57 INFO - GECKO(1374) | } [task 2018-02-27T23:35:57.597Z] 23:35:57 INFO - GECKO(1374) | console.log: [DISPATCH] {type:..,animations:.., } [task 2018-02-27T23:35:57.621Z] 23:35:57 INFO - GECKO(1374) | console.log: [DISPATCH] {type:..,selectedAnimation:.., } [task 2018-02-27T23:35:57.783Z] 23:35:57 INFO - GECKO(1374) | console.log: [DISPATCH] {type:..,animations:.., } [task 2018-02-27T23:35:57.804Z] 23:35:57 INFO - GECKO(1374) | console.log: [DISPATCH] {type:..,selectedAnimation:.., } [task 2018-02-27T23:35:57.949Z] 23:35:57 INFO - GECKO(1374) | Collecting coverage for: chrome://mochitests/content/browser/devtools/client/inspector/animation/test/browser_animation_animated-property-list.js [task 2018-02-27T23:35:58.819Z] 23:35:58 INFO - GECKO(1374) | Writing coverage to: /builds/worker/workspace/build/blobber_upload_dir/jscov_1519774558812.json [task 2018-02-27T23:35:59.030Z] 23:35:59 INFO - GECKO(1374) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration. [task 2018-02-27T23:35:59.030Z] 23:35:59 INFO - GECKO(1374) | MEMORY STAT | vsize 2164MB | residentFast 443MB | heapAllocated 205MB [task 2018-02-27T23:35:59.030Z] 23:35:59 INFO - TEST-OK | devtools/client/inspector/animation/test/browser_animation_animated-property-list.js | took 4640ms [task 2018-02-27T23:35:59.078Z] 23:35:59 INFO - checking window state ...but I don't see any recent changes to that test, and other tests have the same behavior.
Reporter | ||
Comment 6•7 years ago
|
||
The same test is well behaved on linux64/opt: https://treeherder.mozilla.org/logviewer.html#?job_id=164819394&repo=mozilla-central&lineNumber=2003-2014 [task 2018-02-28T11:02:34.870Z] 11:02:34 INFO - checking window state [task 2018-02-28T11:02:34.934Z] 11:02:34 INFO - TEST-START | devtools/client/inspector/animation/test/browser_animation_animated-property-list.js [task 2018-02-28T11:02:38.257Z] 11:02:38 INFO - GECKO(1040) | console.log: "[DISPATCH]" "{\n \"type\": \"UPDATE_SIDEBAR_SIZE\",\n \"sidebarSize\": {\n \"width\": 350,\n \"height\": 350,\n \"splitSidebarWidth\": 350\n }\n}" [task 2018-02-28T11:02:38.314Z] 11:02:38 INFO - GECKO(1040) | console.log: "[DISPATCH]" [task 2018-02-28T11:02:38.434Z] 11:02:38 INFO - GECKO(1040) | console.log: "[DISPATCH]" "{\n \"type\": \"UPDATE_SELECTED_ANIMATION\",\n \"selectedAnimation\": null\n}" [task 2018-02-28T11:02:39.061Z] 11:02:39 INFO - GECKO(1040) | console.log: "[DISPATCH]" [task 2018-02-28T11:02:39.081Z] 11:02:39 INFO - GECKO(1040) | console.log: "[DISPATCH]" [task 2018-02-28T11:02:39.247Z] 11:02:39 INFO - GECKO(1040) | console.log: "[DISPATCH]" [task 2018-02-28T11:02:39.269Z] 11:02:39 INFO - GECKO(1040) | console.log: "[DISPATCH]" [task 2018-02-28T11:02:39.635Z] 11:02:39 INFO - GECKO(1040) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration. [task 2018-02-28T11:02:39.638Z] 11:02:39 INFO - GECKO(1040) | MEMORY STAT | vsize 2139MB | residentFast 380MB | heapAllocated 169MB [task 2018-02-28T11:02:39.640Z] 11:02:39 INFO - TEST-OK | devtools/client/inspector/animation/test/browser_animation_animated-property-list.js | took 4700ms
Reporter | ||
Comment 7•7 years ago
|
||
:gl - Do you understand what has happened here? It looks like it is normal to have some 'console.log: "[DISPATCH]"' logging during some devtools tests, presumably via https://dxr.mozilla.org/mozilla-central/source/devtools/client/shared/redux/middleware/log.js. But now, on jsdcov builds only, there seems to be a very large object logged, starting with '({type:"UPDATE_ANIMATIONS"'.
Flags: needinfo?(gl)
Updated•7 years ago
|
Flags: needinfo?(gl) → needinfo?(dakatsuka)
Comment 8•7 years ago
|
||
We are sending animation actors[1] in UPDATE_ANIMATIONS. I think those objects were printing. However, in this case, normally, JSON.stringify should be failing, and those will print by console.log in catch block. Because the actors have "cyclic object value". I don't know exactly how jscov works, but the handling of "cyclic object value" might differ? [1] https://searchfox.org/mozilla-central/source/devtools/shared/fronts/animation.js
Flags: needinfo?(dakatsuka)
Reporter | ||
Comment 9•7 years ago
|
||
https://hg.mozilla.org/mozilla-central/rev/a3fce9084969 is included in the regressing merge and changes console imports in devtools code -- I wonder if that could be related.
Reporter | ||
Comment 10•7 years ago
|
||
Although *this* bug isn't an intermittent-failure bug, the associated failures in bug 1411358 are quite frequent. :ekyle - As triage owner here, can you think of a way to resolve this, soon?
Flags: needinfo?(klahnakoski)
Whiteboard: [stockwell needswork]
Comment 11•7 years ago
|
||
I suggest disabling this suite first. Then we can go into detail about how to fix this.
Flags: needinfo?(klahnakoski)
Assignee | ||
Comment 12•7 years ago
|
||
Attachment #8957534 -
Flags: review?(gmierz2)
Comment 13•7 years ago
|
||
Jmaher, I'm worried this change will be erased here: https://dxr.mozilla.org/mozilla-central/source/taskcluster/taskgraph/transforms/tests.py#741 You should make the restriction in that function to be sure it works. The run-on-projects flag you set in the YAML might not make it to the end. This flag is notoriously problematic for jsdcov/ccov.
Updated•7 years ago
|
Flags: needinfo?(jmaher)
Assignee | ||
Comment 14•7 years ago
|
||
thanks for pointing this out. I had forgotten about that transform. Based on the transform comment/code |test['run-on-projects'] == 'built-projects'|, I think we are ok as this is only run-on-projects=['try']
Flags: needinfo?(jmaher)
Updated•7 years ago
|
Attachment #8957534 -
Flags: review?(gmierz2) → review+
Comment 15•7 years ago
|
||
Pushed by jmaher@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/2c914b6e6668 Linux jsdcov devtools tests timing out. r=gmierz
Comment 16•7 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/2c914b6e6668
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox60:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla60
Assignee | ||
Updated•7 years ago
|
Keywords: leave-open
Whiteboard: [stockwell needswork] → [stockwell disabled]
Updated•6 years ago
|
Assignee: nobody → jmaher
You need to log in
before you can comment on or make changes to this bug.
Description
•