ggml-hrx: add opt-in compilation diagnostics

ggml/src/ggml-hrx/CMakeLists.txt

@@ -279,6 +279,8 @@ ggml_add_backend_library(ggml-hrx
     graph/value-map.h
     runtime/command-program-executor.cpp
     runtime/command-program-executor.h
+    runtime/compile-trace.cpp
+    runtime/compile-trace.h
     runtime/graph-executor.cpp
     runtime/graph-executor.h
     runtime/graph-program-cache.cpp

ggml/src/ggml-hrx/README.md

@@ -1,5 +1,47 @@
 # HRX Backend
 
+## Compilation diagnostics
+
+Set `GGML_HRX_TRACE_COMPILE=1` before starting an application using the ggml HRX backend to log compilation activity. Each record is a JSON object on stderr prefixed with `hrx compile: `. This output bypasses the application's log-level filter, so it also works with quiet benchmark runs. The setting is read once per process; unset or any value other than `1` disables it.
+
+For example, use an existing benchmark to inspect two prefill/decode cycles in one context:
+
+```sh
+GGML_HRX_TRACE_COMPILE=1 ./build/bin/llama-bench \
+  --model /path/to/model.gguf --device HRX0 --n-gpu-layers 99 \
+  -p 0 -n 0 -pg 64,16 -b 64 -ub 64 -r 2 --no-warmup --progress \
+  2>hrx-compile.log
+```
+
+Select a supported GPU with `ROCR_VISIBLE_DEVICES` as appropriate for the machine. The workload and repetition count are caller choices. Omitting `--no-warmup` captures the benchmark's warmup too.
+
+Every record carries `pid`, a monotonic `time_ns`, and `cache_id`, `execution_id`, and `compilation_id`. IDs are process-local; zero means the corresponding scope does not apply. Use `(pid, cache_id)` to identify a kernel-cache lifetime and `compilation_id` to join a request to its worker events. Clearing the cache emits `cache_clear` and assigns a new cache ID for future work.
+
+| Event | Information |
+| --- | --- |
+| `graph_begin` | A backend graph execution and its incoming `graph_uid`. Each invocation gets a new execution ID, even when the graph is reused. |
+| `graph_end` | Compilation requests made by that execution, including zero, host duration, and success. |
+| `compile_request` | A kernel-cache miss: full cache key, kernel name, exact/dynamic workload specialization, integer parameters, and merged compile parameters. |
+| `compile_begin` | The worker or synchronous caller starts compiling that request. |
+| `compile_end` | Compiler duration, success, and error text. `compiler_started=false` identifies failure before the compiler ran, such as JIT initialization failure. |
+| `compile_wait` | A caller encountered an unresolved compilation: wait duration, success, and `waiting_execution_id`. `execution_id` still identifies the original requester. Already resolved compilations emit no wait event. |
+| `cache_clear` | The end of a cache lifetime, after outstanding compiler workers finish. |
+
+Graph executions are backend calls, not authoritative prefill/decode, token, or repetition labels. One application step may execute multiple backend graphs. Correlate the ordered executions and specialization parameters with the workload and the caller's progress output. Direct kernel-cache callers without a graph scope have `execution_id=0`.
+
+To diagnose repeated compilation, group requests by kernel within a cache lifetime and compare their keys and parameters. Changing sequence-length parameters can reveal candidates for dynamic specialization. Repeating an identical key may indicate a retry after compilation or executable-loading failure. The records report observations; they do not decide whether a specialization is necessary. A graph-program change alone does not imply a kernel compilation.
+
+Compiler durations can overlap across workers. Wait durations measure the host's unresolved-compilation wait, including scheduling and diagnostic overhead; they exclude executable loading and GPU execution. Synchronous compilation blocks the caller within the compile event and normally emits no `compile_wait`. Graph durations cover the host backend call, which may return before GPU work finishes. Summed compiler durations therefore do not measure application stall time.
+
+Capture preserves asynchronous compilation and graph replay. When disabled, instrumentation uses cached enable state and cheap checks, with no added clock reads, event formatting, logging locks, or file I/O. When enabled, output and timing add diagnostic overhead; use ordinary runs for throughput measurements.
+
+Extract just the JSON records for analysis:
+
+```sh
+sed -n 's/^hrx compile: //p' hrx-compile.log > hrx-compile.jsonl
+jq -c 'select(.event == "compile_request") | {cache_id, execution_id, kernel, integer_parameters, compile_parameters}' hrx-compile.jsonl
+```
+
 ## `hrx-system` backend compatibility
 
 `hrx-minimum-commit.txt` records the minimum required commit in ROCm/hrx-system. It contains one full Git commit SHA. The backend's C++ APIs, Loom syntax, and numerical behavior can all depend on that revision. When `GGML_HRX=ON` and `HRX_SOURCE_DIR` is set, CMake requires the HRX checkout's HEAD to equal or descend from the recorded commit.

ggml/src/ggml-hrx/runtime/command-program-executor.cpp

@@ -1223,7 +1223,8 @@ static Status prepare_kernel_command(const CommandProgramExecutionContext & cont
 
     prepared       = make_prepared_command_shape(command);
     executable_ref =
-        context.kernel_executables->get_or_compile({ context.device, context.target }, *resolved.definition, dispatch);
+        context.kernel_executables->get_or_compile({ context.device, context.target, context.compile_trace },
+                                                   *resolved.definition, dispatch);
     if (!executable_ref.valid()) {
         status.log("failed to prepare %s", command_context.c_str());
         return status;
@@ -1293,7 +1294,7 @@ static void materialize_command_list_executables(const CommandProgramExecutionCo
     for (size_t i = 0; i < prepared_commands.size(); ++i) {
         PreparedCommand & command = prepared_commands[i];
         command.kernel.executable = context.kernel_executables->materialize(
-            { context.device, context.target }, executable_refs[i], command.kernel.specialization,
+            { context.device, context.target, context.compile_trace }, executable_refs[i], command.kernel.specialization,
             command.kernel.constants, command.kernel.launch);
         if (command.kernel.executable == nullptr) {
             status.log("failed to prepare %s", format_prepared_command_context(command).c_str());

ggml/src/ggml-hrx/runtime/command-program-executor.h

@@ -25,6 +25,7 @@ struct ggml_hrx_loom_jit_amdgpu;
 namespace ggml::hrx {
 
 class KernelExecutableCache;
+struct CompileTraceExecution;
 struct KernelExecutable;
 class TransientArena;
 class HostBufferRegistry;
@@ -62,6 +63,7 @@ struct CommandProgramExecutionContext {
     HostWeightCache *       host_weights       = nullptr;
     HostBufferRegistry *    host_buffers       = nullptr;
     GraphReplayStreamState * graph_replay_state = nullptr;
+    CompileTraceExecution * compile_trace = nullptr;
 };
 
 struct PreparedCommandBinding {

ggml/src/ggml-hrx/runtime/compile-trace.cpp

@@ -0,0 +1,126 @@
+#include "compile-trace.h"
+
+#include "dispatch/dispatch.h"
+#include "kernel-corpus/kernel-corpus.h"
+#include "loom-kernel-jit.h"
+
+#include <nlohmann/json.hpp>
+
+#include <atomic>
+#include <chrono>
+#include <cstdio>
+#include <cstdlib>
+#include <cstring>
+
+#ifdef _WIN32
+#include <process.h>
+#else
+#include <unistd.h>
+#endif
+
+namespace ggml::hrx {
+namespace {
+
+using json = nlohmann::ordered_json;
+
+void write_event(const char * event, const CompileTraceIds & ids, json fields) {
+#ifdef _WIN32
+    const int pid = _getpid();
+#else
+    const int pid = getpid();
+#endif
+    json record = {
+        { "event", event },
+        { "pid", pid },
+        { "time_ns", compile_trace_now_ns() },
+        { "cache_id", ids.cache_id },
+        { "execution_id", ids.execution_id },
+        { "compilation_id", ids.compilation_id },
+    };
+    record.update(fields);
+    // One stdio call keeps records from compiler workers on separate lines.
+    const std::string line = record.dump();
+    std::fprintf(stderr, "hrx compile: %s\n", line.c_str());
+}
+
+}  // namespace
+
+bool compile_trace_enabled() {
+    static const bool enabled = [] {
+        const char * value = std::getenv("GGML_HRX_TRACE_COMPILE");
+        return value != nullptr ? std::strcmp(value, "1") == 0 : false;
+    }();
+    return enabled;
+}
+
+uint64_t compile_trace_next_id() {
+    static std::atomic<uint64_t> next{ 1 };
+    return next.fetch_add(1, std::memory_order_relaxed);
+}
+
+uint64_t compile_trace_now_ns() {
+    return static_cast<uint64_t>(
+        std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::steady_clock::now().time_since_epoch())
+            .count());
+}
+
+CompileTraceExecution::CompileTraceExecution(uint64_t cache_id, uint64_t graph_uid) {
+    if (cache_id == 0) {
+        return;
+    }
+    ids = { cache_id, compile_trace_next_id(), 0 };
+    write_event("graph_begin", ids, { { "graph_uid", graph_uid } });
+    start_ns_ = compile_trace_now_ns();
+}
+
+CompileTraceExecution::~CompileTraceExecution() {
+    if (ids.cache_id == 0) {
+        return;
+    }
+    const uint64_t duration_ns = compile_trace_now_ns() - start_ns_;
+    write_event("graph_end", ids, {
+        { "duration_ns", duration_ns }, { "compilations", compilations }, { "success", success },
+    });
+}
+
+void trace_compile_request(const std::string & key, const KernelDefinition & definition,
+                           const Dispatch & dispatch, const LoomKernelCompileRequest & request) {
+    json configs = json::object();
+    for (const auto & config : request.config_storage) {
+        configs[config.first] = config.second;
+    }
+    write_event("compile_request", request.trace, {
+        { "key", key },
+        { "kernel", kernel_definition_name(definition) },
+        { "workload_specialization", dispatch.kernel.workload_specialization == WorkloadSpecialization::Exact ?
+                                         "exact" : "dynamic" },
+        { "integer_parameters", dispatch.kernel.integer_parameters },
+        { "compile_parameters", configs },
+    });
+}
+
+uint64_t trace_compile_begin(const CompileTraceIds & ids) {
+    write_event("compile_begin", ids, json::object());
+    return compile_trace_now_ns();
+}
+
+void trace_compile_end(const CompileTraceIds & ids, uint64_t start_ns, bool success, const std::string & error) {
+    const uint64_t duration_ns = start_ns != 0 ? compile_trace_now_ns() - start_ns : 0;
+    write_event("compile_end", ids, {
+        { "duration_ns", duration_ns }, { "compiler_started", start_ns != 0 },
+        { "success", success }, { "error", error },
+    });
+}
+
+void trace_compile_wait(const CompileTraceIds & ids, uint64_t waiting_execution_id, uint64_t start_ns, bool success) {
+    const uint64_t duration_ns = compile_trace_now_ns() - start_ns;
+    write_event("compile_wait", ids, {
+        { "waiting_execution_id", waiting_execution_id }, { "duration_ns", duration_ns }, { "success", success },
+    });
+}
+
+void trace_compile_cache_clear(uint64_t cache_id) {
+    write_event("cache_clear", { cache_id, 0, 0 }, json::object());
+}
+
+}  // namespace ggml::hrx

ggml/src/ggml-hrx/runtime/compile-trace.h

@@ -0,0 +1,47 @@
+#pragma once
+
+// Compilation requests copy these IDs to preserve their origin on JIT workers.
+// All output is opt-in; execution IDs describe backend calls, not token steps.
+
+#include <cstdint>
+#include <string>
+
+namespace ggml::hrx {
+
+struct Dispatch;
+struct KernelDefinition;
+struct LoomKernelCompileRequest;
+
+struct CompileTraceIds {
+    uint64_t cache_id       = 0;
+    uint64_t execution_id   = 0;
+    uint64_t compilation_id = 0;
+};
+
+bool     compile_trace_enabled();
+uint64_t compile_trace_next_id();
+uint64_t compile_trace_now_ns();
+
+struct CompileTraceExecution {
+    CompileTraceExecution(uint64_t cache_id, uint64_t graph_uid);
+    ~CompileTraceExecution();
+
+    CompileTraceExecution(const CompileTraceExecution &) = delete;
+    CompileTraceExecution & operator=(const CompileTraceExecution &) = delete;
+
+    CompileTraceIds ids;
+    uint64_t       compilations = 0;
+    bool           success      = false;
+
+  private:
+    uint64_t start_ns_ = 0;
+};
+
+void trace_compile_request(const std::string & key, const KernelDefinition & definition,
+                           const Dispatch & dispatch, const LoomKernelCompileRequest & request);
+uint64_t trace_compile_begin(const CompileTraceIds & ids);
+void trace_compile_end(const CompileTraceIds & ids, uint64_t start_ns, bool success, const std::string & error);
+void trace_compile_wait(const CompileTraceIds & ids, uint64_t waiting_execution_id, uint64_t start_ns, bool success);
+void trace_compile_cache_clear(uint64_t cache_id);
+
+}  // namespace ggml::hrx

ggml/src/ggml-hrx/runtime/graph-executor.cpp

@@ -73,8 +73,10 @@ CommandProgramBindings GraphExecutor::bind_external_value_buffers(const GraphPro
 
 GraphExecutionResult GraphExecutor::execute(const ggml_cgraph & graph) const {
     GraphExecutionResult result;
+    CompileTraceExecution trace(context_.kernel_executables.trace_id(), graph.uid);
     if (graph.n_nodes == 0) {
         result.code = GGML_STATUS_SUCCESS;
+        trace.success = true;
         return result;
     }
     result.status = context_valid_for_execution();
@@ -119,6 +121,7 @@ GraphExecutionResult GraphExecutor::execute(const ggml_cgraph & graph) const {
         &context_.host_weights,
         &context_.device->host_buffers,
         &context_.graph_replay_state,
+        trace.ids.cache_id != 0 ? &trace : nullptr,
     };
     const PreparedCommandProgramCacheExecutionResult execution =
         use_graph_prepared ? lookup.program->execute_with_result(execution_context, bindings) :
@@ -134,6 +137,7 @@ GraphExecutionResult GraphExecutor::execute(const ggml_cgraph & graph) const {
     }
 
     result.code = GGML_STATUS_SUCCESS;
+    trace.success = true;
     return result;
 }
 

ggml/src/ggml-hrx/runtime/kernel-executable-cache.cpp

@@ -345,6 +345,14 @@ KernelExecutableRef KernelExecutableCache::get_or_compile(const KernelExecutable
             return ref;
         }
 
+        if (trace_id_ != 0) {
+            request.trace = { trace_id_, 0, compile_trace_next_id() };
+            if (context.trace != nullptr) {
+                request.trace.execution_id = context.trace->ids.execution_id;
+                ++context.trace->compilations;
+            }
+            trace_compile_request(key, definition, dispatch, request);
+        }
         compiled_ref = jit_->compile(key, std::move(request));
         auto entry   = std::make_shared<KernelExecutableCacheEntry>(key, definition, dispatch, compiled_ref);
         cache_.emplace(key, entry);
@@ -404,7 +412,10 @@ std::shared_ptr<KernelExecutable> KernelExecutableCache::materialize(const Kerne
     }
 
     std::string error_message;
-    if (compiled_ref == nullptr || !compiled_ref->resolve()) {
+    const uint64_t waiting_execution_id = context.trace != nullptr ? context.trace->ids.execution_id : 0;
+    const bool has_compilation = compiled_ref != nullptr;
+    const bool compilation_succeeded = has_compilation ? compiled_ref->resolve(waiting_execution_id) : false;
+    if (!compilation_succeeded) {
         error_message = compiled_ref ? compiled_ref->error_message() : "missing compiled kernel";
         GGML_LOG_ERROR("%s: %s\n", __func__, error_message.c_str());
 
@@ -474,6 +485,10 @@ void KernelExecutableCache::clear() {
     cache_.clear();
     jit_.reset();
     target_.clear();
+    if (trace_id_ != 0) {
+        trace_compile_cache_clear(trace_id_);
+        trace_id_ = compile_trace_next_id();
+    }
 }
 
 }  // namespace ggml::hrx

ggml/src/ggml-hrx/runtime/kernel-executable-cache.h

@@ -28,6 +28,7 @@ struct KernelExecutable {
 struct KernelExecutablePrepareContext {
     hrx_device_t device = nullptr;
     const char * target = nullptr;
+    CompileTraceExecution * trace = nullptr;
 };
 
 struct KernelExecutableRef {
@@ -60,6 +61,8 @@ class KernelExecutableCache {
 
     void clear();
 
+    uint64_t trace_id() const { return trace_id_; }
+
   private:
     bool ensure_jit_locked(const char * target, std::string & error_message);
 
@@ -69,6 +72,7 @@ class KernelExecutableCache {
     std::string                                                                  target_;
     LoomJitMode                                                                  mode_           = LoomJitMode::Async;
     bool                                                                         mode_is_forced_ = false;
+    uint64_t trace_id_ = compile_trace_enabled() ? compile_trace_next_id() : 0;
 };
 
 }  // namespace ggml::hrx