GPU: Add support for in shader printf

This allows much easier debugging of shader programs.

Usage is as simple as adding `printf` calls inside shaders.
example: `printf("Formating %d\n", my_var);`

Contrary to the `drw_print`, this is not limited
to draw manager shader dispatch/draws. It is compatible
with any shader inside blender.
Most notably, this doesn't need a viewport to display.
So this can be used to debug render pipeline.

Data formating is currently limited to only `%x`, `%d`,
`%u` and `%f`. This could be easily extended if this is
really needed.

There is no type checking, so values are directly reinterpreted
as specified by the printf format.

The current approach for making this work is to bind a
storage buffer inside `GPU_shader_bind`, making it
available to any shader that needs it. The storage buffer
is downloaded back to CPU after a frame or a render
step and the content printed to the console.

This scheduling means that you cannot rely on these printfs
to detect crashes. We could add a mode to force flushing
at shader binding to avoid this limitation.

The values are written from the shaders in binary form and
only formated on the CPU. This avoid issues with manual
printing like with `drw_print`.

Pull Request: https://projects.blender.org/blender/blender/pulls/125071

source/blender/gpu/CMakeLists.txt

@@ -521,6 +521,7 @@ set(GLSL_SRC
   shaders/common/gpu_shader_math_matrix_lib.glsl
   shaders/common/gpu_shader_math_rotation_lib.glsl
   shaders/common/gpu_shader_math_vector_lib.glsl
+  shaders/common/gpu_shader_print_lib.glsl
   shaders/common/gpu_shader_shared_exponent_lib.glsl
   shaders/common/gpu_shader_smaa_lib.glsl
   shaders/common/gpu_shader_test_lib.glsl
@@ -791,6 +792,7 @@ set(SRC_SHADER_CREATE_INFOS
   shaders/infos/gpu_shader_instance_varying_color_varying_size_info.hh
   shaders/infos/gpu_shader_keyframe_shape_info.hh
   shaders/infos/gpu_shader_line_dashed_uniform_color_info.hh
+  shaders/infos/gpu_shader_print_info.hh
   shaders/infos/gpu_shader_sequencer_info.hh
   shaders/infos/gpu_shader_simple_lighting_info.hh
   shaders/infos/gpu_shader_text_info.hh

source/blender/gpu/intern/gpu_context.cc

@@ -24,6 +24,7 @@
 #include "gpu_context_private.hh"
 #include "gpu_matrix_private.hh"
 #include "gpu_private.hh"
+#include "gpu_shader_private.hh"
 
 #ifdef WITH_OPENGL_BACKEND
 #  include "gl_backend.hh"
@@ -114,6 +115,7 @@ GPUContext *GPU_context_create(void *ghost_window, void *ghost_context)
 void GPU_context_discard(GPUContext *ctx_)
 {
   Context *ctx = unwrap(ctx_);
+  printf_end(ctx);
   delete ctx;
   active_ctx = nullptr;
 
@@ -133,6 +135,7 @@ void GPU_context_active_set(GPUContext *ctx_)
   Context *ctx = unwrap(ctx_);
 
   if (active_ctx) {
+    printf_end(active_ctx);
     active_ctx->deactivate();
   }
 
@@ -140,6 +143,7 @@ void GPU_context_active_set(GPUContext *ctx_)
 
   if (ctx) {
     ctx->activate();
+    printf_begin(ctx);
   }
 }
 
@@ -214,7 +218,9 @@ void GPU_render_step()
   GPUBackend *backend = GPUBackend::get();
   BLI_assert(backend);
   if (backend) {
+    printf_end(active_ctx);
     backend->render_step();
+    printf_begin(active_ctx);
   }
 }
 

source/blender/gpu/intern/gpu_context_private.hh

@@ -60,6 +60,8 @@ class Context {
   static int context_counter;
   int context_id = 0;
 
+  GPUStorageBuf *printf_buf = nullptr;
+
  protected:
   /** Thread on which this context is active. */
   pthread_t thread_;

source/blender/gpu/intern/gpu_shader.cc

@@ -383,6 +383,11 @@ void GPU_shader_bind(GPUShader *gpu_shader)
       GPU_matrix_bind(gpu_shader);
     }
   }
+#if GPU_SHADER_PRINTF_ENABLE
+  if (ctx->printf_buf) {
+    GPU_storagebuf_bind(ctx->printf_buf, GPU_SHADER_PRINTF_SLOT);
+  }
+#endif
 }
 
 void GPU_shader_unbind()

source/blender/gpu/intern/gpu_shader_create_info.cc

@@ -548,6 +548,14 @@ void gpu_shader_create_info_init()
     info->builtins_ |= gpu_shader_dependency_get_builtins(info->geometry_source_);
     info->builtins_ |= gpu_shader_dependency_get_builtins(info->compute_source_);
 
+#if GPU_SHADER_PRINTF_ENABLE
+    if ((info->builtins_ & BuiltinBits::USE_PRINTF) == BuiltinBits::USE_PRINTF ||
+        gpu_shader_dependency_force_gpu_print_injection())
+    {
+      info->additional_info("gpu_print");
+    }
+#endif
+
 #ifndef NDEBUG
     /* Automatically amend the create info for ease of use of the debug feature. */
     if ((info->builtins_ & BuiltinBits::USE_DEBUG_DRAW) == BuiltinBits::USE_DEBUG_DRAW) {

source/blender/gpu/intern/gpu_shader_create_info.hh

@@ -22,6 +22,17 @@
 
 #include <iostream>
 
+/* Force enable printf support in release build. */
+#define GPU_FORCE_ENABLE_SHADER_PRINTF 0
+
+#if !defined(NDEBUG) || GPU_FORCE_ENABLE_SHADER_PRINTF
+#  define GPU_SHADER_PRINTF_ENABLE 1
+#else
+#  define GPU_SHADER_PRINTF_ENABLE 0
+#endif
+#define GPU_SHADER_PRINTF_SLOT 13
+#define GPU_SHADER_PRINTF_MAX_CAPACITY (1024 * 4)
+
 namespace blender::gpu::shader {
 
 /* Helps intellisense / auto-completion. */
@@ -174,6 +185,7 @@ enum class BuiltinBits {
   TEXTURE_ATOMIC = (1 << 18),
 
   /* Not a builtin but a flag we use to tag shaders that use the debug features. */
+  USE_PRINTF = (1 << 28),
   USE_DEBUG_DRAW = (1 << 29),
   USE_DEBUG_PRINT = (1 << 30),
 };

source/blender/gpu/intern/gpu_shader_dependency.cc

@@ -39,6 +39,7 @@ extern "C" {
 
 namespace blender::gpu {
 
+using GPUPrintFormatMap = Map<uint32_t, shader::PrintfFormat>;
 using GPUSourceDictionnary = Map<StringRef, struct GPUSource *>;
 using GPUFunctionDictionnary = Map<StringRef, GPUFunction *>;
 
@@ -54,7 +55,8 @@ struct GPUSource {
   GPUSource(const char *path,
             const char *file,
             const char *datatoc,
-            GPUFunctionDictionnary *g_functions)
+            GPUFunctionDictionnary *g_functions,
+            GPUPrintFormatMap *g_formats)
       : fullpath(path), filename(file), source(datatoc)
   {
     /* Scan for builtins. */
@@ -122,6 +124,12 @@ struct GPUSource {
       {
         builtins |= shader::BuiltinBits::USE_DEBUG_DRAW;
       }
+#endif
+#if GPU_SHADER_PRINTF_ENABLE
+      if (source.find("printf") != StringRef::not_found) {
+        printf_preprocess(g_formats);
+        builtins |= shader::BuiltinBits::USE_PRINTF;
+      }
 #endif
       check_no_quotes();
     }
@@ -805,6 +813,191 @@ struct GPUSource {
     source = processed_source.c_str();
   }
 
+  /**
+   * Preprocess printf statement for correct shader code generation.
+   * `printf(format, data1, data2)`
+   * gets replaced by
+   * `print_data(print_data(print_header(format_hash, 2), data1), data2)`.
+   */
+  void printf_preprocess(GPUPrintFormatMap *format_map)
+  {
+    const StringRefNull input = source;
+    std::stringstream output;
+    int64_t cursor = -1;
+    int64_t last_pos = 0;
+
+    while (true) {
+      cursor = find_keyword(input, "printf(", cursor + 1);
+      if (cursor == -1) {
+        break;
+      }
+
+      /* Output anything between 2 print statement. */
+      output << input.substr(last_pos, cursor - last_pos);
+
+      /* Extract string. */
+      int64_t str_start = input.find('(', cursor) + 1;
+      int64_t semicolon = find_token(input, ';', str_start + 1);
+      CHECK(semicolon, input, cursor, "Malformed printf(). Missing `;` .");
+      int64_t str_end = rfind_token(input, ')', semicolon);
+      if (str_end < str_start) {
+        CHECK(-1, input, cursor, "Malformed printf(). Missing closing `)` .");
+      }
+
+      StringRef input_args = input.substr(str_start, str_end - str_start);
+
+      std::string func_args = input_args;
+      /* Workaround to support function call inside prints. We replace commas by a non control
+       * character `$` in order to use simpler regex later.
+       * Modify `"func %d,\n", func(a, b)` into `"func %d,\n", func(a$ b)` */
+      bool string_scope = false;
+      int func_scope = 0;
+      for (char &c : func_args) {
+        if (c == '"') {
+          string_scope = !string_scope;
+        }
+        else if (!string_scope) {
+          if (c == '(') {
+            func_scope++;
+          }
+          else if (c == ')') {
+            func_scope--;
+          }
+          else if (c == ',' && func_scope != 0) {
+            c = '$';
+          }
+        }
+      }
+
+      std::string format;
+      Vector<std::string> arguments;
+      {
+        const std::regex arg_regex(
+            /* String args. */
+            "[\\s]*\"([^\r\n\t\f\v\"]*)\""
+            /* OR. */
+            "|"
+            /* value args. */
+            "([^,]+)");
+        std::smatch args_match;
+        std::string::const_iterator args_search_start(func_args.cbegin());
+        while (std::regex_search(args_search_start, func_args.cend(), args_match, arg_regex)) {
+          args_search_start = args_match.suffix().first;
+          std::string arg_string = args_match[1].str();
+          std::string arg_val = args_match[2].str();
+
+          if (!arg_string.empty()) {
+            if (!format.empty()) {
+              CHECK(-1, input, cursor, "Format string is not the only string arg.");
+            }
+            if (!arguments.is_empty()) {
+              CHECK(-1, input, cursor, "Format string is not first argument.");
+            }
+            format = arg_string;
+          }
+          else {
+            for (char &c : arg_val) {
+              /* Mutate back functions arguments.*/
+              if (c == '$') {
+                c = ',';
+              }
+            }
+            arguments.append(arg_val);
+          }
+        }
+      }
+
+      if (format.empty()) {
+        CHECK(-1, input, cursor, "No format string found.");
+        return;
+      }
+      int format_arg_count = std::count(format.begin(), format.end(), '%');
+      if (format_arg_count > arguments.size()) {
+        CHECK(-1, input, cursor, "printf call has not enough arguments.");
+        return;
+      }
+      if (format_arg_count < arguments.size()) {
+        CHECK(-1, input, cursor, "printf call has too many arguments.");
+        return;
+      }
+
+      uint64_t format_hash_64 = hash_string(format);
+      uint32_t format_hash = uint32_t((format_hash_64 >> 32) ^ format_hash_64);
+
+      if (format_map->contains(format_hash)) {
+        if (format_map->lookup(format_hash).format_str != format) {
+          CHECK(-1, input, cursor, "printf format hash collision.");
+        }
+        else {
+          /* The format map already have the same format. */
+        }
+      }
+      else {
+        shader::PrintfFormat fmt;
+        /* Save for hash collision comparison. */
+        fmt.format_str = format;
+
+        /* Escape characters replacement. Do the most common ones. */
+        format = std::regex_replace(format, std::regex(R"(\\n)"), "\n");
+        format = std::regex_replace(format, std::regex(R"(\\v)"), "\v");
+        format = std::regex_replace(format, std::regex(R"(\\t)"), "\t");
+        format = std::regex_replace(format, std::regex(R"(\\')"), "\'");
+        format = std::regex_replace(format, std::regex(R"(\\")"), "\"");
+        format = std::regex_replace(format, std::regex(R"(\\\\)"), "\\");
+
+        shader::PrintfFormat::Block::ArgumentType type =
+            shader::PrintfFormat::Block::ArgumentType::NONE;
+        int64_t start = 0, end = 0;
+        while ((end = format.find_first_of('%', start + 1)) != -1) {
+          /* Add the previous block without the newly found % character. */
+          fmt.format_blocks.append({type, format.substr(start, end - start)});
+          /* Format type of the next block. */
+          /* TODO(fclem): This doesn't support advance formats like `%3.2f`. */
+          switch (format[end + 1]) {
+            case 'x':
+            case 'u':
+              type = shader::PrintfFormat::Block::ArgumentType::UINT;
+              break;
+            case 'd':
+              type = shader::PrintfFormat::Block::ArgumentType::INT;
+              break;
+            case 'f':
+              type = shader::PrintfFormat::Block::ArgumentType::FLOAT;
+              break;
+            default:
+              BLI_assert_msg(0, "Printing format unsupported");
+              break;
+          }
+          /* Start of the next block. */
+          start = end;
+        }
+        fmt.format_blocks.append({type, format.substr(start, format.size() - start)});
+
+        format_map->add(format_hash, fmt);
+      }
+
+      std::string sub_output = "print_header(" + std::to_string(format_hash) + "u, " +
+                               std::to_string(format_arg_count) + "u)";
+      for (std::string &arg : arguments) {
+        sub_output = "print_data(" + sub_output + ", " + arg + ")";
+      }
+
+      output << sub_output << ";\n";
+
+      cursor = last_pos = str_end + 1;
+    }
+    /* If nothing has been changed, do not allocate processed_source. */
+    if (last_pos == 0) {
+      return;
+    }
+
+    if (last_pos != 0) {
+      output << input.substr(last_pos);
+    }
+    processed_source = output.str();
+    source = processed_source.c_str();
+  }
+
 #undef find_keyword
 #undef rfind_keyword
 #undef find_token
@@ -822,6 +1015,9 @@ struct GPUSource {
 
     using namespace shader;
     /* Auto dependency injection for debug capabilities. */
+    if ((builtins & BuiltinBits::USE_PRINTF) == BuiltinBits::USE_PRINTF) {
+      dependencies.append_non_duplicates(dict.lookup("gpu_shader_print_lib.glsl"));
+    }
     if ((builtins & BuiltinBits::USE_DEBUG_DRAW) == BuiltinBits::USE_DEBUG_DRAW) {
       dependencies.append_non_duplicates(dict.lookup("common_debug_draw_lib.glsl"));
     }
@@ -898,16 +1094,19 @@ struct GPUSource {
 
 using namespace blender::gpu;
 
+static GPUPrintFormatMap *g_formats = nullptr;
 static GPUSourceDictionnary *g_sources = nullptr;
 static GPUFunctionDictionnary *g_functions = nullptr;
+static bool force_printf_injection = false;
 
 void gpu_shader_dependency_init()
 {
+  g_formats = new GPUPrintFormatMap();
   g_sources = new GPUSourceDictionnary();
   g_functions = new GPUFunctionDictionnary();
 
 #define SHADER_SOURCE(datatoc, filename, filepath) \
-  g_sources->add_new(filename, new GPUSource(filepath, filename, datatoc, g_functions));
+  g_sources->add_new(filename, new GPUSource(filepath, filename, datatoc, g_functions, g_formats));
 #include "glsl_compositor_source_list.h"
 #include "glsl_draw_source_list.h"
 #include "glsl_gpu_source_list.h"
@@ -922,6 +1121,21 @@ void gpu_shader_dependency_init()
   }
   BLI_assert_msg(errors == 0, "Dependency errors detected: Aborting");
   UNUSED_VARS_NDEBUG(errors);
+
+#if GPU_SHADER_PRINTF_ENABLE
+  if (!g_formats->is_empty()) {
+    /* Detect if there is any printf in node lib files.
+     * See gpu_shader_dependency_force_gpu_print_injection(). */
+    for (auto *value : g_sources->values()) {
+      if ((value->builtins & shader::BuiltinBits::USE_PRINTF) != shader::BuiltinBits::USE_PRINTF) {
+        if (value->filename.startswith("gpu_shader_material_")) {
+          force_printf_injection = true;
+          break;
+        }
+      }
+    }
+  }
+#endif
 }
 
 void gpu_shader_dependency_exit()
@@ -932,6 +1146,7 @@ void gpu_shader_dependency_exit()
   for (auto *value : g_functions->values()) {
     MEM_delete(value);
   }
+  delete g_formats;
   delete g_sources;
   delete g_functions;
 }
@@ -947,6 +1162,23 @@ GPUFunction *gpu_material_library_use_function(GSet *used_libraries, const char
 
 namespace blender::gpu::shader {
 
+bool gpu_shader_dependency_force_gpu_print_injection()
+{
+  /* WORKAROUND: We cannot know what shader will require printing if the printf is inside shader
+   * node code. In this case, we just force injection inside all shaders. */
+  return force_printf_injection;
+}
+
+bool gpu_shader_dependency_has_printf()
+{
+  return (g_formats != nullptr) && !g_formats->is_empty();
+}
+
+const PrintfFormat &gpu_shader_dependency_get_printf_format(uint32_t format_hash)
+{
+  return g_formats->lookup(format_hash);
+}
+
 BuiltinBits gpu_shader_dependency_get_builtins(const StringRefNull shader_source_name)
 {
   if (shader_source_name.is_empty()) {

source/blender/gpu/intern/gpu_shader_dependency_private.hh

@@ -24,6 +24,28 @@ namespace blender::gpu::shader {
 
 BuiltinBits gpu_shader_dependency_get_builtins(const StringRefNull source_name);
 
+/* Returns true is any shader code has a printf statement. */
+bool gpu_shader_dependency_has_printf();
+
+bool gpu_shader_dependency_force_gpu_print_injection();
+
+struct PrintfFormat {
+  struct Block {
+    enum ArgumentType {
+      NONE = 0,
+      UINT,
+      INT,
+      FLOAT,
+    } type = NONE;
+    std::string fmt;
+  };
+
+  Vector<Block> format_blocks;
+  std::string format_str;
+};
+
+const PrintfFormat &gpu_shader_dependency_get_printf_format(uint32_t format_hash);
+
 Vector<const char *> gpu_shader_dependency_get_resolved_source(const StringRefNull source_name);
 StringRefNull gpu_shader_dependency_get_source(const StringRefNull source_name);
 

source/blender/gpu/intern/gpu_shader_log.cc

@@ -13,6 +13,9 @@
 #include "BLI_string_utils.hh"
 #include "BLI_vector.hh"
 
+#include "GPU_storage_buffer.hh"
+
+#include "gpu_context_private.hh"
 #include "gpu_shader_dependency_private.hh"
 #include "gpu_shader_private.hh"
 
@@ -321,4 +324,76 @@ int GPULogParser::parse_number(const char *log_line, const char **r_new_position
 
 /** \} */
 
+/* -------------------------------------------------------------------- */
+/** \name Shader Debug Printf
+ * \{ */
+
+void printf_begin(Context *ctx)
+{
+  if (ctx == nullptr) {
+    return;
+  }
+  if (!shader::gpu_shader_dependency_has_printf()) {
+    return;
+  }
+  BLI_assert(ctx->printf_buf == nullptr);
+  ctx->printf_buf = GPU_storagebuf_create(GPU_SHADER_PRINTF_MAX_CAPACITY * sizeof(uint32_t));
+  GPU_storagebuf_clear_to_zero(ctx->printf_buf);
+}
+
+void printf_end(Context *ctx)
+{
+  if (ctx == nullptr) {
+    return;
+  }
+  if (ctx->printf_buf == nullptr) {
+    return;
+  }
+
+  Vector<uint32_t> data(GPU_SHADER_PRINTF_MAX_CAPACITY);
+  GPU_storagebuf_read(ctx->printf_buf, data.data());
+  GPU_storagebuf_free(ctx->printf_buf);
+  ctx->printf_buf = nullptr;
+
+  uint32_t data_len = data[0];
+  if (data_len == 0) {
+    return;
+  }
+  if (data_len >= GPU_SHADER_PRINTF_MAX_CAPACITY) {
+    printf("Printf buffer overflow.\n");
+    /* TODO(fclem): We can still read the uncorrupted part. */
+    return;
+  }
+
+  int cursor = 1;
+  while (cursor < data_len + 1) {
+    uint32_t format_hash = data[cursor++];
+
+    const shader::PrintfFormat &format = shader::gpu_shader_dependency_get_printf_format(
+        format_hash);
+
+    for (const shader::PrintfFormat::Block &block : format.format_blocks) {
+      switch (block.type) {
+        case shader::PrintfFormat::Block::NONE:
+          printf("%s", block.fmt.c_str());
+          break;
+        case shader::PrintfFormat::Block::UINT:
+          printf(block.fmt.c_str(), *reinterpret_cast<uint32_t *>(&data[cursor++]));
+          break;
+        case shader::PrintfFormat::Block::INT:
+          printf(block.fmt.c_str(), *reinterpret_cast<int32_t *>(&data[cursor++]));
+          break;
+        case shader::PrintfFormat::Block::FLOAT:
+          printf(block.fmt.c_str(), *reinterpret_cast<float *>(&data[cursor++]));
+          break;
+        default:
+          BLI_assert_unreachable();
+          break;
+      }
+    }
+  }
+}
+
+/** \} */
+
 }  // namespace blender::gpu

source/blender/gpu/intern/gpu_shader_private.hh

@@ -24,6 +24,7 @@ namespace blender {
 namespace gpu {
 
 class GPULogParser;
+class Context;
 
 /* Set to 1 to log the full source of shaders that fail to compile. */
 #define DEBUG_LOG_SHADER_SRC_ON_ERROR 0
@@ -256,6 +257,9 @@ class GPULogParser {
   MEM_CXX_CLASS_ALLOC_FUNCS("GPULogParser");
 };
 
+void printf_begin(Context *ctx);
+void printf_end(Context *ctx);
+
 }  // namespace gpu
 }  // namespace blender
 

source/blender/gpu/shaders/common/gpu_shader_print_lib.glsl

@@ -0,0 +1,27 @@
+/* SPDX-FileCopyrightText: 2024 Blender Authors
+ *
+ * SPDX-License-Identifier: GPL-2.0-or-later */
+
+uint print_data(uint offset, uint data)
+{
+  if (offset < GPU_SHADER_PRINTF_MAX_CAPACITY) {
+    gpu_print_buf[offset] = data;
+  }
+  return offset + 1u;
+}
+
+uint print_data(uint offset, int data)
+{
+  return print_data(offset, uint(data));
+}
+
+uint print_data(uint offset, float data)
+{
+  return print_data(offset, floatBitsToUint(data));
+}
+
+uint print_header(uint format_hash, const uint data_len)
+{
+  uint offset = atomicAdd(gpu_print_buf[0], 1u + data_len) + 1u;
+  return print_data(offset, format_hash);
+}

source/blender/gpu/shaders/infos/gpu_shader_print_info.hh

@@ -0,0 +1,15 @@
+/* SPDX-FileCopyrightText: 2024 Blender Authors
+ *
+ * SPDX-License-Identifier: GPL-2.0-or-later */
+
+/** \file
+ * \ingroup gpu
+ */
+
+#include "gpu_shader_create_info.hh"
+
+GPU_SHADER_CREATE_INFO(gpu_print)
+    .storage_buf(
+        GPU_SHADER_PRINTF_SLOT, Qualifier::READ_WRITE, "uint", "gpu_print_buf[]", Frequency::PASS)
+    .define("GPU_SHADER_PRINTF_MAX_CAPACITY", STRINGIFY(GPU_SHADER_PRINTF_MAX_CAPACITY))
+    .define("GPU_PRINT");