1443747 - StdOut is spammed with 'C:\fakepath' when Webrender is enabled

Status: RESOLVED FIXED

(Core :: Graphics: WebRender, defect, P2)

Description

[niels.breuker]

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:60.0) Gecko/20100101 Firefox/60.0
Build ID: 20180302190033

Steps to reproduce:

Open Firefox with WebRender enabled and capture stdout. (For example firefox.exe -P webrender --no-remote > "SomePath.txt"


Actual results:

Stdout is spammed with messages like these:

WARN: rx::HLSLCompiler::compileToBinary(228):
C:\fakepath(721,32-48): warning X3556: integer divides may be much slower, try using uints if possible.
C:\fakepath(722,25-41): warning X3556: integer modulus may be much slower, try using uints if possible.
C:\fakepath(660,29-40): warning X3556: integer modulus may be much slower, try using uints if possible.
C:\fakepath(660,46-57): warning X3556: integer divides may be much slower, try using uints if possible.
C:\fakepath(680,29-40): warning X3556: integer modulus may be much slower, try using uints if possible.
C:\fakepath(680,46-57): warning X3556: integer divides may be much slower, try using uints if possible.
C:\fakepath(672,29-41): warning X3556: integer modulus may be much slower, try using uints if possible.
C:\fakepath(672,47-59): warning X3556: integer divides may be much slower, try using uints if possible.
C:\fakepath(633,20-34): warning X3556: integer modulus may be much slower, try using uints if possible.
C:\fakepath(633,39-53): warning X3556: integer divides may be much slower, try using uints if possible.


Expected results:

I expected stdout to not be spammed with those messages.

Comment 1

[Milan Sreckovic [:milan] (needinfo for best results)]

Where are these coming from?

Comment 2

[niels.breuker]

It didn't happen until perhaps a week ago.

Comment 3

[Jeff Muizelaar [:jrmuizel]]

I suspect this is from the ANGLE update.

Comment 4

[Jeff Muizelaar [:jrmuizel]]

Actually, I take that back. This could just be shader change in WebRender.

Comment 5

[Darkspirit]

Win10, Radeon RX480
mozregression --launch 2018-03-06 -B debug --pref gfx.webrender.all:true 
bad

mozregression --launch 2018-03-06 -B debug --pref gfx.webrender.all:true gfx.webrender.force-angle:false
not reproducible

last release without https://hg.mozilla.org/mozilla-central/rev/6f54af02c2e6
mozregression --repo autoland --launch 2667f0b010c9 -B debug --pref gfx.webrender.all:true
good

[between them: white/blank webrender with angle]

first release with https://hg.mozilla.org/mozilla-central/rev/02bf3c12111c
mozregression --repo autoland --launch 02bf3c12111c -B debug --pref gfx.webrender.all:true
bad

Possible regression range: https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=6f54af02c2e6&tochange=02bf3c12111c

Comment 6

[Darkspirit]

Correction:
Possible regression range: https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=2667f0b010c9&tochange=02bf3c12111c

Comment 7

[Dzmitry Malyshau [:kvark]]

Milan, these come from our WR shaders doing integer division. Fairly easy to address.

Comment 8

[Jeff Muizelaar [:jrmuizel]]

Here's a pull request doing that https://github.com/servo/webrender/pull/2496

Comment 9

[Darkspirit]

Not fixed.

Win10, Radeon RX480
mozregression --find-fix --bad 2018-03-09 --good 2018-03-19 -B debug --pref gfx.webrender.all:true
[...]
> 0:32.55 INFO: Downloading build from: https://queue.taskcluster.net/v1/task/AFjqtrNIS8e9S2xZFN-e6A/runs/0/artifacts/public%2Fbuild%2Ftarget.zip
> ===== Downloaded 100% =====
> 0:51.61 INFO: Running mozilla-inbound build built on 2018-03-19 19:51:52.322000, revision e2812f29
> 0:57.84 INFO: Launching c:\Users\Darkspirit\AppData\Local\Temp\tmpy0yrsw\firefox\firefox.exe
> 0:57.84 INFO: Application command: c:\Users\Darkspirit\AppData\Local\Temp\tmpy0yrsw\firefox\firefox.exe -profile c:\users\darksp~1\appdata\local\temp\tmp7ar9fc.mozrunner
> 0:58.08 INFO: application_buildid: 20180319185440
> 0:58.08 INFO: application_changeset: e2812f291edf88e167bdd0baf59586c007749981
> 0:58.08 INFO: application_name: Firefox
> 0:58.08 INFO: application_repository: https://hg.mozilla.org/integration/mozilla-inbound
> 0:58.08 INFO: application_version: 61.0a1
[...]
> 1:03.88 INFO: WARN: rx::HLSLCompiler::compileToBinary(228):
> 1:03.88 INFO: C:\fakepath(2425,32-48): warning X3556: integer divides may be much slower, try using uints if possible.
> 1:03.88 INFO: C:\fakepath(2426,25-41): warning X3556: integer modulus may be much slower, try using uints if possible.
> 1:03.88 INFO: C:\fakepath(2335,20-34): warning X3556: integer modulus may be much slower, try using uints if possible.
> 1:03.88 INFO: C:\fakepath(2335,39-53): warning X3556: integer divides may be much slower, try using uints if possible.
> 1:03.88 INFO:
> 1:04.25 INFO: WARN: rx::HLSLCompiler::compileToBinary(228):
> 1:04.25 INFO: C:\fakepath(2205,32-48): warning X3556: integer divides may be much slower, try using uints if possible.
> 1:04.25 INFO: C:\fakepath(2206,25-41): warning X3556: integer modulus may be much slower, try using uints if possible.
> 1:04.25 INFO: C:\fakepath(2115,20-34): warning X3556: integer modulus may be much slower, try using uints if possible.
> 1:04.25 INFO: C:\fakepath(2115,39-53): warning X3556: integer divides may be much slower, try using uints if possible.

Comment 10

[Dzmitry Malyshau [:kvark]]

Should be fixed by https://github.com/servo/webrender/pull/3014, although I can't confirm since my setup doesn't reproduce this.

Comment 11

[Darkspirit]

The quoted warning from comment 0 seems to be fixed. But another "fakepath" warning has come up in the meantime.

mozregression --launch 2018-09-03 -B debug --pref gfx.webrender.all:true
> 0:26.97 INFO: Initializing context 000002429F0A0000 surface 000002428D62DF40 on display 000002429CF061E0
> 0:26.97 INFO: [GPU 1492, Renderer] WARNING: Robustness supported, strategy is not LOSE_CONTEXT_ON_RESET!: file z:/build/build/src/gfx/gl/GLContext.cpp, line 1000
> 0:26.98 INFO: [GPU 1492, Renderer] WARNING: robustness marked as unsupported: file z:/build/build/src/gfx/gl/GLContextFeatures.cpp, line 915
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageCallback" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageCallbackARB" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageControl" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageControlARB" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageInsert" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageInsertARB" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glGetDebugMessageLog" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glGetDebugMessageLogARB" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glGetObjectLabel" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glGetObjectPtrLabel" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glObjectLabel" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glObjectPtrLabel" by glcontext
> 0:26.98 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glPopDebugGroup" by glcontext
> 0:26.99 INFO:  WARN 2018-09-05T00:55:03Z: webrender_bindings::bindings: Could not find symbol "glPushDebugGroup" by glcontext
> 0:26.99 INFO: [GPU 1492, Compositor] WARNING: Created child without a matching parent?: file z:/build/build/src/gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp, line 104
> 0:26.99 INFO: [Child 9328, Main Thread] WARNING: failed to allocate layer transaction: file z:/build/build/src/dom/ipc/TabChild.cpp, line 2904
> 0:26.99 INFO: [Child 9328, Main Thread] WARNING: failed to recreate layer manager: file z:/build/build/src/dom/ipc/TabChild.cpp, line 3240
> 0:26.99 INFO: [GFX1-]: IPC Channel is already torn down unexpectedly
> 0:26.99 INFO:
> 0:26.99 INFO: [Parent 10052, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file z:/build/build/src/parser/html/nsHtml5StreamParser.cpp, line 1015
> 0:26.99 INFO: ++DOCSHELL 000002A385D44800 == 1 [pid = 7480] [id = {0ab6b413-9228-49ac-9fbf-6b45263ddd2a}]
> 0:26.99 INFO: ++DOMWINDOW == 1 (000002A385D13800) [pid = 7480] [serial = 1] [outer = 0000000000000000]
> 0:26.99 INFO: [GPU 1492, Compositor] WARNING: Created child without a matching parent? root 0: file z:/build/build/src/gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp, line 235
> 0:26.99 INFO: ++DOMWINDOW == 2 (000002A38B5A2C00) [pid = 7480] [serial = 2] [outer = 000002A385D13800]
> 0:27.18 INFO: WARN: compileToBinary(228):
> 0:27.18 INFO: C:\fakepath(847,1-6): warning X4000: use of potentially uninitialized variable (f_evaluate_color_for_style_in_corner_float4_float4_float4)
> 0:27.18 INFO: C:\fakepath(760,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec4_float4)
> 0:27.18 INFO: C:\fakepath(738,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec2)
> 0:27.18 INFO: C:\fakepath(760,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec4_float4)
> 0:27.18 INFO: C:\fakepath(738,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec2)
> 0:27.18 INFO: C:\fakepath(877,1-6): warning X4000: use of potentially uninitialized variable (f_evaluate_color_for_style_in_edge_float4_float4)
> 0:27.18 INFO: C:\fakepath(760,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec4_float4)
> 0:27.18 INFO: C:\fakepath(738,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec2)
> 0:27.18 INFO: C:\fakepath(760,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec4_float4)
> 0:27.18 INFO: C:\fakepath(738,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec2)
> 0:27.18 INFO: C:\fakepath(877,1-6): warning X4000: use of potentially uninitialized variable (f_evaluate_color_for_style_in_edge_float4_float4)
> 0:27.18 INFO:
> 0:27.35 INFO: WARN: compileToBinary(228):
> 0:27.35 INFO: C:\fakepath(1695,20-34): warning X3556: integer modulus may be much slower, try using uints if possible.
> 0:27.35 INFO: C:\fakepath(1695,39-53): warning X3556: integer divides may be much slower, try using uints if possible.
> 0:27.35 INFO:
> 0:27.49 INFO: WARN: compileToBinary(228):
> 0:27.49 INFO: C:\fakepath(1835,20-34): warning X3556: integer modulus may be much slower, try using uints if possible.
> 0:27.49 INFO: C:\fakepath(1835,39-53): warning X3556: integer divides may be much slower, try using uints if possible.
> 0:27.49 INFO:
> 0:27.57 INFO: WARN: compileToBinary(228):
> 0:27.57 INFO: C:\fakepath(1869,20-34): warning X3556: integer modulus may be much slower, try using uints if possible.
> 0:27.57 INFO: C:\fakepath(1869,39-53): warning X3556: integer divides may be much slower, try using uints if possible.
> 0:27.57 INFO: C:\fakepath(1964,55-70): warning X3556: integer divides may be much slower, try using uints if possible.
> 0:27.57 INFO: C:\fakepath(1966,58-73): warning X3556: integer modulus may be much slower, try using uints if possible.
> 0:27.57 INFO:
> 0:27.79 INFO: [Parent 10052, LoadRoots] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3460
> 0:27.79 INFO: [Parent 10052, LoadRoots] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3460
> 0:27.79 INFO: [Parent 10052, LoadRoots] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3460


mozregression --repo try --launch b91f07ab2d18bc453b9bf8ced90ea8bd5492bffd -B debug --pref gfx.webrender.all:true
> 0:31.14 INFO: Initializing context 000001CBAE3CB000 surface 000001CBAAA39B80 on display 000001CBAAA09050
> 0:31.16 INFO: [GPU 7796, Renderer] WARNING: Robustness supported, strategy is not LOSE_CONTEXT_ON_RESET!: file z:/build/build/src/gfx/gl/GLContext.cpp, line 1000
> 0:31.16 INFO: [GPU 7796, Renderer] WARNING: robustness marked as unsupported: file z:/build/build/src/gfx/gl/GLContextFeatures.cpp, line 915
> 0:31.16 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageCallback" by glcontext
> 0:31.17 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageCallbackARB" by glcontext
> 0:31.17 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageControl" by glcontext
> 0:31.17 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageControlARB" by glcontext
> 0:31.17 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageInsert" by glcontext
> 0:31.17 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glDebugMessageInsertARB" by glcontext
> 0:31.18 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glGetDebugMessageLog" by glcontext
> 0:31.18 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glGetDebugMessageLogARB" by glcontext
> 0:31.18 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glGetObjectLabel" by glcontext
> 0:31.18 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glGetObjectPtrLabel" by glcontext
> 0:31.18 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glObjectLabel" by glcontext
> 0:31.18 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glObjectPtrLabel" by glcontext
> 0:31.18 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glPopDebugGroup" by glcontext
> 0:31.18 INFO:  WARN 2018-09-05T00:50:41Z: webrender_bindings::bindings: Could not find symbol "glPushDebugGroup" by glcontext
> 0:31.18 INFO: [GPU 7796, MediaPDecoder #1] WARNING: NS_ENSURE_TRUE(SUCCEEDED(hr)) failed: file z:/build/build/src/dom/media/platforms/wmf/WMFUtils.cpp, line 74
> 0:31.21 INFO: [Child 3952, Main Thread] WARNING: No CID found when attempting to map contract ID: file z:/build/build/src/xpcom/components/nsComponentManager.cpp, line 626
> 0:31.26 INFO: ++DOMWINDOW == 17 (000001405883A000) [pid = 9256] [serial = 17] [outer = 00000140565A5000]
> 0:31.39 INFO: ++DOCSHELL 00000285EA044800 == 1 [pid = 3952] [id = {6225f09d-7952-4f74-a450-cc73c0935527}]
> 0:31.39 INFO: ++DOMWINDOW == 1 (00000285EA013800) [pid = 3952] [serial = 1] [outer = 0000000000000000]
> 0:31.42 INFO: ++DOMWINDOW == 2 (00000285EF8A5C00) [pid = 3952] [serial = 2] [outer = 00000285EA013800]
> 0:31.44 INFO: [GPU 7796, Compositor] WARNING: Possibly dropping task posted to updater thread: file z:/build/build/src/gfx/layers/apz/src/APZUpdater.cpp, line 416
> 0:31.44 INFO: ++DOMWINDOW == 3 (00000285FBC99400) [pid = 3952] [serial = 3] [outer = 00000285EA013800]
> 0:31.59 INFO: [Parent 9256, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file z:/build/build/src/parser/html/nsHtml5StreamParser.cpp, line 1015
> 0:31.62 INFO: ++DOMWINDOW == 4 (00000285FBCA1800) [pid = 3952] [serial = 4] [outer = 00000285EA013800]
> 0:31.89 INFO: WARN: compileToBinary(228):
> 0:31.89 INFO: C:\fakepath(847,1-6): warning X4000: use of potentially uninitialized variable (f_evaluate_color_for_style_in_corner_float4_float4_float4)
> 0:31.89 INFO: C:\fakepath(760,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec4_float4)
> 0:31.89 INFO: C:\fakepath(738,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec2)
> 0:31.89 INFO: C:\fakepath(760,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec4_float4)
> 0:31.89 INFO: C:\fakepath(738,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec2)
> 0:31.89 INFO: C:\fakepath(877,1-6): warning X4000: use of potentially uninitialized variable (f_evaluate_color_for_style_in_edge_float4_float4)
> 0:31.89 INFO: C:\fakepath(760,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec4_float4)
> 0:31.89 INFO: C:\fakepath(738,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec2)
> 0:31.89 INFO: C:\fakepath(760,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec4_float4)
> 0:31.90 INFO: C:\fakepath(738,1-6): warning X4000: use of potentially uninitialized variable (dyn_index_vec2)
> 0:31.90 INFO: C:\fakepath(877,1-6): warning X4000: use of potentially uninitialized variable (f_evaluate_color_for_style_in_edge_float4_float4)
> 0:31.90 INFO:
> 0:33.17 INFO: [Parent 9256, LoadRoots] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3460
> 0:33.17 INFO: [Parent 9256, LoadRoots] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3460
> 0:33.17 INFO: [Parent 9256, LoadRoots] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3460

Comment 12

[Dzmitry Malyshau [:kvark]]

Thank you for checking this out so quickly!
One of the remaining errors is from "vEdgeReference[edge_axis] + vPartialWidths[edge_axis]," where `edge_axis` is not known to be less than 4. The other one from `evaluate_color_for_style_in_corner` is not clear.

Comment 13

[Dzmitry Malyshau [:kvark]]

Trying to repro this on a different windows machine, I suspect that the instructions are not as simple as

> Open Firefox with WebRender enabled and capture stdout. (For example firefox.exe -P webrender --no-remote > "SomePath.txt"

There must be some environment variable, build configuration, or a config flag that enables extra logging. The compile warnings are output by WR in "WARN" channel, which isn't (or at least shouldn't be) enabled by default.

Comment 14

[Dzmitry Malyshau [:kvark]]

An attempt to fix those new errors is made in https://github.com/servo/webrender/pull/3024 , which has a try push assigned.

Comment 15

[Darkspirit]

Attachment: 3024.txt

(In reply to Dzmitry Malyshau [:kvark] from comment #14)
Win10, GTX 1060 (driver 398.82)

I just ran the command, waited a bit and closed the window.
"use of potentially uninitialized variable" is gone,
but there are some (new?) "integer modulus may be much slower, try using uints if possible."

Comment 16

[niels.breuker]

Personally I use a tiny C# program to direct any output, including errors, to the console:


class Program {
	static Process s_process = new Process();
	static void Main(string[] args) {
		Console.CancelKeyPress += delegate {
			s_process.Kill();
		};

		s_process.StartInfo = new ProcessStartInfo {
			FileName = args[0],
			Arguments = String.Join(" ", args.Skip(1).Select(x => $"\"{x}\"")),
			RedirectStandardOutput = true,
			RedirectStandardError = true,
			UseShellExecute = false,
		};
		s_process.OutputDataReceived += (sender, arg) => Console.WriteLine(arg.Data);
		s_process.ErrorDataReceived += (sender, arg) => Console.WriteLine(arg.Data);
		s_process.Start();
		s_process.BeginOutputReadLine();
		s_process.BeginErrorReadLine();
		s_process.WaitForExit();
	}
}

Comment 17

[Dzmitry Malyshau [:kvark]]

niels, wouldn't you see the same by just running FF from the console?

Comment 18

[niels.breuker]

Not on Windows because the Firefox process doesn't attach to the console.

Comment 19

[Darkspirit]

---------------------------
Notepad
---------------------------
Cannot find "fakepath"
---------------------------
OK   
---------------------------