diff --git a/ggml/src/ggml-hrx/CMakeLists.txt b/ggml/src/ggml-hrx/CMakeLists.txt index df31214c45bf..805545884c96 100644 --- a/ggml/src/ggml-hrx/CMakeLists.txt +++ b/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 diff --git a/ggml/src/ggml-hrx/README.md b/ggml/src/ggml-hrx/README.md index 47a530eaf4ef..b60ec1509a9f 100644 --- a/ggml/src/ggml-hrx/README.md +++ b/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. diff --git a/ggml/src/ggml-hrx/runtime/command-program-executor.cpp b/ggml/src/ggml-hrx/runtime/command-program-executor.cpp index 7723246b29f9..2b03090b48f6 100644 --- a/ggml/src/ggml-hrx/runtime/command-program-executor.cpp +++ b/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()); diff --git a/ggml/src/ggml-hrx/runtime/command-program-executor.h b/ggml/src/ggml-hrx/runtime/command-program-executor.h index bc1debfe03a3..f2035a88698f 100644 --- a/ggml/src/ggml-hrx/runtime/command-program-executor.h +++ b/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 { diff --git a/ggml/src/ggml-hrx/runtime/compile-trace.cpp b/ggml/src/ggml-hrx/runtime/compile-trace.cpp new file mode 100644 index 000000000000..3792c8e5db3c --- /dev/null +++ b/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 + +#include +#include +#include +#include +#include + +#ifdef _WIN32 +#include +#else +#include +#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 next{ 1 }; + return next.fetch_add(1, std::memory_order_relaxed); +} + +uint64_t compile_trace_now_ns() { + return static_cast( + std::chrono::duration_cast(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 diff --git a/ggml/src/ggml-hrx/runtime/compile-trace.h b/ggml/src/ggml-hrx/runtime/compile-trace.h new file mode 100644 index 000000000000..dbaf59eeadd1 --- /dev/null +++ b/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 +#include + +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 diff --git a/ggml/src/ggml-hrx/runtime/graph-executor.cpp b/ggml/src/ggml-hrx/runtime/graph-executor.cpp index fa509c839792..4d1e7db8096c 100644 --- a/ggml/src/ggml-hrx/runtime/graph-executor.cpp +++ b/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; } diff --git a/ggml/src/ggml-hrx/runtime/kernel-executable-cache.cpp b/ggml/src/ggml-hrx/runtime/kernel-executable-cache.cpp index 5a86bc35f616..04c4356a59a2 100644 --- a/ggml/src/ggml-hrx/runtime/kernel-executable-cache.cpp +++ b/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(key, definition, dispatch, compiled_ref); cache_.emplace(key, entry); @@ -404,7 +412,10 @@ std::shared_ptr 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 diff --git a/ggml/src/ggml-hrx/runtime/kernel-executable-cache.h b/ggml/src/ggml-hrx/runtime/kernel-executable-cache.h index 42d9c0674649..bd5f5d3d8ca9 100644 --- a/ggml/src/ggml-hrx/runtime/kernel-executable-cache.h +++ b/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 diff --git a/ggml/src/ggml-hrx/runtime/loom-kernel-jit.cpp b/ggml/src/ggml-hrx/runtime/loom-kernel-jit.cpp index d79a1fbf5cfe..e159614f8b66 100644 --- a/ggml/src/ggml-hrx/runtime/loom-kernel-jit.cpp +++ b/ggml/src/ggml-hrx/runtime/loom-kernel-jit.cpp @@ -134,6 +134,9 @@ class LoomSyncJit final : public LoomJit { static void compile_ref(LoomCompiledKernel & compiled_ref, ggml_hrx_loom_jit_amdgpu * jit) { ggml_hrx_loom_jit_compile_result compiled; std::string error_message; + if (compiled_ref.request().trace.compilation_id != 0) { + compiled_ref.trace_start_ns_ = trace_compile_begin(compiled_ref.request().trace); + } const bool success = compile_kernel(jit, compiled_ref.request(), compiled_ref.key(), compiled, error_message); compiled_ref.complete(std::move(compiled), success, std::move(error_message)); } @@ -236,6 +239,9 @@ class LoomAsyncJit final : public LoomJit { static void compile_ref(LoomCompiledKernel & compiled_ref, ggml_hrx_loom_jit_amdgpu * jit) { ggml_hrx_loom_jit_compile_result compiled; std::string error_message; + if (compiled_ref.request().trace.compilation_id != 0) { + compiled_ref.trace_start_ns_ = trace_compile_begin(compiled_ref.request().trace); + } const bool success = compile_kernel(jit, compiled_ref.request(), compiled_ref.key(), compiled, error_message); compiled_ref.complete(std::move(compiled), success, std::move(error_message)); } @@ -287,15 +293,23 @@ LoomCompiledKernel::LoomCompiledKernel(std::string key, LoomKernelCompileRequest key_(std::move(key)), request_(std::move(request)) {} -bool LoomCompiledKernel::resolve() const { +bool LoomCompiledKernel::resolve(uint64_t waiting_execution_id) const { const State current = state(); if (current != State::Pending) { return current == State::Succeeded; } - std::unique_lock lock(mutex_); - complete_.wait(lock, [&] { return state() != State::Pending; }); - return state() == State::Succeeded; + const uint64_t start_ns = request_.trace.compilation_id != 0 ? compile_trace_now_ns() : 0; + bool success; + { + std::unique_lock lock(mutex_); + complete_.wait(lock, [&] { return state() != State::Pending; }); + success = state() == State::Succeeded; + } + if (start_ns != 0) { + trace_compile_wait(request_.trace, waiting_execution_id, start_ns, success); + } + return success; } std::string LoomCompiledKernel::error_message() const { @@ -309,6 +323,9 @@ ggml_hrx_loom_jit_compile_result LoomCompiledKernel::take_result() { } void LoomCompiledKernel::complete(ggml_hrx_loom_jit_compile_result compiled, bool success, std::string error) { + if (request_.trace.compilation_id != 0) { + trace_compile_end(request_.trace, trace_start_ns_, success, error); + } { std::lock_guard lock(mutex_); compiled_ = std::move(compiled); diff --git a/ggml/src/ggml-hrx/runtime/loom-kernel-jit.h b/ggml/src/ggml-hrx/runtime/loom-kernel-jit.h index 3353297290fc..4834ebc58689 100644 --- a/ggml/src/ggml-hrx/runtime/loom-kernel-jit.h +++ b/ggml/src/ggml-hrx/runtime/loom-kernel-jit.h @@ -1,6 +1,7 @@ #pragma once #include "loom-jit.h" +#include "compile-trace.h" #include #include @@ -15,6 +16,7 @@ namespace ggml::hrx { struct LoomKernelCompileRequest { + CompileTraceIds trace; const void * source_data = nullptr; size_t source_size = 0; ggml_hrx_loom_jit_source_format source_format = GGML_HRX_LOOM_JIT_SOURCE_FORMAT_TEXT; @@ -36,7 +38,7 @@ class LoomCompiledKernel { const std::string & key() const { return key_; } - bool resolve() const; + bool resolve(uint64_t waiting_execution_id = 0) const; std::string error_message() const; ggml_hrx_loom_jit_compile_result take_result(); @@ -62,6 +64,7 @@ class LoomCompiledKernel { LoomKernelCompileRequest request_; ggml_hrx_loom_jit_compile_result compiled_; std::string error_; + uint64_t trace_start_ns_ = 0; std::atomic state_ = State::Pending; };