Linux jsdcov devtools tests timing out

RESOLVED FIXED in Firefox 60

Status

defect
RESOLVED FIXED
Last year
10 months ago

People

(Reporter: gbrown, Assigned: jmaher)

Tracking

(Blocks 1 bug, {leave-open})

Version 3
mozilla60
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox60 fixed)

Details

(Whiteboard: [stockwell disabled])

Attachments

(1 attachment)

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.
:jmaher -- Do you know what this is about?
Flags: needinfo?(jmaher)
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)
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)
See Also: → 1442982
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.
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.
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
: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)
Flags: needinfo?(gl) → needinfo?(dakatsuka)
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)
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.
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]
I suggest disabling this suite first. Then we can go into detail about how to fix this.
Flags: needinfo?(klahnakoski)
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.
Flags: needinfo?(jmaher)
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)
Blocks: 1436238
Blocks: 1441542
Attachment #8957534 - Flags: review?(gmierz2) → review+
Pushed by jmaher@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2c914b6e6668
Linux jsdcov devtools tests timing out. r=gmierz
https://hg.mozilla.org/mozilla-central/rev/2c914b6e6668
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → mozilla60
Keywords: leave-open
Whiteboard: [stockwell needswork] → [stockwell disabled]
Assignee: nobody → jmaher
You need to log in before you can comment on or make changes to this bug.