diff --git a/docs/windows-game.md b/docs/windows-game.md index 84da57b..182f7b9 100644 --- a/docs/windows-game.md +++ b/docs/windows-game.md @@ -64,6 +64,10 @@ tracking/lock waits from driver calls. It is disabled in ordinary runs. `-ProfileCudaApi` aggregates existing CUDA API host durations without adding HIP events or synchronization. `-UncachedInteropLists` restores per-frame copy-list allocation for comparison with the normal safely reused lists. +`-ProfileGpuBoundary` requires `-AsyncInterop` and measures D3D12 GPU intervals +around the input/output copies and external fence. It reads 32 timestamp bytes +only after existing completion, with no extra CPU wait. Its external interval +includes HIP and scheduling; it is not an isolated transformer kernel time. The runner drains stdout/stderr concurrently as raw bytes; the earlier line-oriented PowerShell collector imposed large per-frame delays. The optional ZLUDA kernel profiler is for diagnostics only. Measurements and reproduction diff --git a/docs/windows-performance.md b/docs/windows-performance.md index 9343deb..4b49487 100644 --- a/docs/windows-performance.md +++ b/docs/windows-performance.md @@ -130,6 +130,27 @@ scans, stdout/stderr, exceptions and runtime provenance. To include the local validated output-store optimization, pass its combined native directory with `-NativeRoot`; proprietary objects remain local. +`-ProfileGpuBoundary` (requires `-AsyncInterop`) adds D3D12 timestamps before +and after the VRAM input/output copies. Resolved results are read only once +the copy slot's existing fence completes; 32 diagnostic bytes per frame are +read and no new completion wait is added. `external_span_ms` spans HIP and +host/driver scheduling across the external fence. `between_boundaries_ms` +also includes game rendering, and `input_interval_ms` is not Present timing. +These queries obey the queue's timestamp ordering and add GPU commands; they +are disabled for an ordinary FPS run. GPU clock behavior during idle can +affect intervals; no hardware occupancy is inferred. Timestamp semantics: +[Microsoft D3D12 timing](https://learn.microsoft.com/en-us/windows/win32/direct3d12/timing). + +The timestamp-enabled 4K burst/recreation gate completes twelve frames, all +finite; all six async RGB outputs still match their fresh controls exactly. +Each async mode emits all three timing records, including the final frame +at feature release. Results: `test-results/k-async-gpu-boundary-4k`. +All sixteen CTest gates pass on the rebuilt shim. Reproduce with: + +```powershell +.\scripts\windows\test-async-k.ps1 -ProfileGpuBoundary +``` + Further game coverage (HIP kernel profiling disabled, GPU output checks enabled): M at 1920x1080 completes 4833 frames, all finite. K at 3840x2160 completes 4685 frames, all finite. Neither has a backend failure, CPU image copy or an diff --git a/docs/windows-rdna4-port.md b/docs/windows-rdna4-port.md index 510b79d..364ddc5 100644 --- a/docs/windows-rdna4-port.md +++ b/docs/windows-rdna4-port.md @@ -66,6 +66,14 @@ scan is 0.380 ms. Logs: stops at its bound (`diagnostic_timeout`); there is no recorded game crash. The K performance gate remains open. +Optional `-ProfileGpuBoundary` now records D3D12 GPU timestamps around input +copies, the external-fence span and output copies. Copy-slot completion +controls query reuse/readback; only 32 timing bytes are read, with no extra +completion wait. The timestamp-enabled burst/recreate gate passes all twelve +K/4K frames with exact candidate RGB (`test-results/k-async-gpu-boundary-4k`), +and all sixteen CTest gates pass on the rebuilt shim. Game timestamps remain +the next performance diagnostic; their span includes scheduling as well as HIP. + Three ordinary K/4K async frames and three queued together without intermediate CPU completion all match their corresponding prior synchronous RGB exactly; the temporal controls differ between frames. One burst attempt times out during diff --git a/scripts/windows/test-async-k.ps1 b/scripts/windows/test-async-k.ps1 index fbff164..0ead9a8 100644 --- a/scripts/windows/test-async-k.ps1 +++ b/scripts/windows/test-async-k.ps1 @@ -3,6 +3,7 @@ param( [string]$NgxCore, [string]$DlssDll, [string]$NativeRoot, [string]$ZludaRoot, [string]$PackageRoot, [string]$Resolution = '3840x2160', + [switch]$ProfileGpuBoundary, [string]$OutputDirectory ) $ErrorActionPreference = 'Stop' @@ -19,6 +20,7 @@ New-Item -ItemType Directory -Force $OutputDirectory | Out-Null $settings = @{D4R_DIAG_BURST='1'; D4R_DIAG_RECREATE=$null; D4R_ASYNC_INTEROP=$null; D4R_ZLUDA_NATIVE_DIR=$NativeRoot; D4R_QUIET_API='1'; D4R_VALIDATE_OUTPUT='1'; D4R_PROFILE_STAGES='1'; D4R_ZLUDA_PROFILE=$null; D4R_ZLUDA_PROFILE_API=$null; + D4R_PROFILE_GPU_BOUNDARY=$(if ($ProfileGpuBoundary) { '1' } else { $null }); ZLUDA_CACHE_DIR=(Join-Path $repo 'build/zluda-cache-windows'); PYTHONPATH=(Join-Path $repo '.tools/python/vendor')} $old=@{} @@ -40,13 +42,18 @@ try { OptiScalerDll=(Join-Path $repo 'dist/optiscaler-windows-d4r/OptiScaler.dll'); OutputDirectory=$output} & (Join-Path $PSScriptRoot 'test-windows-rdna4.ps1') @arguments if ($LASTEXITCODE) { throw "Failed $variant-$mode; logs: $output" } + if ($ProfileGpuBoundary -and $variant -eq 'async') { + $stdout=Get-Content -LiteralPath (Join-Path $output 'd3d12-evaluate-preset-11.stdout.log') -Raw + $timings=[regex]::Matches($stdout, '(?m)^D4R_GPU_BOUNDARY [^\r\n]*diagnostics_cpu_bytes=32 serializing=0\r?$') + if ($timings.Count -ne 3) { throw "Expected three completed GPU timing records for $variant-$mode, found $($timings.Count)." } + } } & python.exe (Join-Path $repo 'tools/windows/frame_compare.py') --reference (Join-Path $OutputDirectory "sync-$mode") --actual (Join-Path $OutputDirectory "async-$mode") --width $width --height $height --exact | Tee-Object -FilePath (Join-Path $OutputDirectory "$mode-comparison.log") if ($LASTEXITCODE) { throw "Async $mode output mismatch" } } @{passed=$true; architecture='gfx1201'; preset=11; resolution=$Resolution; - modes=@('burst','recreate'); framesPerMode=3; exactRgb=$true} | + modes=@('burst','recreate'); framesPerMode=3; exactRgb=$true; gpuBoundaryTiming=[bool]$ProfileGpuBoundary} | ConvertTo-Json | Set-Content -LiteralPath (Join-Path $OutputDirectory 'validation.json') -Encoding UTF8 Write-Host "PASS asynchronous K burst/recreate: $OutputDirectory" } finally { diff --git a/scripts/windows/windows-game.ps1 b/scripts/windows/windows-game.ps1 index 18a6e3d..f585bc0 100644 --- a/scripts/windows/windows-game.ps1 +++ b/scripts/windows/windows-game.ps1 @@ -13,6 +13,7 @@ param( [switch]$ProfileKernels, [switch]$ProfileCommandHooks, [switch]$ProfileCudaApi, + [switch]$ProfileGpuBoundary, [switch]$UncachedInteropLists, [switch]$AsyncInterop, [switch]$VerboseRuntime, @@ -21,6 +22,7 @@ param( [string]$OutputDirectory ) $ErrorActionPreference = 'Stop' +if ($ProfileGpuBoundary -and !$AsyncInterop) { throw '-ProfileGpuBoundary requires -AsyncInterop.' } $package = [IO.Path]::GetFullPath($PSScriptRoot) $GameExe = (Get-Item -LiteralPath $GameExe -ErrorAction Stop).FullName $game = Split-Path $GameExe @@ -182,6 +184,7 @@ $settings = @{ D4R_ZLUDA_PROFILE=$(if ($ProfileKernels) { '1' } else { $null }); D4R_PROFILE_COMMAND_HOOKS=$(if ($ProfileCommandHooks) { '1' } else { $null }); D4R_ZLUDA_PROFILE_API=$(if ($ProfileCudaApi) { '1' } else { $null }); + D4R_PROFILE_GPU_BOUNDARY=$(if ($ProfileGpuBoundary) { '1' } else { $null }); D4R_DISABLE_INTEROP_LIST_CACHE=$(if ($UncachedInteropLists) { '1' } else { $null }); D4R_ASYNC_INTEROP=$(if ($AsyncInterop) { '1' } else { $null }); D4R_DIAG_DIR=$OutputDirectory; ZLUDA_LOG_DIR=(Join-Path $OutputDirectory 'zluda-trace'); diff --git a/tools/windows/d3d12_boundary_timing.h b/tools/windows/d3d12_boundary_timing.h new file mode 100644 index 0000000..f79efa3 --- /dev/null +++ b/tools/windows/d3d12_boundary_timing.h @@ -0,0 +1,55 @@ +#pragma once +#include "d3d12_external.h" +#include + +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 queries_; + ComPtr 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; + } +}; +} diff --git a/tools/windows/ngx_windows_runtime.h b/tools/windows/ngx_windows_runtime.h index 11ffd8e..266ac24 100644 --- a/tools/windows/ngx_windows_runtime.h +++ b/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 input_allocator, output_allocator; ComPtr input, output; + std::unique_ptr 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 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(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 order(rt_->async_mutex); diff --git a/tools/windows/profile_report.py b/tools/windows/profile_report.py index de088ec..212d5f1 100644 --- a/tools/windows/profile_report.py +++ b/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']: