KhronosGroup / Vulkan-ValidationLayers

Vulkan Validation Layers (VVL)
https://vulkan.lunarg.com/doc/sdk/latest/linux/khronos_validation_layer.html
Other
731 stars 397 forks source link

debug printfs from compute shaders seemingly not outputting to console #8103

Closed AlexRouSg closed 1 month ago

AlexRouSg commented 1 month ago

Environment:

Describe the Issue

I am trying to debug printf from a compute shader but no messages are showing up in the console, however prints from a vertex shader do show up. Also worth noting that renderdoc captures the compute printf and there is only one message so it should not be buffer size related which is set at 1048576.

I have even tried on a very simple compute shader with no other extensions.

Expected behavior

Printfs from compute shaders show up in the console.

spencer-lunarg commented 1 month ago

@AlexRouSg I can confirm locally that 1.3.280.1, 1.3.283 and ToT all work with compute with something like

#version 450
#extension GL_EXT_debug_printf : enable
void main() {
    float myfloat = 3.1415f;
    debugPrintfEXT("float == %f", myfloat);
}

Can you give me the SPIR-V that is not working, I'm curious if our implementation of Debug Printf is missing something

AlexRouSg commented 1 month ago

Workgroup size: 32x32x1 Workgroup count: 32x32x1

; SPIR-V
; Version: 1.6
; Generator: Google Shaderc over Glslang; 11
; Bound: 43
; Schema: 0
               OpCapability Shader
               OpExtension "SPV_KHR_non_semantic_info"
          %2 = OpExtInstImport "GLSL.std.450"
         %30 = OpExtInstImport "NonSemantic.DebugPrintf"
               OpMemoryModel Logical GLSL450
               OpEntryPoint GLCompute %main "main" %gl_GlobalInvocationID %_ %t
               OpExecutionModeId %main LocalSizeId %8 %9 %10
          %1 = OpString "water.comp"
         %29 = OpString "TEST"
               OpSource GLSL 450 %1 "#version 450
#pragma shader_stage(compute)
#extension GL_EXT_debug_printf : require

#define FREQ 0.25

layout(local_size_x_id = 0, local_size_y_id = 1, local_size_z_id = 2) in;

layout(push_constant) uniform constants {
    float deltaTime;
};

layout(binding = 0, r32f) uniform restrict image2D t;

void main() {
    if (gl_GlobalInvocationID.x == 0 && gl_GlobalInvocationID.y == 0) {
        debugPrintfEXT(\"TEST\");
    }
}
"
               OpSourceExtension "GL_EXT_debug_printf"
               OpSourceExtension "GL_GOOGLE_cpp_style_line_directive"
               OpSourceExtension "GL_GOOGLE_include_directive"
               OpName %main "main"
               OpName %gl_GlobalInvocationID "gl_GlobalInvocationID"
               OpName %constants "constants"
               OpMemberName %constants 0 "deltaTime"
               OpName %_ ""
               OpName %t "t"
               OpModuleProcessed "entry-point main"
               OpModuleProcessed "client vulkan100"
               OpModuleProcessed "target-env spirv1.6"
               OpModuleProcessed "target-env vulkan1.3"
               OpModuleProcessed "entry-point main"
               OpDecorate %8 SpecId 0
               OpDecorate %9 SpecId 1
               OpDecorate %10 SpecId 2
               OpDecorate %gl_GlobalInvocationID BuiltIn GlobalInvocationId
               OpDecorate %32 SpecId 0
               OpDecorate %33 SpecId 1
               OpDecorate %34 SpecId 2
               OpMemberDecorate %constants 0 Offset 0
               OpDecorate %constants Block
               OpDecorate %t DescriptorSet 0
               OpDecorate %t Binding 0
               OpDecorate %t Restrict
       %void = OpTypeVoid
          %4 = OpTypeFunction %void
       %uint = OpTypeInt 32 0
          %8 = OpSpecConstant %uint 1
          %9 = OpSpecConstant %uint 1
         %10 = OpSpecConstant %uint 1
       %bool = OpTypeBool
     %v3uint = OpTypeVector %uint 3
%_ptr_Input_v3uint = OpTypePointer Input %v3uint
%gl_GlobalInvocationID = OpVariable %_ptr_Input_v3uint Input
     %uint_0 = OpConstant %uint 0
%_ptr_Input_uint = OpTypePointer Input %uint
     %uint_1 = OpConstant %uint 1
         %32 = OpSpecConstant %uint 1
         %33 = OpSpecConstant %uint 1
         %34 = OpSpecConstant %uint 1
         %35 = OpSpecConstantComposite %v3uint %32 %33 %34
      %float = OpTypeFloat 32
  %constants = OpTypeStruct %float
%_ptr_PushConstant_constants = OpTypePointer PushConstant %constants
          %_ = OpVariable %_ptr_PushConstant_constants PushConstant
         %40 = OpTypeImage %float 2D 0 0 0 2 R32f
%_ptr_UniformConstant_40 = OpTypePointer UniformConstant %40
          %t = OpVariable %_ptr_UniformConstant_40 UniformConstant
               OpLine %1 15 11
       %main = OpFunction %void None %4
          %6 = OpLabel
               OpLine %1 16 0
         %17 = OpAccessChain %_ptr_Input_uint %gl_GlobalInvocationID %uint_0
         %18 = OpLoad %uint %17
         %19 = OpIEqual %bool %18 %uint_0
               OpSelectionMerge %21 None
               OpBranchConditional %19 %20 %21
         %20 = OpLabel
               OpLine %1 16 0
         %23 = OpAccessChain %_ptr_Input_uint %gl_GlobalInvocationID %uint_1
         %24 = OpLoad %uint %23
         %25 = OpIEqual %bool %24 %uint_0
               OpBranch %21
         %21 = OpLabel
         %26 = OpPhi %bool %19 %6 %25 %20
               OpSelectionMerge %28 None
               OpBranchConditional %26 %27 %28
         %27 = OpLabel
               OpLine %1 17 0
         %31 = OpExtInst %void %30 1 %29
               OpBranch %28
         %28 = OpLabel
               OpReturn
               OpFunctionEnd
spencer-lunarg commented 1 month ago

@AlexRouSg have you tried setting set VK_LAYER_PRINTF_TO_STDOUT=1 as it may be printing, but to the debug callback instead

I created a test here https://github.com/KhronosGroup/Vulkan-ValidationLayers/pull/8106 and it works as expected

spencer-lunarg commented 1 month ago

(I want it to run in CI to see if it fails on the NVIDIA windows machines we have)

AlexRouSg commented 1 month ago

(I want it to run in CI to see if it fails on the NVIDIA windows machines we have)

yup I have even tried vkconfig redirect output to file and nothing's showing up except the vertex shader everything's also compiled at runtime with exactly the same shader compiler and flags so I'm very confused lol

The only thing different between them is that the compute was done in a different command buffer and queue submit immediately before the graphics work

EDIT:

Just tried with everything in the same command buffer and with dispatch count of 1 and no change

AlexRouSg commented 1 month ago

not sure if this is helpful but vertex shader does also say this

pSubmits[0] Internal Error: Unable to locate information for shader used in command buffer: ... Unable to find suitable #line directive in SPIR-V OpSource.

spencer-lunarg commented 1 month ago

can you try just going

void main() {
    debugPrintfEXT("TEST");
}

and see if you are getting spammed

AlexRouSg commented 1 month ago

can you try just going

void main() {
    debugPrintfEXT("TEST");
}

and see if you are getting spammed

no change

spencer-lunarg commented 1 month ago

Unable to locate information for shader used in command buffer

that is a separate issue of use not being able to detect which VkShaderModule handle it came from, so that is a red herring

spencer-lunarg commented 1 month ago

Let me try a test that combines both a compute and graphics together... curious if we have our VkPipelineBindPoint messed up and don't separate things correctly

AlexRouSg commented 1 month ago

I have disabled absolutely everything except the compute dispatch and swapchain acquire/present and it's still not showing up hmmmm image

AlexRouSg commented 1 month ago

@spencer-lunarg I FOUND OUT WHAT BROKE

I ruled out everything one by one until the last thing I tried is to create a shader module instead of passing VkShaderModuleCreateInfo to the pnext and then all the messages now show up

spencer-lunarg commented 1 month ago

AWESOME you figured it out

VkShaderModuleCreateInfo to the pnext

you mean the pNext of VkPipelineShaderStageCreateInfo?

AlexRouSg commented 1 month ago

AWESOME you figured it out

VkShaderModuleCreateInfo to the pnext

you mean the pNext of VkPipelineShaderStageCreateInfo?

yes

spencer-lunarg commented 1 month ago

ok, this makes sense looking at the code... ok will get test and fix this... this pNext thing was added post 1.0 and I remember having to fix it up everywhere, well I guess debug printf was missed

Thanks again for helping nail this down, that was a nasty bug

spencer-lunarg commented 1 month ago

update - created https://github.com/KhronosGroup/Vulkan-ValidationLayers/pull/8106 as I found we were not handling this case for a LOT of spots, so I added most support, but still have some left (including GPU-AV and DebugPrintF)

I added tests for it in the PR and just need some extra time to go back and add it, it basically is nasty because we have a million and one ways pipeline state can look like :laughing:

spencer-lunarg commented 1 month ago

@AlexRouSg update - https://github.com/KhronosGroup/Vulkan-ValidationLayers/pull/8162 merged and now confirmed this all works

Thanks again for helping me narrow this down... it ended up being a little nasty to add, but we have tests now so will keep making sure this path is supported so it doesn't trip up the next person

AlexRouSg commented 1 month ago

I have just verified it on my end and appears to be working! Thank you for your hard work.