Measure Windows interop GPU boundaries without added completion waits

tools/windows/d3d12_boundary_timing.h

@@ -0,0 +1,55 @@
+#pragma once
+#include "d3d12_external.h"
+#include <cstring>
+
+namespace d4r::win {
+// Diagnostic timestamps, read only after the copy slot's existing completion
+// fence. No extra queue/CPU wait, and no image readback. The interval across
+// the external fence includes HIP execution and scheduling, not just kernels.
+class BoundaryTiming {
+    ComPtr<ID3D12QueryHeap> queries_;
+    ComPtr<ID3D12Resource> readback_;
+    uint64_t ticket_ = 0;
+public:
+    explicit BoundaryTiming(ID3D12Device* device) {
+        D3D12_QUERY_HEAP_DESC query{};
+        query.Type = D3D12_QUERY_HEAP_TYPE_TIMESTAMP; query.Count = 4;
+        dx(device->CreateQueryHeap(&query, IID_PPV_ARGS(queries_.GetAddressOf())), "Boundary timestamp heap");
+        D3D12_HEAP_PROPERTIES heap{}; heap.Type = D3D12_HEAP_TYPE_READBACK;
+        D3D12_RESOURCE_DESC desc{};
+        desc.Dimension = D3D12_RESOURCE_DIMENSION_BUFFER; desc.Width = 4 * sizeof(uint64_t);
+        desc.Height = 1; desc.DepthOrArraySize = 1; desc.MipLevels = 1;
+        desc.SampleDesc.Count = 1; desc.Layout = D3D12_TEXTURE_LAYOUT_ROW_MAJOR;
+        dx(device->CreateCommittedResource(&heap, D3D12_HEAP_FLAG_NONE, &desc,
+            D3D12_RESOURCE_STATE_COPY_DEST, nullptr, IID_PPV_ARGS(readback_.GetAddressOf())), "Boundary timestamp readback");
+    }
+    void input_begin(ID3D12GraphicsCommandList* list) { list->EndQuery(queries_.Get(), D3D12_QUERY_TYPE_TIMESTAMP, 0); }
+    void input_end(ID3D12GraphicsCommandList* list) { list->EndQuery(queries_.Get(), D3D12_QUERY_TYPE_TIMESTAMP, 1); }
+    void output_begin(ID3D12GraphicsCommandList* list) { list->EndQuery(queries_.Get(), D3D12_QUERY_TYPE_TIMESTAMP, 2); }
+    void output_end(ID3D12GraphicsCommandList* list) {
+        list->EndQuery(queries_.Get(), D3D12_QUERY_TYPE_TIMESTAMP, 3);
+        list->ResolveQueryData(queries_.Get(), D3D12_QUERY_TYPE_TIMESTAMP, 0, 4, readback_.Get(), 0);
+    }
+    void submitted(uint64_t ticket) { ticket_ = ticket; }
+    // Caller has observed the slot's completion fence, including ResolveQueryData.
+    void report(ID3D12CommandQueue* queue, const void* feature) {
+        if (!ticket_) return;
+        uint64_t ticks[4]{}, frequency = 0;
+        D3D12_RANGE read{0, sizeof(ticks)}, written{0, 0};
+        void* mapped = nullptr;
+        dx(readback_->Map(0, &read, &mapped), "Map completed boundary timestamps");
+        std::memcpy(ticks, mapped, sizeof(ticks)); readback_->Unmap(0, &written);
+        dx(queue->GetTimestampFrequency(&frequency), "Boundary timestamp frequency");
+        if (!frequency || !ticks[0] || ticks[0] > ticks[1] || ticks[1] > ticks[2] || ticks[2] > ticks[3])
+            throw std::runtime_error("Invalid completed boundary timestamps");
+        const double ms = 1000. / double(frequency);
+        std::printf("D4R_GPU_BOUNDARY feature=%p ticket=%llu input_copy_ms=%.6f external_span_ms=%.6f output_copy_ms=%.6f total_ms=%.6f input_start_ticks=%llu input_end_ticks=%llu output_start_ticks=%llu output_end_ticks=%llu frequency=%llu diagnostics_cpu_bytes=32 serializing=0\n",
+            feature, (unsigned long long)ticket_, double(ticks[1] - ticks[0]) * ms,
+            double(ticks[2] - ticks[1]) * ms, double(ticks[3] - ticks[2]) * ms,
+            double(ticks[3] - ticks[0]) * ms, (unsigned long long)ticks[0],
+            (unsigned long long)ticks[1], (unsigned long long)ticks[2],
+            (unsigned long long)ticks[3], (unsigned long long)frequency);
+        ticket_ = 0;
+    }
+};
+}

tools/windows/ngx_windows_runtime.h

@@ -1,5 +1,6 @@
 #pragma once
 #include "d3d12_external.h"
+#include "d3d12_boundary_timing.h"
 #include "pixel_conversion.h"
 #include "cuda_image_api.h"
 #include "ngx_parameters.h"
