[Qiong Wu (qiowu) (DingmaomaoBJTU)]

Problem

winml perf --runtime winml-runtime --backend cgc reports host-side feed/infer/fetch latency. That interval includes input binding, Runtime execution and output access; it cannot tell how long the GPU spends executing the inference commands.

This PR adds --etw-tracing <new-directory>. It enables the Runtime CGC GPU timestamp provider, collects its events and reports GPU inference-body time separately from the existing CPU latency statistics. The option names the collection mechanism, matching the existing --op-tracing naming style. This initial implementation supports the Runtime CGC GPU path, not arbitrary ETW providers.

Usage and output

Run from a Windows terminal with ETW permissions and a compatible development Runtime:

winml perf -m C:modelsyolo11n.onnx `
  --runtime winml-runtime --backend cgc --device gpu `
  --iterations 1000 --warmup 10 `
  --etw-tracing C:perfyolo11n-001

The trace directory must not already exist. --iterations and --warmup retain their existing CLI meanings; enabling tracing does not change their defaults. The example explicitly requests 1000 measured Runs and excludes the first 10 warmup Runs.

The console gains a separate GPU execution time (ms; inference body) section with Mean, P50, P95, valid/expected Run counts, ETW loss and recorded-path exclusions. Existing Latency and throughput output retain their CPU-side meaning.

The regular benchmark JSON gains an optional gpu_execution object containing:

• source: runtime-cgc-etw, metric: inference-body, and unit: ms.
• mean_ms, median_ms, p95_ms, and per-Run samples_ms.
• Expected/valid/recorded/replay-miss/replay-hit counts, missing Runs, outside-window submissions and lost events.
• Aggregation description and the trace directory.

Without --etw-tracing, the new JSON object is omitted and no ETW session is started.

Collection and attribution

1. Start a uniquely named logman ETW session before the benchmark runs. Enable Microsoft.Windows.AI.WindowsMLRuntimeCore.GpuTiming at level 4, keyword 0x1, and Microsoft.Windows.AI.WindowsMLRuntimeCore at level 4, keyword 0x2.
2. Record QPC start/end and thread ID around each measured Python Pipeline.run() call. Warmup calls do not enter the measured-window list.
3. Release benchmark Runtime sessions while tracing remains active. The Runtime may emit GPU samples at the next submission or during teardown, after the GPU fence completes.
4. Stop the owned ETW session, then decode the ETL with tracerpt. Raw-QPC events and loss summary use separate invocations because tracerpt rejects combining -rts and -summary.
5. Match each measured window to exactly one PipelineRunStart using PID, TID and QPC. Require its successful matching PipelineRunStop, then associate GPU submissions by RunId. Event delivery order does not determine iteration attribution.

For each accepted submission, GPU body milliseconds are (BodyEnd - BodyStart) * 1000 / TimestampFrequency. Integer timestamps are subtracted before conversion to floating point.

Only replay paths 1 and 2 contribute: those timestamps bracket inference commands without surrounding upload/readback. Recorded path 0 includes transfers and is counted but excluded. Statistics summarize one measured window; this is not the Runtime comparison harness's median of per-round medians.

Evidence and failure behavior

GPU statistics are persisted only in the regular benchmark JSON (gpu_execution). No separate GPU result JSON is written. The summary pass discards its duplicate event dump using -o NUL. The collection directory retains:

File	Contents
trace.etl	Original ETW capture
events.xml	Decoded events with raw QPC timestamps

| summary.xml | Tracerpt text summary, including event loss |
| windows.json | Process ID and measured Python call windows |

| capture.log | logman/tracerpt output |

The analyzer rejects lost events, missing samples, ambiguous Run matches, unsuccessful/missing Run stops, duplicate measured Run IDs, unknown paths, invalid timestamps/frequency, no replay samples and multiple submissions per measured Run. It does not substitute CPU latency when GPU timing is unavailable. Trace artifacts remain available for diagnosis.

Validation

• Five standalone protocol tests pass: reordered/delayed delivery, process isolation, recorded-path exclusion, large timestamp precision, invalid/incomplete data and duplicate Run IDs.
• Real-capture replay checks verify analysis, JSON serialization, GPU console output and separate tracerpt argument sets.
• Local RTX 5090 D runs completed through WinML CLI with a development Runtime:
  • ResNet-50, batch 1: 20/20 measured replay samples, zero ETW loss; GPU P50 0.754560 ms.
  • YOLO11n: 1000/1000 measured replay samples, zero missing/lost events; GPU P50 0.777632 ms and P95 0.780674 ms. That run used 5 warmup iterations.
• CLI help and standalone tests passed after renaming the flag to --etw-tracing; the local TAEF launcher was rebuilt with the new name. The recorded hardware runs preceded this flag-only rename.
• git diff --check passed. Targeted pytest suite: 162 passed (GPU protocol and perf CLI tests). Full src/tests Ruff passed; mypy passed for the collector, analyzer, perf command and Runtime session. Latest-head CI is running.

Dependencies and remaining limitations

• Requires the Runtime CGC GPU timing events introduced by windows-ml PR 17256037, plus compatible Python bindings/native DLLs. Updating CLI alone does not update that Runtime payload.
• The caller must have ETW access. The separately tested Te.Service/benchmark-agent launcher provides elevation externally and is not included in this CLI PR.
• Loss-summary parsing currently recognizes English tracerpt text. Unrecognized/localized output fails explicitly.
• This version accepts local ONNX/MLIR, Runtime CGC and GPU selection; monitor, operator tracing, module and device-comparison combinations are rejected. Multi-submission Run aggregation is not implemented.
• The locally tested Runtime Python projection includes a separate fix to avoid mutating shared ctypes Python buffer-function signatures, which otherwise can break Click's Windows console error output. That Runtime fix is outside this PR.
• Models, binary payloads and captured traces are excluded from the commit.

Expanded tracing profile

The current implementation additionally enables Runtime/ORT/WIL/TIP and DxgKrnl diagnostics at verbose level with all keywords. Unavailable optional providers are recorded in the result; the core timing providers remain required. No kernel stacks or capture-state callbacks are enabled. This diagnostic profile adds CPU/memory/disk overhead and should not be compared directly with untraced baseline latency. Latest YOLO11n run received 1000/1000 samples and zero loss (716653 total ETW events).

[Zhipeng Wang (timenick)]

Re-reviewed 47f166e. All three previously reported P2 issues are addressed: bounded-memory XML streaming, ETW session cleanup after log failures, and pytest-discoverable replay coverage. Focused validation: 14 tests passed, including the prior cleanup and memory reproductions; Ruff and all current-head CI checks passed. Live ETW capture was not verified locally. One non-blocking documentation correction is noted inline.

🤖 Generated with Codex