1516314 - Intermittent webgl-resize-test.html == wrapper.html?green.png load failed: timed out waiting for pending paint count to reach zero (after reftest-wait removed and switch to print mode) (waiting for MozAfterPaint)

Status: RESOLVED INCOMPLETE

(Core :: Graphics: CanvasWebGL, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com

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

https://queue.taskcluster.net/v1/task/AXTMeevfTdaiF42JZ40NEQ/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/AXTMeevfTdaiF42JZ40NEQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2018-12-20T14:55:01.964Z] 14:55:01     INFO - REFTEST TEST-START | file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-resize-test.html == file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/wrapper.html?green.png
[task 2018-12-20T14:55:01.965Z] 14:55:01     INFO - REFTEST INFO | RESTORE PREFERENCE pref(media.useAudioChannelAPI,false)
[task 2018-12-20T14:55:01.969Z] 14:55:01     INFO - REFTEST INFO | RESTORE PREFERENCE pref(webgl.force-enabled,false)
[task 2018-12-20T14:55:01.970Z] 14:55:01     INFO - REFTEST INFO | SET PREFERENCE pref(webgl.force-enabled,true)
[task 2018-12-20T14:55:01.973Z] 14:55:01     INFO - REFTEST INFO | SET PREFERENCE pref(media.useAudioChannelAPI,true)
[task 2018-12-20T14:55:01.974Z] 14:55:01     INFO - REFTEST TEST-LOAD | file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-resize-test.html | 7 / 106 (6%)
[task 2018-12-20T14:55:01.999Z] 14:55:01     INFO - ++DOMWINDOW == 24 (0x7f53452c2800) [pid = 7538] [serial = 25] [outer = 0x7f5367c56600]
[task 2018-12-20T14:55:02.030Z] 14:55:02     INFO - [Child 7538, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/dom/base/nsContentUtils.cpp, line 4020
[task 2018-12-20T14:55:02.107Z] 14:55:02     INFO - [Child 7538, Main Thread] WARNING: robust_buffer_access_behavior marked as unsupported: file /builds/worker/workspace/build/src/gfx/gl/GLContextFeatures.cpp, line 937
[task 2018-12-20T14:55:02.107Z] 14:55:02     INFO - [Child 7538, Main Thread] WARNING: Robustness supported, strategy is not LOSE_CONTEXT_ON_RESET!: file /builds/worker/workspace/build/src/gfx/gl/GLContext.cpp, line 1029
[task 2018-12-20T14:55:02.110Z] 14:55:02     INFO - [Child 7538, Main Thread] WARNING: robustness marked as unsupported: file /builds/worker/workspace/build/src/gfx/gl/GLContextFeatures.cpp, line 937
[task 2018-12-20T14:55:03.075Z] 14:55:03     INFO - --DOCSHELL 0x7fc220f0e800 == 8 [pid = 7387] [id = {b184b660-f8c4-4407-bc74-5fce3f7d9bc4}]
[task 2018-12-20T14:55:03.076Z] 14:55:03     INFO - --DOCSHELL 0x7fc2224dd000 == 7 [pid = 7387] [id = {1d8ce0f9-b78b-4bb2-a297-0a0dfae67b02}]
[task 2018-12-20T14:55:03.077Z] 14:55:03     INFO - --DOCSHELL 0x7fc21eb96800 == 6 [pid = 7387] [id = {63cfc96d-0fcb-43da-8bc8-44bec0111f23}]
[task 2018-12-20T14:55:03.078Z] 14:55:03     INFO - --DOMWINDOW == 21 (0x7fc221716c00) [pid = 7387] [serial = 6] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:03.079Z] 14:55:03     INFO - --DOMWINDOW == 20 (0x7fc21e810200) [pid = 7387] [serial = 16] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:03.465Z] 14:55:03     INFO - --DOMWINDOW == 8 (0x7f02a7d13800) [pid = 7470] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:03.467Z] 14:55:03     INFO - --DOMWINDOW == 7 (0x7f02a85a7400) [pid = 7470] [serial = 6] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:03.467Z] 14:55:03     INFO - --DOMWINDOW == 6 (0x7f02a85a6400) [pid = 7470] [serial = 4] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:06.559Z] 14:55:06     INFO - --DOMWINDOW == 19 (0x7fc22f253000) [pid = 7387] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:06.559Z] 14:55:06     INFO - --DOMWINDOW == 18 (0x7fc2217da800) [pid = 7387] [serial = 8] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:06.560Z] 14:55:06     INFO - --DOMWINDOW == 17 (0x7fc2217db800) [pid = 7387] [serial = 10] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:06.561Z] 14:55:06     INFO - --DOMWINDOW == 16 (0x7fc220b50400) [pid = 7387] [serial = 12] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:06.562Z] 14:55:06     INFO - --DOMWINDOW == 15 (0x7fc21e83a800) [pid = 7387] [serial = 17] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:06.563Z] 14:55:06     INFO - --DOMWINDOW == 14 (0x7fc21e83ec00) [pid = 7387] [serial = 18] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:09.014Z] 14:55:09     INFO - --DOMWINDOW == 23 (0x7f5346366000) [pid = 7538] [serial = 16] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-clear-test.html?depth]
[task 2018-12-20T14:55:09.015Z] 14:55:09     INFO - --DOMWINDOW == 22 (0x7f5351b61800) [pid = 7538] [serial = 4] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-disable-test.html?nogl]
[task 2018-12-20T14:55:09.016Z] 14:55:09     INFO - --DOMWINDOW == 21 (0x7f5346364000) [pid = 7538] [serial = 15] [outer = (nil)] [url = data:text/html;charset=UTF-8,%3C%21%2D%2DCLEAR%2D%2D%3E]
[task 2018-12-20T14:55:09.017Z] 14:55:09     INFO - --DOMWINDOW == 20 (0x7f5351b60400) [pid = 7538] [serial = 5] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/wrapper.html?green.png]
[task 2018-12-20T14:55:09.018Z] 14:55:09     INFO - --DOMWINDOW == 19 (0x7f5346365c00) [pid = 7538] [serial = 17] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/wrapper.html?green.png]
[task 2018-12-20T14:55:09.019Z] 14:55:09     INFO - --DOMWINDOW == 18 (0x7f5346362800) [pid = 7538] [serial = 14] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/wrapper.html?green.png]
[task 2018-12-20T14:55:09.019Z] 14:55:09     INFO - --DOMWINDOW == 17 (0x7f53514a5800) [pid = 7538] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2018-12-20T14:55:09.020Z] 14:55:09     INFO - --DOMWINDOW == 16 (0x7f5347483000) [pid = 7538] [serial = 13] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-clear-test.html?readback]
[task 2018-12-20T14:55:09.021Z] 14:55:09     INFO - --DOMWINDOW == 15 (0x7f5351b60c00) [pid = 7538] [serial = 6] [outer = (nil)] [url = data:text/html;charset=UTF-8,%3C%21%2D%2DCLEAR%2D%2D%3E]
[task 2018-12-20T14:55:09.021Z] 14:55:09     INFO - --DOMWINDOW == 14 (0x7f5347485400) [pid = 7538] [serial = 12] [outer = (nil)] [url = data:text/html;charset=UTF-8,%3C%21%2D%2DCLEAR%2D%2D%3E]
[task 2018-12-20T14:55:09.022Z] 14:55:09     INFO - --DOMWINDOW == 13 (0x7f5347481000) [pid = 7538] [serial = 11] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/wrapper.html?green.png]
[task 2018-12-20T14:55:09.023Z] 14:55:09     INFO - --DOMWINDOW == 12 (0x7f5351b63000) [pid = 7538] [serial = 7] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-disable-test.html]
[task 2018-12-20T14:55:09.023Z] 14:55:09     INFO - --DOMWINDOW == 11 (0x7f5351b5f800) [pid = 7538] [serial = 8] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/wrapper.html?green.png]
[task 2018-12-20T14:55:09.024Z] 14:55:09     INFO - --DOMWINDOW == 10 (0x7f53508d9000) [pid = 7538] [serial = 10] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-clear-test.html]
[task 2018-12-20T14:55:09.025Z] 14:55:09     INFO - --DOMWINDOW == 9 (0x7f53508db000) [pid = 7538] [serial = 9] [outer = (nil)] [url = data:text/html;charset=UTF-8,%3C%21%2D%2DCLEAR%2D%2D%3E]
[task 2018-12-20T14:55:13.766Z] 14:55:13     INFO - [Parent 7387, StreamTrans #34] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 419
[task 2018-12-20T14:55:13.767Z] 14:55:13     INFO - [Parent 7387, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 1127
[task 2018-12-20T14:55:15.479Z] 14:55:15     INFO - --DOMWINDOW == 8 (0x7f5345f3bc00) [pid = 7538] [serial = 21] [outer = (nil)] [url = data:text/html;charset=UTF-8,%3C%21%2D%2DCLEAR%2D%2D%3E]
[task 2018-12-20T14:55:15.480Z] 14:55:15     INFO - --DOMWINDOW == 7 (0x7f5345f44c00) [pid = 7538] [serial = 20] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/wrapper.html?green.png]
[task 2018-12-20T14:55:15.480Z] 14:55:15     INFO - --DOMWINDOW == 6 (0x7f5346370000) [pid = 7538] [serial = 19] [outer = (nil)] [url = file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-clear-test.html?stencil]
[task 2018-12-20T14:55:15.481Z] 14:55:15     INFO - --DOMWINDOW == 5 (0x7f5346368400) [pid = 7538] [serial = 18] [outer = (nil)] [url = data:text/html;charset=UTF-8,%3C%21%2D%2DCLEAR%2D%2D%3E]
[task 2018-12-20T14:57:53.877Z] 14:57:53     INFO - [Parent 7387, Main Thread] WARNING: Suboptimal indexes for the SQL statement 0x7fc216155250 (http://mzl.la/1FuID0j).: file /builds/worker/workspace/build/src/storage/mozStoragePrivateHelpers.cpp, line 114
[task 2018-12-20T15:00:01.985Z] 15:00:01     INFO - REFTEST TEST-UNEXPECTED-FAIL | file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-resize-test.html == file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/wrapper.html?green.png | load failed: timed out waiting for pending paint count to reach zero (after reftest-wait removed and switch to print mode) (waiting for MozAfterPaint)
[task 2018-12-20T15:00:01.990Z] 15:00:01     INFO - REFTEST INFO | Saved log: START file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-resize-test.html
[task 2018-12-20T15:00:02.000Z] 15:00:01     INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering WaitForTestEnd
[task 2018-12-20T15:00:02.003Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
[task 2018-12-20T15:00:02.005Z] 15:00:02     INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2018-12-20T15:00:02.007Z] 15:00:02     INFO - REFTEST INFO | Saved log: DoDrawWindow 0,0,800,1000
[task 2018-12-20T15:00:02.008Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT
[task 2018-12-20T15:00:02.009Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: waiting for MozAfterPaint
[task 2018-12-20T15:00:02.011Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] AttrModifiedListener fired
[task 2018-12-20T15:00:02.013Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] AttrModifiedListener fired
[task 2018-12-20T15:00:02.015Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-resize-test.html
[task 2018-12-20T15:00:02.017Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] SendUpdateCanvasForEvent with 1 rects
[task 2018-12-20T15:00:02.019Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] Rect: 0 0 800 1000
[task 2018-12-20T15:00:02.021Z] 15:00:02     INFO - REFTEST INFO | Saved log: Updating canvas for invalidation
[task 2018-12-20T15:00:02.023Z] 15:00:02     INFO - REFTEST INFO | Saved log: DoDrawWindow 0,0,800,1000
[task 2018-12-20T15:00:02.025Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] AttrModifiedListener fired
[task 2018-12-20T15:00:02.033Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT
[task 2018-12-20T15:00:02.036Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: waiting for MozAfterPaint
[task 2018-12-20T15:00:02.038Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT
[task 2018-12-20T15:00:02.040Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: waiting for MozAfterPaint
[task 2018-12-20T15:00:02.042Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-resize-test.html
[task 2018-12-20T15:00:02.044Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] Webrender enabled, sending update whole canvas for invalidation
[task 2018-12-20T15:00:02.046Z] 15:00:02     INFO - REFTEST INFO | Saved log: Updating entire canvas for invalidation
[task 2018-12-20T15:00:02.048Z] 15:00:02     INFO - REFTEST INFO | Saved log: DoDrawWindow 0,0,800,1000
[task 2018-12-20T15:00:02.050Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT
[task 2018-12-20T15:00:02.051Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: dispatching MozReftestInvalidate
[task 2018-12-20T15:00:02.053Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL
[task 2018-12-20T15:00:02.056Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_SPELL_CHECKS
[task 2018-12-20T15:00:02.058Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH
[task 2018-12-20T15:00:02.060Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: done requesting APZ flush
[task 2018-12-20T15:00:02.062Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH
[task 2018-12-20T15:00:02.064Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH
[task 2018-12-20T15:00:02.065Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-resize-test.html
[task 2018-12-20T15:00:02.066Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] Webrender enabled, sending update whole canvas for invalidation
[task 2018-12-20T15:00:02.067Z] 15:00:02     INFO - REFTEST INFO | Saved log: Updating entire canvas for invalidation
[task 2018-12-20T15:00:02.068Z] 15:00:02     INFO - REFTEST INFO | Saved log: DoDrawWindow 0,0,800,1000
[task 2018-12-20T15:00:02.070Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH
[task 2018-12-20T15:00:02.071Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: apz-repaints-flushed fired
[task 2018-12-20T15:00:02.072Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FINISH
[task 2018-12-20T15:00:02.073Z] 15:00:02     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: waiting for MozAfterPaint
[task 2018-12-20T15:00:02.074Z] 15:00:02     INFO - REFTEST TEST-END | file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/webgl-resize-test.html == file:///builds/worker/workspace/build/tests/reftest/tests/dom/canvas/test/reftest/wrapper.html?green.png

Comment 1

[Sotaro Ikeda [:sotaro]]

(In reply to Treeherder Bug Filer from comment #0)
> Filed by: apavel [at] mozilla.com
> 
> https://treeherder.mozilla.org/logviewer.html#?job_id=218129208&repo=mozilla-
> release

I checked the source. mozilla-release does not have a fix of Bug 1490117 yet.

https://hg.mozilla.org/releases/mozilla-release/file/a7882c0ccf94e9a0864868ea6d09417fe190a5a2/gfx/layers/wr/WebRenderBridgeParent.cpp

Comment 2

[Intermittent Failures Robot]

1 failures in 2627 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 1

Platform breakdown:

• linux64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1516314&startday=2019-01-07&endday=2019-01-13&tree=all

Comment 3

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup