1543260 - Intermittent dom/canvas/crashtests/1349067.html | application timed out after 370 seconds with no output

Status: RESOLVED FIXED

(Core :: Graphics: Canvas2D, defect)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: cbrindusan [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=239195235&repo=autoland

https://queue.taskcluster.net/v1/task/MSB4GdX8Tue3I2l0XPo6bw/runs/0/artifacts/public/logs/live_backing.log

https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/MSB4GdX8Tue3I2l0XPo6bw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2019-04-09T21:52:31.497Z] 21:52:31 INFO - REFTEST TEST-START | http://10.0.2.2:8854/tests/dom/canvas/crashtests/1349067.html
[task 2019-04-09T21:52:31.501Z] 21:52:31 INFO - REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/dom/canvas/crashtests/1349067.html | 393 / 3710 (10%)
[task 2019-04-09T21:59:09.135Z] 21:59:09 INFO - wait for org.mozilla.geckoview.test complete; top activity=org.mozilla.geckoview.test
[task 2019-04-09T21:59:09.244Z] 21:59:09 INFO - org.mozilla.geckoview.test unexpectedly found running. Killing...
[task 2019-04-09T21:59:09.245Z] 21:59:09 INFO - REFTEST TEST-INFO | started process screentopng
[task 2019-04-09T21:59:11.131Z] 21:59:11 INFO - REFTEST TEST-INFO | screentopng: exit 0
[task 2019-04-09T21:59:25.797Z] 21:59:25 WARNING - TEST-UNEXPECTED-FAIL | http://10.0.2.2:8854/tests/dom/canvas/crashtests/1349067.html | application timed out after 370 seconds with no output

Comment 1

[Geoff Brown [:gbrown]]

Regressed by bug 1541955?

Comment 2

[Geoff Brown [:gbrown]]