@@ -201,6 +202,7 @@ class Feature {
     struct CopySlot {
         ComPtr<ID3D12CommandAllocator> input_allocator, output_allocator;
         ComPtr<ID3D12GraphicsCommandList> input, output;
+        std::unique_ptr<BoundaryTiming> timing;
         uint64_t done = 0;
     };
     struct AsyncFrame {
@@ -265,7 +267,7 @@ public:
         jobs_changed_.notify_all();
         if (worker_.joinable()) worker_.join();
         if (copy_completion_) {
-            try { wait_copies(copy_value_); }
+            try { wait_copies(copy_value_); report_completed_copies(); }
             catch (const std::exception& e) { std::fprintf(stderr, "D4R_ASYNC_CLEANUP_FAILURE %s\n", e.what()); }
         }
         std::lock_guard<std::mutex> lock(rt_->mutex); cleanup();
@@ -275,6 +277,7 @@ public:
         if (!std::getenv("D4R_ASYNC_INTEROP")) return;
         wait_worker();
         if (copy_value_) wait_copies(copy_value_);
+        report_completed_copies();
         rt_->drain_async_queue();
     }
 
@@ -347,6 +350,13 @@ public:
         }
     }
 private:
+    void report_completed_copies() {
+        if (!copy_completion_ || !queue_) return;
+        const auto completed = copy_completion_->GetCompletedValue();
+        if (completed == UINT64_MAX) throw std::runtime_error("Device removed during boundary timing");
+        for (auto& slot : copy_slots_) if (slot->timing && slot->done && slot->done <= completed)
+            slot->timing->report(queue_.Get(), this);
+    }
     void wait_copies(uint64_t value) {
         if (copy_completion_->GetCompletedValue() >= value) return;
         dx(copy_completion_->SetEventOnCompletion(value, copy_event_.value), "Async copy completion event");
@@ -359,6 +369,7 @@ private:
         if (!worker_failure_.empty()) throw std::runtime_error(worker_failure_);
     }
     CopySlot& copy_slot() {
+        report_completed_copies();
         if (!copy_completion_) {
             dx(rt_->device->CreateFence(0, D3D12_FENCE_FLAG_NONE, IID_PPV_ARGS(copy_completion_.GetAddressOf())), "Async copy fence");
             copy_event_.value = CreateEventW(nullptr, FALSE, FALSE, nullptr);
@@ -372,6 +383,7 @@ private:
             for (auto& slot : copy_slots_) if (slot->done < selected->done) selected = slot.get();
             // Bounded ownership; this wait is outside the runtime mutex.
             wait_copies(selected->done);
+            report_completed_copies();
         }
         if (selected) {
             dx(selected->input_allocator->Reset(), "Async input allocator Reset");
@@ -386,6 +398,7 @@ private:
             dx(rt_->device->CreateCommandList(0, D3D12_COMMAND_LIST_TYPE_DIRECT, allocator.Get(), nullptr, IID_PPV_ARGS(list.GetAddressOf())), "Async copy list");
         };
         create(slot->input_allocator, slot->input); create(slot->output_allocator, slot->output);
+        if (std::getenv("D4R_PROFILE_GPU_BOUNDARY")) slot->timing = std::make_unique<BoundaryTiming>(rt_->device.Get());
         copy_slots_.push_back(std::move(slot)); return *copy_slots_.back();
     }
     bool resize_needed(void* parameters) {
@@ -438,8 +451,14 @@ private:
             frame->resources.emplace_back(resource);
             d4r_ngx_set_d3d12_resource(frame->parameters, names[i], resource);
         }
-        record_inputs(slot.input.Get(), parameters); dx(slot.input->Close(), "Async input Close");
-        record_output(slot.output.Get(), parameters); dx(slot.output->Close(), "Async output Close");
+        if (slot.timing) slot.timing->input_begin(slot.input.Get());
+        record_inputs(slot.input.Get(), parameters);
+        if (slot.timing) slot.timing->input_end(slot.input.Get());
+        dx(slot.input->Close(), "Async input Close");
+        if (slot.timing) slot.timing->output_begin(slot.output.Get());
+        record_output(slot.output.Get(), parameters);
+        if (slot.timing) slot.timing->output_end(slot.output.Get());
+        dx(slot.output->Close(), "Async output Close");
         if (!worker_.joinable()) worker_ = std::thread([this] { work(); });
         ID3D12CommandList* input[] = {slot.input.Get()}, *output[] = {slot.output.Get()};
         // Allocate the job before any GPU wait is published. Worker cannot
@@ -457,6 +476,7 @@ private:
             queue->ExecuteCommandLists(1, output);
             slot.done = ++copy_value_;
             dx(queue->Signal(copy_completion_.Get(), slot.done), "Async output-copy retirement Signal");
+            if (slot.timing) slot.timing->submitted(frame->ticket.output);
         } catch (const std::exception& e) {
             jobs_.pop_back(); worker_failure_ = e.what();
             { std::lock_guard<std::mutex> order(rt_->async_mutex);

tools/windows/profile_report.py

@@ -43,6 +43,7 @@ def report(directory, metadata_directory=None):
     kernels = collections.defaultdict(list)
     hook_threads = collections.defaultdict(list)
     apis = collections.defaultdict(list)
+    boundaries = collections.defaultdict(list)
     replay = collections.defaultdict(lambda: collections.defaultdict(dict))
     for path in sorted(directory.glob('*.log')):
         data = path.read_bytes()
@@ -58,6 +59,12 @@ def report(directory, metadata_directory=None):
                 if name != 'interval_ms' or number > 0:
                     commands[kind.lower() + '.' + name].append(number)
         for line in text.splitlines():
+            if line.startswith('D4R_GPU_BOUNDARY '):
+                fields = dict(re.findall(r'(\w+)=(\S+)', line))
+                if all(key in fields for key in ('feature', 'ticket', 'input_copy_ms', 'external_span_ms',
+                                                 'output_copy_ms', 'total_ms', 'input_start_ticks',
+                                                 'output_end_ticks', 'frequency')):
+                    boundaries[fields['feature']].append(fields)
             if line.startswith('D4R_CUDA_API_PROFILE '):
                 fields = dict(re.findall(r'(\w+)=(\S+)', line))
                 if all(key in fields for key in ('api', 'calls', 'total_ms', 'max_ms', 'period_ms', 'thread')):
@@ -75,16 +82,35 @@ def report(directory, metadata_directory=None):
                   commandStages={name: stats(values) for name, values in commands.items()},
                   commandHookSamples=[],
                   cudaApi=[],
+                  gpuBoundaryStages={},
                   replayPairs=[],
                   kernels=[], notes=[
                       'CPU stage times include waits and host work; they are not isolated GPU timings.',
                       'CUDA API profiles measure host call duration without GPU events or added synchronization; they still include existing waits.',
+                      'D3D12 boundary timestamps span copies and HIP/scheduling across the external fence; they do not isolate kernel execution or measure Present.',
+                      'Boundary timestamps are read after existing completion fences; only 32 timing bytes are read, with no extra completion wait. GPU clock idle behavior can affect intervals.',
                       'Command record intervals are between NGX recording calls on one thread, not Present/FPS.',
                       'Hook estimates use random one-in-64 samples; driver timing covers generated forwarding methods only.',
                       'Hook access includes lock waits; summing threads does not measure serial frame latency or CPU execution time.',
                       '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.'])
+    boundary_stages = collections.defaultdict(list)
+    for rows in boundaries.values():
+        rows.sort(key=lambda row: int(row['ticket']))
+        for row in rows:
+            for key in ('input_copy_ms', 'external_span_ms', 'output_copy_ms', 'total_ms'):
+                boundary_stages[key].append(float(row[key]))
+        for previous, current in zip(rows, rows[1:]):
+            if int(current['ticket']) != int(previous['ticket']) + 2 or current['frequency'] != previous['frequency']:
+                continue
+            frequency = int(current['frequency'])
+            before = int(current['input_start_ticks']) - int(previous['output_end_ticks'])
+            interval = int(current['input_start_ticks']) - int(previous['input_start_ticks'])
+            if frequency > 0 and before >= 0 and interval > 0:
+                boundary_stages['between_boundaries_ms'].append(before * 1000. / frequency)
+                boundary_stages['input_interval_ms'].append(interval * 1000. / frequency)
+    result['gpuBoundaryStages'] = {name: stats(values) for name, values in boundary_stages.items()}
     for name, pairs in replay.items():
         complete = [row for row in pairs.values() if set(row) == {'control', 'candidate'}]
         if complete:
@@ -132,7 +158,7 @@ def main():
     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 any(result[key] for key in ('cpuStages', 'kernels', 'commandStages', 'commandHookSamples', 'replayPairs', 'cudaApi')):
+    if not any(result[key] for key in ('cpuStages', 'kernels', 'commandStages', 'commandHookSamples', 'replayPairs', 'cudaApi', 'gpuBoundaryStages')):
         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')
@@ -140,6 +166,8 @@ def main():
         print(f"CPU {name}: n={row['samples']} mean={row['mean']:.3f} ms median={row['median']:.3f} ms p95={row['p95']:.3f} ms")
     for name, row in result['commandStages'].items():
         print(f"COMMAND {name}: n={row['samples']} mean={row['mean']:.3f} ms median={row['median']:.3f} ms p95={row['p95']:.3f} ms")
+    for name, row in result['gpuBoundaryStages'].items():
+        print(f"GPU BOUNDARY {name}: n={row['samples']} mean={row['mean']:.3f} ms median={row['median']:.3f} ms p95={row['p95']:.3f} ms")
     for row in result['cudaApi'][:20]:
         print(f"CUDA API {row['api']} {row['thread']}: n={row['calls']} mean={row['meanMs']:.6f} ms total={row['totalMs']:.3f} ms max={row['maxMs']:.3f} ms")
     for row in result['commandHookSamples']: