1442823 - Linux jsdcov devtools tests timing out

Status: RESOLVED FIXED

(Testing :: Code Coverage, defect)

Description

[Geoff Brown [:gbrown]]

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.

Comment 1

[Geoff Brown [:gbrown]]

:jmaher -- Do you know what this is about?

Comment 2

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

let me redirect to :sparky- I am not aware of any specific changes to jsdcov; maybe this is a tooling or a devtools thing

Comment 3

[Greg Mierzwinski [:sparky]]

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

Comment 4

[Geoff Brown [:gbrown]]

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.

Comment 5

[Geoff Brown [:gbrown]]

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.

Comment 6

[Geoff Brown [:gbrown]]

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

Comment 7

[Geoff Brown [:gbrown]]

: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"'.

Comment 8

[Daisuke Akatsuka (:daisuke)]

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

Comment 9

[Geoff Brown [:gbrown]]

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.

Comment 10

[Geoff Brown [:gbrown]]

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?

Comment 11

[Kyle Lahnakoski [:ekyle]]

I suggest disabling this suite first. Then we can go into detail about how to fix this.

Comment 12

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

Attachment: jsdcov devtools only run on try

Comment 13

[Greg Mierzwinski [:sparky]]

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.

Comment 14

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

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']

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2c914b6e6668
Linux jsdcov devtools tests timing out. r=gmierz

Comment 16

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/2c914b6e6668