Remove game log backpressure and measure Windows K/M kernels

tools/windows/cuda_api.h

@@ -7,6 +7,7 @@ using CUcontext = void*;
 using CUmodule = void*;
 using CUfunction = void*;
 struct CudaApi {
+    bool verbose = true;
     d4r::diag::SearchDirectory search;
     d4r::diag::Library library;
 #define D4R_CU(name, ret, ...) using name##_fn = ret(WINAPI*)(__VA_ARGS__); name##_fn name = library.symbol<name##_fn>(#name)
@@ -41,7 +42,7 @@ struct CudaApi {
         const char* name = "unknown", *message = "unknown";
         if (result) { cuGetErrorName(result, &name); cuGetErrorString(result, &message); }
         else name = "CUDA_SUCCESS";
-        std::printf("CUDA %s -> %d (%s)\n", call, result, name ? name : "unknown");
+        if (verbose || result) std::printf("CUDA %s -> %d (%s)\n", call, result, name ? name : "unknown");
         if (result) throw std::runtime_error(std::string(call) + ": " + (message ? message : "unknown"));
     }
 };

tools/windows/d4r_nvngx_windows.cpp

@@ -154,7 +154,7 @@ API unsigned NVSDK_NGX_D3D12_EvaluateFeature(ID3D12GraphicsCommandList* list, co
             d4r_ngx_set_uint(snapshot->parameters, (prefix + ".Enhanced").c_str(), state.enhanced);
             d4r_ngx_set_uint(snapshot->parameters, (prefix + ".Layout").c_str(), unsigned(state.layout));
             d4r_ngx_set_uint(snapshot->parameters, (prefix + ".Access").c_str(), unsigned(state.access));
-            std::printf("D4R_RESOURCE_ACCESS plane=%s enhanced=%u legacy=0x%x layout=%u access=0x%x\n",
+            if (!std::getenv("D4R_QUIET_API")) std::printf("D4R_RESOURCE_ACCESS plane=%s enhanced=%u legacy=0x%x layout=%u access=0x%x\n",
                 names[i], state.enhanced, unsigned(state.legacy), unsigned(state.layout), unsigned(state.access));
         }
         d4r::win::commands::record_boundary(list, [feature, snapshot](ID3D12CommandQueue* queue) {
@@ -168,7 +168,7 @@ API unsigned NVSDK_NGX_D3D12_EvaluateFeature(ID3D12GraphicsCommandList* list, co
                 d4r_ngx_set_uint(snapshot->parameters, (prefix + ".Enhanced").c_str(), resolved.enhanced);
                 d4r_ngx_set_uint(snapshot->parameters, (prefix + ".Layout").c_str(), unsigned(resolved.layout));
                 d4r_ngx_set_uint(snapshot->parameters, (prefix + ".Access").c_str(), unsigned(resolved.access));
-                std::printf("D4R_INHERITED_ACCESS plane=%s tracked=%u enhanced=%u layout=%u legacy=0x%x\n",
+                if (!std::getenv("D4R_QUIET_API")) std::printf("D4R_INHERITED_ACCESS plane=%s tracked=%u enhanced=%u layout=%u legacy=0x%x\n",
                     names[i], !resolved.inherited, resolved.enhanced, unsigned(resolved.layout), unsigned(resolved.legacy));
             }
             feature->evaluate_boundary(queue, snapshot->parameters);

tools/windows/hip_api.h

@@ -4,6 +4,7 @@
 
 namespace d4r::diag {
 struct HipApi {
+    bool verbose = true; // Probes log every call; the game can suppress successful API calls.
     SearchDirectory search;
     Library library;
 #define D4R_HIP_FUNCTION(name) decltype(&::name) name = library.symbol<decltype(&::name)>(#name)
@@ -36,7 +37,7 @@ struct HipApi {
         search(std::filesystem::path(wide(root)) / L"bin"),
         library(std::filesystem::path(wide(root)) / L"bin" / L"amdhip64_7.dll") {}
     void check(hipError_t result, const char* call) const {
-        std::printf("HIP %s -> %d (%s)\n", call, static_cast<int>(result), hipGetErrorName(result));
+        if (verbose || result != hipSuccess) std::printf("HIP %s -> %d (%s)\n", call, static_cast<int>(result), hipGetErrorName(result));
         if (result != hipSuccess) throw std::runtime_error(std::string(call) + ": " + hipGetErrorString(result));
     }
     int select_gfx1201(int requested, hipDeviceProp_t& selected) const {

tools/windows/ngx_windows_runtime.h

@@ -17,7 +17,7 @@ inline std::string env_path(const char* name) {
     return value;
 }
 inline void ngx_check(unsigned result, const char* operation) {
-    std::printf("D4R_NGX %s result=0x%08x\n", operation, result);
+    if (result != 1 || !std::getenv("D4R_QUIET_API")) std::printf("D4R_NGX %s result=0x%08x\n", operation, result);
     if (result != 1) throw std::runtime_error(std::string(operation) + " NGX=" + std::to_string(result));
 }
 inline ResourceAccess ngx_resource_access(void* parameters, const char* name, D3D12_RESOURCE_STATES fallback) {
@@ -82,6 +82,7 @@ struct Runtime {
         try {
             hipDeviceProp_t props{};
             hip.select_gfx1201(-1, props);
+            hip.verbose = cuda.verbose = !std::getenv("D4R_QUIET_API");
             const auto luid = adapter_luid(d3d);
             if (std::memcmp(&luid, props.luid, sizeof(luid))) throw std::runtime_error("D3D12/HIP LUID mismatch");
             cuda.check(cuda.cuInit(0), "cuInit(Windows runtime)");
@@ -289,8 +290,18 @@ private:
     }
     void execute_cuda(ID3D12CommandQueue* queue) {
         const auto begin = std::chrono::steady_clock::now();
+        auto stage = begin;
+        const bool profileStages = std::getenv("D4R_PROFILE_STAGES") != nullptr;
+        auto mark = [&](const char* name) {
+            if (!profileStages) return;
+            const auto now = std::chrono::steady_clock::now();
+            std::printf("D4R_STAGE name=%s cpu_ms=%.6f\n", name,
+                std::chrono::duration<double, std::milli>(now - stage).count());
+            stage = std::chrono::steady_clock::now();
+        };
         rt_->timeline->wait_input(queue);
         rt_->cuda.check(rt_->cuda.cuCtxSynchronize(), "Interop input producer completion");
+        mark("input_fence_wait");
         for (unsigned i : {0u, 1u, 2u, 4u}) if (planes_[i].texture) {
             auto& plane = planes_[i];
             void* data = plane.shared->mapped; uint64_t pitch = plane.shared->footprint.Footprint.RowPitch;
@@ -301,6 +312,7 @@ private:
             }
             plane.image->upload_device(reinterpret_cast<uintptr_t>(data), pitch);
         }
+        mark("input_conversion_array_upload");
         if (std::getenv("D4R_INTEROP_VERIFY")) {
             for (unsigned i : {0u, 1u, 2u, 4u}) if (planes_[i].texture) {
                 uint32_t sample[8]{};
@@ -315,13 +327,16 @@ private:
             }
         }
         ngx_check(rt_->evaluate(handle_, parameters_, nullptr), "CUDA EvaluateFeature");
+        mark("ngx_evaluate_host");
         // NGX can use internal nonblocking streams. The default stream alone
         // does not establish completion of those streams.
         rt_->cuda.check(rt_->cuda.cuCtxSynchronize(), "NGX all-stream completion");
+        mark("ngx_all_stream_completion");
         auto& output = planes_[3];
         output.image->download_device(reinterpret_cast<uintptr_t>(output.canonical ? output.canonical->data : output.shared->mapped),
             output.canonical ? output.canonical->pitch : output.shared->footprint.Footprint.RowPitch);
         rt_->cuda.check(rt_->cuda.cuCtxSynchronize(), "VRAM output completion");
+        mark("output_array_download");
         if (std::getenv("D4R_VALIDATE_OUTPUT")) {
             if (!rt_->pixels) rt_->pixels = std::make_unique<PixelProgram>(rt_->hip, pixel_module_path());
             const auto counts = rt_->pixels->validate(output.canonical ? output.canonical->data : output.shared->mapped,
@@ -329,9 +344,11 @@ private:
             std::printf("D4R_OUTPUT_VALIDATION elements=%llu nan=%u inf=%u diagnostics_cpu_bytes=8\n", output.desc.Width * output.desc.Height * 4, counts[0], counts[1]);
             if (counts[0] || counts[1]) throw std::runtime_error("DLSS output contains NaN/Inf");
         }
+        mark("output_diagnostic");
         if (output.canonical) rt_->pixels->convert(true, output.canonical->data, output.canonical->pitch, output.shared->mapped,
             output.shared->footprint.Footprint.RowPitch, unsigned(output.desc.Width), output.desc.Height, output.spec.storage, 3);
         rt_->timeline->signal_output(queue);
+        mark("output_conversion_fence_signal");
         std::printf("D4R_FRAME cpu_frame_copies=%u frame_age=0 interop_ngx_ms=%.3f\n", std::getenv("D4R_INTEROP_VERIFY") ? 1u : 0u,
             std::chrono::duration<double, std::milli>(std::chrono::steady_clock::now() - begin).count());
     }

tools/windows/profile_report.py

@@ -0,0 +1,92 @@
+"""Summarize native Windows d4r CPU stages and optional serializing HIP events.
+
+CPU completion time is not GPU execution time. HIP occupancy API predictions
+are not hardware counters. No bandwidth / WMMA utilization is inferred here.
+"""
+import argparse
+import collections
+import json
+import pathlib
+import re
+import statistics
+
+
+def stats(values):
+    values = sorted(values)
+    def quantile(q):
+        index = (len(values) - 1) * q
+        lower = int(index)
+        return values[lower] + (values[min(lower + 1, len(values) - 1)] - values[lower]) * (index - lower)
+    return dict(samples=len(values), total=sum(values), mean=statistics.mean(values),
+                median=statistics.median(values), p95=quantile(.95), maximum=values[-1])
+
+
+def metadata(directory):
+    result = {}
+    if directory is None:
+        return result
+    for path in sorted(directory.glob('*.txt')):
+        text = path.read_text(encoding='utf-8-sig', errors='replace')
+        for block in re.split(r'(?m)^  - \.args:', text)[1:]:
+            fields = dict(re.findall(r'(?m)^    \.(\w+):\s*([^\r\n]+)', block))
+            if 'name' in fields:
+                result[fields['name'].strip()] = {key: int(fields[key]) for key in (
+                    'wavefront_size', 'vgpr_count', 'sgpr_count', 'vgpr_spill_count', 'sgpr_spill_count',
+                    'group_segment_fixed_size', 'private_segment_fixed_size') if key in fields}
+    return result
+
+
+def report(directory, metadata_directory=None):
+    kernel_metadata = metadata(metadata_directory)
+    stages = collections.defaultdict(list)
+    kernels = collections.defaultdict(list)
+    for path in sorted(directory.glob('*.log')):
+        text = path.read_text(encoding='utf-8-sig', errors='replace')
+        for name, value in re.findall(r'D4R_STAGE name=(\S+) cpu_ms=([0-9.]+)', text):
+            stages[name].append(float(value))
+        for line in text.splitlines():
+            if not line.startswith('D4R_KERNEL_PROFILE '):
+                continue
+            fields = dict(re.findall(r'(\w+)=("[^"]+"|\S+)', line))
+            kernels[(fields['kernel'].strip('"'), fields['backend'], fields['phase'])].append(fields)
+    result = dict(cpuStages={name: stats(values) for name, values in stages.items()},
+                  kernels=[], notes=[
+                      'CPU stage times include waits and host work; they are not isolated GPU timings.',
+                      'HIP-event profiling synchronizes every sampled launch and changes scheduling.',
+                      'Occupancy is an API prediction, not a measured hardware counter.',
+                      'Bandwidth and WMMA utilization require additional supported hardware tooling.'])
+    for (name, backend, phase), rows in kernels.items():
+        item = dict(kernel=name, backend=backend, phase=phase,
+                    gpuMs=stats([float(row['gpu_ms']) for row in rows]),
+                    enqueueMs=stats([float(row['enqueue_ms']) for row in rows]),
+                    completionMs=stats([float(row['completion_ms']) for row in rows]),
+                    configurations=[dict(config) for config in sorted({tuple((key, row[key]) for key in
+                        ('grid', 'block', 'static_lds_bytes', 'dynamic_lds_bytes', 'regs', 'private_bytes',
+                         'max_threads', 'predicted_blocks_per_multiprocessor')) for row in rows})])
+        result['kernels'].append(item)
+        if backend == 'native':
+            item['elfMetadata'] = kernel_metadata.get(name + ('_prep' if phase == 'prep' else ''), {})
+    result['kernels'].sort(key=lambda row: row['gpuMs']['total'], reverse=True)
+    return result
+
+
+def main():
+    parser = argparse.ArgumentParser(description=__doc__)
+    parser.add_argument('directory', type=pathlib.Path)
+    parser.add_argument('--output', type=pathlib.Path)
+    parser.add_argument('--metadata-directory', type=pathlib.Path, help='llvm-readobj --notes output for native code objects')
+    args = parser.parse_args()
+    result = report(args.directory, args.metadata_directory)
+    if not result['cpuStages'] and not result['kernels']:
+        parser.error('no complete stage or HIP-event records found')
+    if args.output:
+        args.output.write_text(json.dumps(result, indent=2) + '\n', encoding='utf-8')
+    for name, row in result['cpuStages'].items():
+        print(f"CPU {name}: n={row['samples']} mean={row['mean']:.3f} ms median={row['median']:.3f} ms p95={row['p95']:.3f} ms")
+    for row in result['kernels']:
+        times = row['gpuMs']
+        print(f"GPU {row['kernel']} {row['backend']} {row['phase']}: n={times['samples']} mean={times['mean']:.6f} ms total={times['total']:.3f} ms")
+
+
+if __name__ == '__main__':
+    main()