(In reply to Treeherder Bug Filer from comment #0)

https://treeherder.mozilla.org/logviewer.html#?job_id=239195235&repo=autoland

https://taskcluster-artifacts.net/MSB4GdX8Tue3I2l0XPo6bw/0/public/test_info//logcat-emulator-5554.log

04-09 22:49:57.060  2424  2439 I Gecko   : REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/dom/canvas/crashtests/1349067.html | 393 / 3710 (10%)
04-09 22:49:57.060  2424  2439 I Gecko   : 
04-09 22:49:57.060  2424  2439 I Gecko   : {"action":"log","time":1554846597060,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"START http://10.0.2.2:8854/tests/dom/canvas/crashtests/1349067.html"}
04-09 22:49:57.270  2484  2499 D EGL_emulation: eglCreateContext: 0x75c39de7ce40: maj 3 min 0 rcv 3
04-09 22:49:57.280  2484  2499 D EGL_emulation: eglMakeCurrent: 0x75c39de7ce40: ver 3 0 (tinfo 0x75c385a4a720)
04-09 22:49:57.310  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008cdf
04-09 22:49:57.310  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008824
04-09 22:49:57.340  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
04-09 22:49:57.360  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
04-09 22:49:57.390  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
04-09 22:49:57.400  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
04-09 22:49:57.400  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
04-09 22:49:57.410  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x000088ff
04-09 22:49:57.410  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008cdf
04-09 22:49:57.410  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008824
04-09 22:49:57.410  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00009122
04-09 22:49:57.420  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00009125
04-09 22:49:57.440  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008904
04-09 22:49:57.440  2484  2499 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008905
04-09 22:49:57.480  2484  2499 E Web Content: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://10.0.2.2:8854/tests/dom/canvas/crashtests/1349067.html" line: 0}]
04-09 22:49:57.510  2424  2439 I Gecko   : 
04-09 22:49:57.510  2424  2439 I Gecko   : {"action":"log","time":1554846597510,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] OnDocumentLoad triggering AfterOnLoadScripts"}
04-09 22:49:57.530  2424  2439 I Gecko   : 
04-09 22:49:57.530  2424  2439 I Gecko   : {"action":"log","time":1554846597530,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"Initializing canvas snapshot"}
04-09 22:49:57.530  2484  2499 W Web Content: [JavaScript Warning: "Use of Mutation Events is deprecated. Use MutationObserver instead." {file: "resource://reftest/reftest-content.js" line: 785}]
04-09 22:49:57.530  2424  2439 I Gecko   : 
04-09 22:49:57.530  2424  2439 I Gecko   : {"action":"log","time":1554846597530,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd"}
04-09 22:49:57.530  2424  2439 I Gecko   : 
04-09 22:49:57.530  2424  2439 I Gecko   : {"action":"log","time":1554846597530,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] WaitForTestEnd: Adding listeners"}
04-09 22:49:57.540  2424  2439 I Gecko   : 
04-09 22:49:57.540  2424  2439 I Gecko   : {"action":"log","time":1554846597530,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"Initializing canvas snapshot"}
04-09 22:49:57.550  2424  2439 I Gecko   : 
04-09 22:49:57.550  2424  2439 I Gecko   : {"action":"log","time":1554846597550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT"}
04-09 22:49:57.550  2424  2439 I Gecko   : 
04-09 22:49:57.550  2424  2439 I Gecko   : {"action":"log","time":1554846597550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: dispatching MozReftestInvalidate"}
04-09 22:49:57.550  2424  2439 I Gecko   : 
04-09 22:49:57.550  2424  2439 I Gecko   : {"action":"log","time":1554846597550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL"}
04-09 22:49:57.550  2424  2439 I Gecko   : 
04-09 22:49:57.550  2424  2439 I Gecko   : {"action":"log","time":1554846597550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: STATE_WAITING_FOR_SPELL_CHECKS"}
04-09 22:49:57.550  2424  2439 I Gecko   : 
04-09 22:49:57.550  2424  2439 I Gecko   : {"action":"log","time":1554846597550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH"}
04-09 22:49:57.550  2424  2439 I Gecko   : 
04-09 22:49:57.550  2424  2439 I Gecko   : {"action":"log","time":1554846597550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: APZ flush not required"}
04-09 22:49:57.550  2424  2439 I Gecko   : 
04-09 22:49:57.550  2424  2439 I Gecko   : {"action":"log","time":1554846597550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: STATE_WAITING_TO_FINISH"}
04-09 22:49:57.560  2484  2499 E EGL_emulation: eglQueryContext 32c0  EGL_BAD_ATTRIBUTE
04-09 22:49:57.560  2484  2499 E EGL_emulation: tid 2499: eglQueryContext(1716): error 0x3004 (EGL_BAD_ATTRIBUTE)
04-09 22:49:57.560  2484  2499 E EGL_emulation: eglQueryContext 32c0  EGL_BAD_ATTRIBUTE
04-09 22:49:57.560  2484  2499 E EGL_emulation: tid 2499: eglQueryContext(1716): error 0x3004 (EGL_BAD_ATTRIBUTE)
04-09 22:49:57.580  2424  2439 I Gecko   : 
04-09 22:49:57.580  2424  2439 I Gecko   : {"action":"log","time":1554846597580,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: Doing sync flush to compositor"}
04-09 22:49:57.580  2424  2439 I Gecko   : 
04-09 22:49:57.580  2424  2439 I Gecko   : {"action":"log","time":1554846597580,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: Completed"}
04-09 22:49:57.580  2424  2566 D         : HostConnection::get() New Host Connection established 0x75c386b28e00, tid 2566
04-09 22:49:57.590  2424  2566 D EGL_emulation: eglCreateContext: 0x75c37b7f2e80: maj 3 min 0 rcv 3
04-09 22:49:57.610  2424  2566 D EGL_emulation: eglMakeCurrent: 0x75c37b7f2e80: ver 3 0 (tinfo 0x75c373c93a20)
04-09 22:49:57.610  2424  2566 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008cdf
04-09 22:49:57.610  2424  2566 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008824
04-09 22:49:57.640  2484  2499 D EGL_emulation: eglMakeCurrent: 0x75c39de7ce40: ver 3 0 (tinfo 0x75c385a4a720)
04-09 22:49:57.650  2484  2499 E EGL_emulation: eglQueryContext 32c0  EGL_BAD_ATTRIBUTE
04-09 22:49:57.650  2484  2499 E EGL_emulation: tid 2499: eglQueryContext(1716): error 0x3004 (EGL_BAD_ATTRIBUTE)
04-09 22:49:57.650  2484  2499 E EGL_emulation: eglQueryContext 32c0  EGL_BAD_ATTRIBUTE
04-09 22:49:57.650  2484  2499 E EGL_emulation: tid 2499: eglQueryContext(1716): error 0x3004 (EGL_BAD_ATTRIBUTE)
04-09 22:49:57.650  2424  2436 D         : HostConnection::get() New Host Connection established 0x75c373cd6b00, tid 2436
04-09 22:49:57.660  2484  2499 D EGL_emulation: eglMakeCurrent: 0x75c39de7ce40: ver 3 0 (tinfo 0x75c385a4a720)
04-09 22:49:57.660  2484  2499 D EGL_emulation: eglMakeCurrent: 0x75c39de7ce40: ver 3 0 (tinfo 0x75c385a4a720)
04-09 22:49:57.670  2484  2499 D EGL_emulation: eglMakeCurrent: 0x75c39de7ce40: ver 3 0 (tinfo 0x75c385a4a720)
04-09 22:55:31.960  2424  2430 I art     : Thread[3,tid=2430,WaitingInMainSignalCatcherLoop,Thread*=0x75c394994400,peer=0x12c33d30,"Signal Catcher"]: reacting to signal 3

Comment 3

[Geoff Brown [:gbrown]]

:kats - This looks like it will become a frequent intermittent; I think it started with the emulator update in bug 1541955. Any interest?

Comment 4

[Kartikaya Gupta (email:[e-mail])]

In the short term it's probably ok to back out the patch; I can work with it applied locally. It would be useful to know if it's the emulator upgrade or the ES3 bump that caused the problem. If it's the ES3 bump maybe we can make that conditional on WR being enabled. Offhand though I'm not sure why it would cause this problem; I can look at the logs more closely tomorrow.

Comment 5

[Intermittent Failures Robot]

18 failures in 580 pushes (0.031 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 18

Platform breakdown:

• android-em-7-0-x86_64: 18

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1543260&startday=2019-04-09&endday=2019-04-09&tree=all

Comment 6

[Kartikaya Gupta (email:[e-mail])]

So the the various "glUtilsParamSize: unknow param" errors come from this file in the android tree. The unknown parameter values in the errors correspond to the following constants:

0x00008cdf -> GL_MAX_COLOR_ATTACHMENTS
0x00008824 -> GL_MAX_DRAW_BUFFERS
0x00008caa -> GL_READ_FRAMEBUFFER_BINDING
0x000088ff -> GL_MAX_ARRAY_TEXTURE_LAYERS
0x00009122 -> GL_MAX_VERTEX_OUTPUT_COMPONENTS
0x00009125 -> GL_MAX_FRAGMENT_INPUT_COMPONENTS
0x00008904 -> GL_MIN_PROGRAM_TEXEL_OFFSET
0x00008905 -> GL_MAX_PROGRAM_TEXEL_OFFSET

Three of these constants (GL_MAX_COLOR_ATTACHMENTS, GL_MAX_DRAW_BUFFERS, and GL_MAX_ARRAY_TEXTURE_LAYERS) are present in the switch statement in glUtilsParamSize and were added in commit ba063e79becd21e6a647c0036674c9 which looks like it wasn't in android 7 but made it into android 8. The other constants are not in that switch statement even in android 9. So I guess that matches what we're seeing here since we are running Android 7 in the emulator.

What appears to be happening is that the emulator has a buggy GL ES 3 implementation in that they don't handle these constants properly. Our WebGL tests detect that we're running GL ES 3 and try to use them, resulting in badness. Fixing this properly means writing a patch to the android emulator and waiting for it to get into a release (and I don't know how long that will take) unless we do local emulator builds that we can patch directly.

Disabling ES3 for the non-WR runs will solve the problem in the short term; when we try and run WebGL tests on Android 7 + WR we'll run into this again, but maybe we can just disable the webgl test in question for that configuration until we have a fixed emulator.

/cc jgilbert also in case he has thoughts on this.

Comment 7

[Kartikaya Gupta (email:[e-mail])]

Let's see if this helps: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=d6657526de54880fa01fd6b7591798fc15dd68ad

Comment 8

[Geoff Brown [:gbrown]]

(In reply to Kartikaya Gupta (email:[e-mail]) from comment #6)

... unless we do local emulator builds that we can patch directly.

We tried that for a while, but now we only use pre-built binaries from the android sdk.

Switching the Android 7.0 test environment to Android 8 or 9 might not be a lot of work (for a long-term fix).

Comment 9

[Kartikaya Gupta (email:[e-mail])]

Attachment: Bug 1543260 - Make GLES3 in the android emulator conditional on WR. r?gbrown

This disables GLES3 in the android emulator unless WebRender is
explicitly enabled, because for now the half-baked ES3 support in the
emulator causes some WebGL tests to fail.

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9b7b997246cb
Make GLES3 in the android emulator conditional on WR. r=gbrown

Comment 11

[Daniel Varga [:dvarga]]

https://hg.mozilla.org/mozilla-central/rev/9b7b997246cb

Comment 12

[Cristina Coroiu [:ccoroiu]]

Retriggers:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=android%2C7.0%2Cx86-64%2Copt%2Creftests%2Cwith%2Ce10s%2Ctest-android-em-7.0-x86_64%2Fopt-crashtest-e10s%2Cr-e10s%28c%29&tochange=82054c3d9cadbb02f7cb3e4aa69ea3bd608bf003&fromchange=4bb96b9e1a3241c400b6fcdcd6ebf7e97fc5fcb9&selectedJob=239550643

Comment 13

[Intermittent Failures Robot]

88 failures in 509 pushes (0.173 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 70
• mozilla-central: 7
• try: 2
• mozilla-inbound: 9

Platform breakdown:

• android-em-7-0-x86_64: 88

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1543260&startday=2019-04-10&endday=2019-04-10&tree=all

Comment 14

[Intermittent Failures Robot]

107 failures in 3025 pushes (0.035 failures/push) were associated with this bug in the last 7 days.

This is the #8 most frequent failure this week.

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

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

Repository breakdown:

• autoland: 88
• mozilla-central: 7
• try: 2
• mozilla-inbound: 10

Platform breakdown:

• android-em-7-0-x86_64: 107

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1543260&startday=2019-04-08&endday=2019-04-14&tree=all