From a897d4fda2daa8a85e8329f9afe48026ac625a99 Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" Date: Thu, 13 Aug 2026 10:35:05 +0800 Subject: [PATCH 1/2] Align GenAI perf metrics schema --- docs/commands/perf.md | 22 +- docs/samples/qwen3-genai-bundle.md | 7 +- src/winml/modelkit/commands/_perf_genai.py | 702 +++++++++++++++----- src/winml/modelkit/commands/perf.py | 16 +- src/winml/modelkit/session/genai_session.py | 76 ++- tests/unit/commands/test_perf_cli.py | 92 +++ tests/unit/commands/test_perf_genai.py | 355 +++++++--- tests/unit/session/test_genai_session.py | 105 +-- 8 files changed, 1059 insertions(+), 316 deletions(-) diff --git a/docs/commands/perf.md b/docs/commands/perf.md index a79329ea6..318774340 100644 --- a/docs/commands/perf.md +++ b/docs/commands/perf.md @@ -36,7 +36,7 @@ $ winml perf [options] | `--use-cache/--no-use-cache` | | flag | `true` | Reuse persistent model build artifacts. `--no-use-cache` performs a fresh build in a temporary folder and discards it after benchmarking. | | `--rebuild/--no-rebuild` | | flag | `false` | Force model rebuild even if a cached artifact already exists. | | `--module` | | `TEXT` | — | PyTorch module class name for per-module benchmarking (e.g., `BertAttention`). Builds and times each matching instance separately. See [Load and export](../concepts/load-and-export.md). | -| `--monitor/--no-monitor` | | flag | `false` | Show a live NPU/CPU utilization chart while the benchmark runs and include hardware metrics in the JSON report. | +| `--monitor/--no-monitor` | | flag | `false` | Show a live NPU/CPU utilization chart while the benchmark runs and include hardware metrics in the JSON report. With `--runtime winml-genai`, the monitor wraps the genai load + generation benchmark. | | `--op-tracing` | | `basic\|detail` | — | Enable operator-level profiling. QNN detail tracing requires an EPContext model; a raw ONNX input is detected and compiled automatically with the required profiling options. | | `--compile` / `--no-compile` | | flag | `false` | Compile the model to EPContext binaries during build. QNN detail op-tracing enables this automatically for a raw ONNX input unless `--no-compile` or `--skip-build` was explicitly specified. For `--runtime winml-genai` on the NPU, `--compile` pre-compiles each QNN stage (in an isolated subprocess) before generation. | | `--compile-timeout` | | `INTEGER` | `300` | *(winml-genai)* Max seconds to compile each EPContext stage before falling back to the original ONNX. Requires `--compile`. | @@ -48,6 +48,26 @@ $ winml perf [options] `winml perf` loads the model through `WinMLAutoModel` — accepting both HuggingFace IDs and local ONNX files — then generates random input tensors from the model's I/O configuration. It runs the specified number of warm-up iterations (excluded from statistics) followed by the timed iterations, collecting per-sample latency. The final report includes mean, min, max, P50, P90, P95, P99, standard deviation, and throughput in samples per second. When `--monitor` is active, a hardware polling loop runs in parallel and records NPU / GPU utilization, CPU usage, and device memory alongside the timing data. +Both runtime reports include `schema_version: 2` and a `benchmark_info.runtime` discriminator (`winml` or `winml-genai`). Shared metadata such as `model_id`, `running_model_path`, `device`, `ep`, `iterations`, `warmup`, and `timestamp` uses the same field names where the concepts overlap; GenAI also keeps `bundle_dir` because the runnable artifact is a bundle directory. + +When `--memory` is enabled, both `winml` and `winml-genai` reports use the same `memory` field names for shared concepts: RSS baseline, after-compile/load, after-inference, peak, model-load delta, inference/generation delta, and total delta; VRAM local/shared baseline, after-compile/load, after-inference, peak, model-load delta, inference/generation delta, and total delta. + +With `--runtime winml-genai`, `winml perf` benchmarks the onnxruntime-genai decoder pipeline rather than a single `session.run()`. The JSON report uses a phase-based schema: `load` contains startup spans, `requests` contains one warmup or timed generation sample per request, `aggregate` summarizes timed requests only, `memory` contains optional RAM/VRAM deltas, and `hw_monitor` contains optional monitor output. The optional `memory` and `hw_monitor` top-level names match the classic `winml` perf report; GenAI keeps `load`/`requests`/`aggregate` instead of classic `latency_ms`/`throughput` because generation has distinct prompt, first-token, and decode phases. + +### GenAI metric definitions + +| Core metric | JSON field(s) | Definition | +|---|---|---| +| Model Load Time | `load.session_load_duration_ms`, `load.native_load_duration_ms` | `session_load_duration_ms` is the outer `GenaiSession.load()` wall-clock span. `native_load_duration_ms` is the onnxruntime-genai `og.Config` + `og.Model` + `og.Tokenizer` span. | +| Weight Upload Time | `load.weight_upload_duration_ms`, `load.weight_upload_estimate_duration_ms` | Exact upload telemetry is `null` today because onnxruntime-genai does not expose it. The estimate is `model_create_duration_ms` and is labeled by `weight_upload_estimate_source`. | +| Cold Start Time | `aggregate.cold_start_ttft_duration_ms`, `aggregate.cold_start_total_duration_ms` | Load plus the first request's TTFT, or load plus the first request's total request duration. | +| Warm Start Time / Latency | `aggregate.request_duration_ms` | Timed-request full duration after warmups: template + tokenization + generator creation + model compute + sequence fetch + detokenization. | +| TTFT | `requests[].model_ttft_duration_ms`, `requests[].request_ttft_duration_ms`, `aggregate.*ttft*` | Model TTFT is prefill + first-token compute. Request TTFT also includes template, tokenization, and generator creation. | +| Prefill TPS | `requests[].prefill_tokens_per_second`, `aggregate.prefill_tokens_per_second` | Prompt tokens divided by `prefill_duration_ms`. | +| Decode TPS | `requests[].steady_state_decode_tokens_per_second`, `aggregate.steady_state_decode_tokens_per_second` | Tokens after the first divided by the sum of per-token decode durations after the first. | +| RAM Usage | `memory.rss_*` | Classic-compatible RSS fields such as `rss_baseline_mb`, `rss_after_compile_mb`, `rss_after_inference_mb`, `rss_model_load_delta_mb`, `rss_inference_delta_mb`, and `rss_total_delta_mb`. GenAI also emits `rss_peak_mb`. Requires `--memory`. | +| VRAM Usage | `memory.vram_*` | Classic-compatible adapter memory fields such as `vram_local_after_inference_mb`, `vram_shared_after_inference_mb`, load/inference/total deltas, plus GenAI extras for baseline, after-compile, and peak. Requires `--memory`. | + ## Examples Basic benchmark on the best available device: diff --git a/docs/samples/qwen3-genai-bundle.md b/docs/samples/qwen3-genai-bundle.md index 1eaa833c7..f33b0c5f8 100644 --- a/docs/samples/qwen3-genai-bundle.md +++ b/docs/samples/qwen3-genai-bundle.md @@ -113,8 +113,11 @@ winml perf -m out/qwen3-bundle --runtime winml-genai --device npu --compile \ `--device npu` selects the QNN execution provider: `winml perf` registers the WinML QNN EP and the bundle's `context` and `iterator` stages run on the NPU HTP, while the CPU companions handle the embedding lookup and vocab projection. The command reports -time-to-first-token (prefill) and decode throughput, and writes a results JSON under -`~/.cache/winml/perf/`. +canonical GenAI phases: session/native load, best-effort weight-upload estimate, +cold-start TTFT/total, request/model TTFT, prefill throughput, steady-state decode +throughput, full request latency, optional RAM/VRAM deltas, and a results JSON under +`~/.cache/winml/perf/`. Exact weight-upload telemetry is currently `null` because +onnxruntime-genai does not expose it; the estimate is labeled in JSON. !!! tip "One command from a model id (auto-build)" `winml perf --runtime winml-genai` also accepts a HuggingFace **model id** directly. diff --git a/src/winml/modelkit/commands/_perf_genai.py b/src/winml/modelkit/commands/_perf_genai.py index 7ca1b07cf..0b4549fae 100644 --- a/src/winml/modelkit/commands/_perf_genai.py +++ b/src/winml/modelkit/commands/_perf_genai.py @@ -8,9 +8,9 @@ :class:`GenaiSession`. Unlike the single-shot WinML path (which times each ``session.run()`` call), decoder pipelines split into a **prefill** phase (prompt -> first token) and a **decode** phase (subsequent tokens), so this -module reports LLM-style metrics: time-to-first-token (TTFT), prefill latency, -decode throughput (tokens/sec), time-per-output-token (TPOT), and total -generation time. +module reports LLM-style metrics: startup/cold-start spans, time-to-first-token (TTFT), +prefill throughput, decode throughput (tokens/sec), time-per-output-token +(TPOT), warm-start latency, and total generation time. Timing is captured inside :meth:`GenaiSession.generate_timed` at the onnxruntime-genai call boundaries (``append_tokens`` = prefill, each @@ -25,8 +25,10 @@ from __future__ import annotations +import gc import json import logging +import time from dataclasses import dataclass, field from datetime import datetime, timezone from pathlib import Path @@ -40,7 +42,6 @@ GenaiSession, GenaiSessionError, GenerationConfig, - HWMonitor, short_ep_name, ) from ..utils.constants import ( @@ -51,6 +52,8 @@ if TYPE_CHECKING: + from collections.abc import Callable + from rich.console import Console from ..utils.constants import EPName @@ -154,6 +157,155 @@ def _percentile(sorted_xs: list[float], p: float) -> float: return sorted_xs[idx] +def _stats(values: list[float]) -> dict[str, float]: + """Return the percentile summary shape used by perf JSON blocks.""" + sorted_values = sorted(values) + mean = _mean(values) + variance = _mean([(value - mean) ** 2 for value in values]) if values else 0.0 + return { + "mean": mean, + "std": variance**0.5, + "min": min(values) if values else 0.0, + "max": max(values) if values else 0.0, + "p50": _percentile(sorted_values, 50), + "p90": _percentile(sorted_values, 90), + "p95": _percentile(sorted_values, 95), + "p99": _percentile(sorted_values, 99), + } + + +def _round_stats(values: dict[str, float]) -> dict[str, float]: + """Round a stats block for JSON output.""" + return {key: round(value, 3) for key, value in values.items()} + + +def _get_rss_mb() -> float: + """Return current process RSS in MB.""" + from ..session.monitor.memory_tracker import get_rss_mb + + return get_rss_mb() + + +def _get_vram_mb(adapter_luid: str | None) -> tuple[float, float]: + """Return current process device-memory usage as local/shared MB.""" + from ..session.monitor.memory_tracker import get_vram_mb + + return get_vram_mb(adapter_luid) + + +def _resolve_adapter_luid(device: str, ep: EPNameOrAlias | None) -> str | None: + """Resolve the adapter LUID used for best-effort process VRAM sampling.""" + if device == "cpu": + return None + + ep_name = normalize_ep_name(ep) if ep is not None else None + kinds = [device] if device in ("npu", "gpu") else ["npu", "gpu"] + try: + from ..sysinfo.pdh_adapters import resolve_adapter_luid + + for kind in kinds: + luid = resolve_adapter_luid(kind, ep_name=ep_name) + if luid: + return luid + except Exception: + logger.debug("Could not resolve adapter LUID for genai memory tracking", exc_info=True) + return None + + +@dataclass +class _MemorySnapshot: + """Point-in-time process RAM and device-memory usage.""" + + rss_mb: float = 0.0 + vram_local_mb: float = 0.0 + vram_shared_mb: float = 0.0 + + +class _GenaiMemoryTracker: + """Best-effort process memory tracking for the genai benchmark phases.""" + + def __init__(self, *, device: str, ep: EPNameOrAlias | None) -> None: + self._adapter_luid = _resolve_adapter_luid(device, ep) + self._baseline = _MemorySnapshot() + self._after_load = _MemorySnapshot() + self._after_benchmark = _MemorySnapshot() + + def _snapshot(self) -> _MemorySnapshot: + gc.collect() + rss = _get_rss_mb() + local, shared = _get_vram_mb(self._adapter_luid) + return _MemorySnapshot(rss_mb=rss, vram_local_mb=local, vram_shared_mb=shared) + + def record_baseline(self) -> None: + self._baseline = self._snapshot() + + def record_after_load(self) -> None: + self._after_load = self._snapshot() + + def record_after_benchmark(self) -> None: + self._after_benchmark = self._snapshot() + + @staticmethod + def _delta(after: float, before: float) -> float: + return round(after - before, 2) + + def to_dict(self) -> dict[str, float]: + baseline = self._baseline + after_load = self._after_load + after_benchmark = self._after_benchmark + return { + "rss_baseline_mb": round(baseline.rss_mb, 2), + "rss_after_compile_mb": round(after_load.rss_mb, 2), + "rss_after_inference_mb": round(after_benchmark.rss_mb, 2), + "rss_peak_mb": round( + max(baseline.rss_mb, after_load.rss_mb, after_benchmark.rss_mb), 2 + ), + "rss_model_load_delta_mb": self._delta(after_load.rss_mb, baseline.rss_mb), + "rss_inference_delta_mb": self._delta(after_benchmark.rss_mb, after_load.rss_mb), + "rss_total_delta_mb": self._delta(after_benchmark.rss_mb, baseline.rss_mb), + "vram_local_baseline_mb": round(baseline.vram_local_mb, 2), + "vram_shared_baseline_mb": round(baseline.vram_shared_mb, 2), + "vram_local_after_compile_mb": round(after_load.vram_local_mb, 2), + "vram_shared_after_compile_mb": round(after_load.vram_shared_mb, 2), + "vram_local_after_inference_mb": round(after_benchmark.vram_local_mb, 2), + "vram_shared_after_inference_mb": round(after_benchmark.vram_shared_mb, 2), + "vram_local_peak_mb": round( + max( + baseline.vram_local_mb, + after_load.vram_local_mb, + after_benchmark.vram_local_mb, + ), + 2, + ), + "vram_shared_peak_mb": round( + max( + baseline.vram_shared_mb, + after_load.vram_shared_mb, + after_benchmark.vram_shared_mb, + ), + 2, + ), + "vram_local_model_load_delta_mb": self._delta( + after_load.vram_local_mb, baseline.vram_local_mb + ), + "vram_shared_model_load_delta_mb": self._delta( + after_load.vram_shared_mb, baseline.vram_shared_mb + ), + "vram_local_inference_delta_mb": self._delta( + after_benchmark.vram_local_mb, after_load.vram_local_mb + ), + "vram_shared_inference_delta_mb": self._delta( + after_benchmark.vram_shared_mb, after_load.vram_shared_mb + ), + "vram_local_total_delta_mb": self._delta( + after_benchmark.vram_local_mb, baseline.vram_local_mb + ), + "vram_shared_total_delta_mb": self._delta( + after_benchmark.vram_shared_mb, baseline.vram_shared_mb + ), + } + + # ============================================================================= # Data classes # ============================================================================= @@ -164,6 +316,7 @@ class GenaiPerfConfig: """Resolved request for a genai generation benchmark.""" bundle_dir: Path + model_id: str | None = None ep: EPNameOrAlias | None = None device: str = "auto" prompt: str = _DEFAULT_PROMPT @@ -175,74 +328,143 @@ class GenaiPerfConfig: compile_timeout: int = 300 monitor: bool = False context_length: int | None = None + memory: bool = False output_path: Path | None = None @dataclass -class _RunSample: - """Timing captured for a single full generation.""" +class _RequestSample: + """Canonical timing captured for one generation request.""" + + kind: str + index: int + prompt_tokens: int + generated_tokens: int + template_duration_ms: float + tokenization_duration_ms: float + generator_create_duration_ms: float + prefill_duration_ms: float + first_token_duration_ms: float + decode_token_durations_ms: list[float] + sequence_fetch_duration_ms: float + detokenization_duration_ms: float + + @property + def model_ttft_duration_ms(self) -> float: + """Model-only TTFT: prefill + first generated token.""" + return self.prefill_duration_ms + self.first_token_duration_ms + + @property + def request_ttft_duration_ms(self) -> float: + """Request-level TTFT from prompt preparation through first token.""" + return ( + self.template_duration_ms + + self.tokenization_duration_ms + + self.generator_create_duration_ms + + self.model_ttft_duration_ms + ) + + @property + def response_eval_duration_ms(self) -> float: + """Time spent generating response tokens, including the first token.""" + return self.first_token_duration_ms + sum(self.decode_token_durations_ms) + + @property + def model_compute_duration_ms(self) -> float: + """Model compute: prefill + first token + steady-state decode.""" + return self.prefill_duration_ms + self.response_eval_duration_ms + + @property + def request_duration_ms(self) -> float: + """Full warm request duration from prompt prep to response text ready.""" + return ( + self.template_duration_ms + + self.tokenization_duration_ms + + self.generator_create_duration_ms + + self.model_compute_duration_ms + + self.sequence_fetch_duration_ms + + self.detokenization_duration_ms + ) - ttft_ms: float - prefill_ms: float - total_ms: float - decode_tokens_per_sec: float - tpot_ms: float - n_tokens: int + @property + def prefill_tokens_per_second(self) -> float: + """Prompt-processing throughput.""" + seconds = self.prefill_duration_ms / 1000.0 + return self.prompt_tokens / seconds if seconds > 0 else 0.0 + + @property + def steady_state_decode_tokens_per_second(self) -> float: + """Decode throughput excluding the first generated token.""" + total_ms = sum(self.decode_token_durations_ms) + return len(self.decode_token_durations_ms) / (total_ms / 1000.0) if total_ms > 0 else 0.0 + + @property + def response_eval_tokens_per_second(self) -> float: + """Response-token throughput including the first generated token.""" + seconds = self.response_eval_duration_ms / 1000.0 + return self.generated_tokens / seconds if seconds > 0 else 0.0 + + @property + def steady_state_tpot_ms(self) -> float: + """Mean per-token latency for tokens after the first.""" + return _mean(self.decode_token_durations_ms) + + def to_dict(self) -> dict[str, Any]: + """Convert to the canonical JSON request sample shape.""" + return { + "kind": self.kind, + "index": self.index, + "prompt_tokens": self.prompt_tokens, + "generated_tokens": self.generated_tokens, + "template_duration_ms": round(self.template_duration_ms, 3), + "tokenization_duration_ms": round(self.tokenization_duration_ms, 3), + "generator_create_duration_ms": round(self.generator_create_duration_ms, 3), + "prefill_duration_ms": round(self.prefill_duration_ms, 3), + "first_token_duration_ms": round(self.first_token_duration_ms, 3), + "decode_token_durations_ms": [ + round(value, 3) for value in self.decode_token_durations_ms + ], + "sequence_fetch_duration_ms": round(self.sequence_fetch_duration_ms, 3), + "detokenization_duration_ms": round(self.detokenization_duration_ms, 3), + "request_ttft_duration_ms": round(self.request_ttft_duration_ms, 3), + "model_ttft_duration_ms": round(self.model_ttft_duration_ms, 3), + "response_eval_duration_ms": round(self.response_eval_duration_ms, 3), + "model_compute_duration_ms": round(self.model_compute_duration_ms, 3), + "request_duration_ms": round(self.request_duration_ms, 3), + "prefill_tokens_per_second": round(self.prefill_tokens_per_second, 2), + "steady_state_decode_tokens_per_second": round( + self.steady_state_decode_tokens_per_second, 2 + ), + "response_eval_tokens_per_second": round(self.response_eval_tokens_per_second, 2), + "steady_state_tpot_ms": round(self.steady_state_tpot_ms, 3), + } @dataclass class GenaiBenchmarkResult: - """Aggregated results from a genai generation benchmark.""" + """Canonical results from a genai generation benchmark.""" config: GenaiPerfConfig timestamp: str = field(default_factory=lambda: datetime.now(timezone.utc).isoformat()) - - # Generation shape prompt_tokens: int = 0 generated_tokens: int = 0 context_length: int | None = None - - # EP that actually took effect (from GenaiSession.effective_ep): the override - # alias when it applied, or None to mean "config" (no override, or an - # override that matched no stage). Reported instead of the *requested* ep so - # the report never claims an EP that never applied. effective_ep: str | None = None effective_device: str | None = None - - # Time to first token (prefill + first decode), milliseconds - ttft_mean_ms: float = 0.0 - ttft_min_ms: float = 0.0 - ttft_max_ms: float = 0.0 - ttft_p50_ms: float = 0.0 - ttft_p90_ms: float = 0.0 - ttft_p95_ms: float = 0.0 - ttft_p99_ms: float = 0.0 - - # Prefill / prompt-processing phase (og append_tokens), milliseconds - prefill_mean_ms: float = 0.0 - - # Decode phase - decode_tokens_per_sec: float = 0.0 - avg_token_latency_ms: float = 0.0 - # Time per output token — steady-state decode (og generate_next_token), ms - tpot_mean_ms: float = 0.0 - - # Whole generation (prefill + all decode), milliseconds - total_generation_mean_ms: float = 0.0 - - # Per-iteration samples (warmup excluded) - raw_ttft_ms: list[float] = field(default_factory=list) - raw_prefill_ms: list[float] = field(default_factory=list) - raw_decode_tokens_per_sec: list[float] = field(default_factory=list) - raw_tpot_ms: list[float] = field(default_factory=list) - raw_total_ms: list[float] = field(default_factory=list) + load: dict[str, float | str | None] = field(default_factory=dict) + requests: list[_RequestSample] = field(default_factory=list) + aggregate: dict[str, Any] = field(default_factory=dict) + memory_profile: dict[str, float] | None = None hw_monitor: dict[str, Any] | None = None def to_dict(self) -> dict[str, Any]: """Convert to a JSON-serializable dictionary.""" - result = { + result: dict[str, Any] = { + "schema_version": 2, "benchmark_info": { "runtime": RUNTIME_TYPE, + "model_id": self.config.model_id or str(self.config.bundle_dir), + "running_model_path": str(self.config.bundle_dir), "bundle_dir": str(self.config.bundle_dir), "ep": self.effective_ep or "config", "device": self.config.device, @@ -260,34 +482,31 @@ def to_dict(self) -> dict[str, Any]: "context_length": self.context_length, "timestamp": self.timestamp, }, - "ttft_ms": { - "mean": round(self.ttft_mean_ms, 3), - "min": round(self.ttft_min_ms, 3), - "max": round(self.ttft_max_ms, 3), - "p50": round(self.ttft_p50_ms, 3), - "p90": round(self.ttft_p90_ms, 3), - "p95": round(self.ttft_p95_ms, 3), - "p99": round(self.ttft_p99_ms, 3), - }, - "prefill_ms": {"mean": round(self.prefill_mean_ms, 3)}, - "decode": { - "tokens_per_sec": round(self.decode_tokens_per_sec, 2), - "avg_token_latency_ms": round(self.avg_token_latency_ms, 3), - "tpot_ms": round(self.tpot_mean_ms, 3), - }, - "total_generation_ms": {"mean": round(self.total_generation_mean_ms, 3)}, - "raw": { - "ttft_ms": [round(v, 3) for v in self.raw_ttft_ms], - "prefill_ms": [round(v, 3) for v in self.raw_prefill_ms], - "decode_tokens_per_sec": [round(v, 2) for v in self.raw_decode_tokens_per_sec], - "tpot_ms": [round(v, 3) for v in self.raw_tpot_ms], - "total_ms": [round(v, 3) for v in self.raw_total_ms], + "load": { + key: round(value, 3) if isinstance(value, float) else value + for key, value in self.load.items() }, + "requests": [sample.to_dict() for sample in self.requests], + "aggregate": self._round_aggregate(), } - if self.hw_monitor is not None: + if self.memory_profile: + result["memory"] = self.memory_profile + if self.hw_monitor: result["hw_monitor"] = self.hw_monitor return result + def _round_aggregate(self) -> dict[str, Any]: + """Round aggregate statistics while preserving counters and flags.""" + rounded: dict[str, Any] = {} + for key, value in self.aggregate.items(): + if isinstance(value, dict): + rounded[key] = _round_stats(value) + elif isinstance(value, float): + rounded[key] = round(value, 3) + else: + rounded[key] = value + return rounded + # ============================================================================= # Benchmark engine @@ -303,14 +522,13 @@ class GenaiPerfBenchmark: ``None`` a :class:`GenaiSession` is constructed from ``config``. Note: - The prompt is pre-encoded once (via :meth:`GenaiSession.encode`, which - also loads the model) so model-load and tokenization costs are - excluded from the timed generations. Each timed generation is driven - by :meth:`GenaiSession.generate_timed`, which captures wall-clock spans - at the onnxruntime-genai call boundaries (``append_tokens`` = prefill, - each ``generate_next_token`` = one decode step), so TTFT and TPOT - reflect model compute rather than generator-construction or - detokenization overhead. + The session is loaded explicitly so model-load and prompt-preparation + spans can be reported separately from warm-start generation. Each timed + generation is driven by :meth:`GenaiSession.generate_timed`, which + captures wall-clock spans at the onnxruntime-genai call boundaries + (``append_tokens`` = prefill, each ``generate_next_token`` = one decode + step), so TTFT and TPOT reflect model compute rather than + generator-construction or detokenization overhead. """ def __init__( @@ -318,10 +536,11 @@ def __init__( config: GenaiPerfConfig, *, session: GenaiSession | None = None, + clock: Callable[[], float] = time.perf_counter, ) -> None: self._config = config self._session = session - self._prompt_token_ids: list[int] = [] + self._clock = clock self._generation_count = 0 def _build_session(self) -> GenaiSession: @@ -379,16 +598,49 @@ def _prompt_text(self, session: GenaiSession) -> str: def run(self) -> GenaiBenchmarkResult: """Execute the benchmark and return aggregated metrics.""" + if self._config.monitor: + hw_monitor = self._build_hw_monitor() + if hw_monitor is not None: + with hw_monitor as hw: + result = self._run_unmonitored() + result.hw_monitor = hw.to_dict() + return result + return self._run_unmonitored() + + def _build_hw_monitor(self) -> Any | None: + """Return an HWMonitor for the genai run, or None when unavailable.""" + try: + from ..session.monitor.hw_monitor import HWMonitor + except Exception: + logger.debug("HWMonitor import failed for genai benchmark", exc_info=True) + return None + + if not HWMonitor.is_available(): + logger.warning("HWMonitor unavailable; running genai benchmark without monitoring") + return None + + device = self._config.device + monitor_device = "auto" if device in ("config", "auto") else device + ep_name = normalize_ep_name(self._config.ep) if self._config.ep is not None else None + return HWMonitor(poll_interval_ms=200, device=monitor_device, ep_name=ep_name) + + def _run_unmonitored(self) -> GenaiBenchmarkResult: + """Execute the benchmark without wrapping it in HWMonitor.""" if self._session is None: self._session = self._build_session() session = self._session - # Loads the model and tokenizer, then encodes the prompt once. Both - # are outside the timed loop so they don't inflate TTFT. Unless - # apply_template is disabled, the prompt is wrapped in the bundle's own - # chat template so the measured prefill reflects realistic chat usage - # (falls back to the raw prompt when the bundle ships no template). - self._prompt_token_ids = session.encode(self._prompt_text(session)) + memory_tracker: _GenaiMemoryTracker | None = None + if self._config.memory: + memory_tracker = _GenaiMemoryTracker(device=self._config.device, ep=self._config.ep) + memory_tracker.record_baseline() + + session_load_start = self._clock() + session.load() + session_load_end = self._clock() + session_load_ms = (session_load_end - session_load_start) * 1000.0 + if memory_tracker is not None: + memory_tracker.record_after_load() gen_config = GenerationConfig( max_new_tokens=self._config.max_new_tokens, @@ -402,51 +654,44 @@ def run(self) -> GenaiBenchmarkResult: self._config.iterations, self._config.max_new_tokens, ) - hw_metrics: dict[str, Any] | None = None - if self._config.monitor and HWMonitor.is_available(): - monitor_device = self._monitor_device() - ep_name = self._monitor_ep() - with HWMonitor( - poll_interval_ms=_HW_POLL_INTERVAL_MS, - device=monitor_device if monitor_device and ep_name else "cpu", - ep_name=ep_name, - ) as hw: - samples = [ - self._time_one_generation(session, gen_config) for _ in range(total_runs) - ] - hw_metrics = hw.to_dict() - else: - if self._config.monitor: - logger.warning("HWMonitor is unavailable; generation resource metrics omitted") - samples = [self._time_one_generation(session, gen_config) for _ in range(total_runs)] + samples = [ + self._time_one_generation( + session, + gen_config, + kind="warmup" if i < self._config.warmup else "timed", + index=i, + ) + for i in range(total_runs) + ] - result = self._aggregate(samples) - result.hw_monitor = hw_metrics - return result + result = self._aggregate(samples, session_load_ms=session_load_ms) - def _monitor_device(self) -> str | None: - """Return the proven device to monitor, or ``None`` when unresolved.""" - effective = getattr(self._session, "effective_device", None) - return effective if effective in ("cpu", "gpu", "npu") else None + if memory_tracker is not None: + memory_tracker.record_after_benchmark() + result.memory_profile = memory_tracker.to_dict() - def _monitor_ep(self) -> EPName | None: - """Return the unique EP proven by loaded effective routing.""" - return getattr(self._session, "effective_hardware_ep", None) + return result def _time_one_generation( self, session: GenaiSession, gen_config: GenerationConfig, - ) -> _RunSample: - """Run one generation and convert its og-boundary timing to a sample. - - Timing is captured inside :meth:`GenaiSession.generate_timed` at the - onnxruntime-genai call boundaries (``append_tokens`` = prefill, each - ``generate_next_token`` = one decode step), so TTFT and TPOT reflect - model compute rather than generator-construction / detokenization - overhead. + *, + kind: str, + index: int, + ) -> _RequestSample: + """Run one generation and convert spans to a canonical request sample. + + Prompt templating and tokenization are timed per request so the core + report can expose both request-level and model-compute metrics. """ - timing = session.generate_timed(self._prompt_token_ids, gen_config) + template_start = self._clock() + prompt_text = self._prompt_text(session) + template_end = self._clock() + prompt_token_ids = session.encode(prompt_text) + tokenization_end = self._clock() + + timing = session.generate_timed(prompt_token_ids, gen_config, clock=self._clock) self._generation_count += 1 if self._generation_count == 1: logger.info("Model response (iteration 1): %s", timing.response_text) @@ -456,52 +701,99 @@ def _time_one_generation( self._generation_count, timing.response_text, ) - return _RunSample( - ttft_ms=timing.ttft_s * 1000.0, - prefill_ms=timing.prefill_s * 1000.0, - total_ms=timing.total_s * 1000.0, - decode_tokens_per_sec=timing.decode_tokens_per_sec, - tpot_ms=timing.tpot_s * 1000.0, - n_tokens=timing.generated_tokens, + return _RequestSample( + kind=kind, + index=index, + prompt_tokens=timing.input_tokens, + generated_tokens=timing.generated_tokens, + template_duration_ms=(template_end - template_start) * 1000.0, + tokenization_duration_ms=(tokenization_end - template_end) * 1000.0, + generator_create_duration_ms=timing.generator_create_s * 1000.0, + prefill_duration_ms=timing.prefill_s * 1000.0, + first_token_duration_ms=timing.first_token_s * 1000.0, + decode_token_durations_ms=[value * 1000.0 for value in timing.decode_s], + sequence_fetch_duration_ms=timing.sequence_fetch_s * 1000.0, + detokenization_duration_ms=timing.detokenization_s * 1000.0, ) - def _aggregate(self, samples: list[_RunSample]) -> GenaiBenchmarkResult: - """Aggregate timed samples (first ``warmup`` runs excluded).""" - timed = samples[self._config.warmup :] or samples - ttfts = [s.ttft_ms for s in timed] - prefills = [s.prefill_ms for s in timed] - totals = [s.total_ms for s in timed] - decode_tps = [s.decode_tokens_per_sec for s in timed] - tpots = [s.tpot_ms for s in timed] - token_latencies = [s.total_ms / s.n_tokens for s in timed if s.n_tokens] - sorted_ttfts = sorted(ttfts) + def _aggregate( + self, samples: list[_RequestSample], *, session_load_ms: float + ) -> GenaiBenchmarkResult: + """Aggregate canonical samples (warmup requests excluded from stats).""" + timed = [sample for sample in samples if sample.kind == "timed"] or samples + first = samples[0] if samples else None + load = self._load_metrics(session_load_ms) + aggregate: dict[str, Any] = { + "warmup_excluded": True, + "warmup_request_count": len([sample for sample in samples if sample.kind == "warmup"]), + "timed_request_count": len(timed), + "cold_start_ttft_duration_ms": ( + session_load_ms + first.request_ttft_duration_ms if first else 0.0 + ), + "cold_start_total_duration_ms": ( + session_load_ms + first.request_duration_ms if first else 0.0 + ), + "request_duration_ms": _stats([s.request_duration_ms for s in timed]), + "model_compute_duration_ms": _stats([s.model_compute_duration_ms for s in timed]), + "model_ttft_duration_ms": _stats([s.model_ttft_duration_ms for s in timed]), + "request_ttft_duration_ms": _stats([s.request_ttft_duration_ms for s in timed]), + "prefill_duration_ms": _stats([s.prefill_duration_ms for s in timed]), + "response_eval_duration_ms": _stats([s.response_eval_duration_ms for s in timed]), + "steady_state_tpot_ms": _stats([s.steady_state_tpot_ms for s in timed]), + "prefill_tokens_per_second": _stats([s.prefill_tokens_per_second for s in timed]), + "steady_state_decode_tokens_per_second": _stats( + [s.steady_state_decode_tokens_per_second for s in timed] + ), + "response_eval_tokens_per_second": _stats( + [s.response_eval_tokens_per_second for s in timed] + ), + } return GenaiBenchmarkResult( config=self._config, effective_ep=getattr(self._session, "effective_ep", None), effective_device=getattr(self._session, "effective_device", None), - prompt_tokens=len(self._prompt_token_ids), - generated_tokens=timed[0].n_tokens if timed else 0, + prompt_tokens=timed[0].prompt_tokens if timed else 0, + generated_tokens=timed[0].generated_tokens if timed else 0, context_length=self._session.context_length if self._session else None, - ttft_mean_ms=_mean(ttfts), - ttft_min_ms=min(ttfts) if ttfts else 0.0, - ttft_max_ms=max(ttfts) if ttfts else 0.0, - ttft_p50_ms=_percentile(sorted_ttfts, 50), - ttft_p90_ms=_percentile(sorted_ttfts, 90), - ttft_p95_ms=_percentile(sorted_ttfts, 95), - ttft_p99_ms=_percentile(sorted_ttfts, 99), - prefill_mean_ms=_mean(prefills), - decode_tokens_per_sec=_mean(decode_tps), - avg_token_latency_ms=_mean(token_latencies), - tpot_mean_ms=_mean(tpots), - total_generation_mean_ms=_mean(totals), - raw_ttft_ms=ttfts, - raw_prefill_ms=prefills, - raw_decode_tokens_per_sec=decode_tps, - raw_tpot_ms=tpots, - raw_total_ms=totals, + load=load, + requests=samples, + aggregate=aggregate, ) + def _load_metrics(self, session_load_ms: float) -> dict[str, float | str | None]: + """Return canonical load metrics with a clear weight-upload estimate.""" + load_timings = getattr(self._session, "load_timings_ms", {}) if self._session else {} + metrics: dict[str, float | str | None] = { + "session_load_duration_ms": session_load_ms, + "ep_registration_duration_ms": 0.0, + "bundle_prepare_duration_ms": 0.0, + "native_load_duration_ms": 0.0, + "config_create_duration_ms": 0.0, + "model_create_duration_ms": 0.0, + "tokenizer_create_duration_ms": 0.0, + "weight_upload_duration_ms": None, + "weight_upload_estimate_duration_ms": None, + "weight_upload_estimate_source": "unavailable", + } + for key in ( + "ep_registration_duration_ms", + "bundle_prepare_duration_ms", + "native_load_duration_ms", + "config_create_duration_ms", + "model_create_duration_ms", + "tokenizer_create_duration_ms", + ): + if key in load_timings: + metrics[key] = float(load_timings[key]) + if "session_load_duration_ms" in load_timings: + metrics["session_load_duration_ms"] = session_load_ms + model_create_ms = float(metrics["model_create_duration_ms"] or 0.0) + if model_create_ms > 0: + metrics["weight_upload_estimate_duration_ms"] = model_create_ms + metrics["weight_upload_estimate_source"] = "model_create_duration" + return metrics + # ============================================================================= # Reporting @@ -525,37 +817,107 @@ def display_genai_report(result: GenaiBenchmarkResult, console: Console) -> None f"(max_new_tokens={cfg.max_new_tokens})" ) + load = result.load + aggregate = result.aggregate + if load or aggregate.get("cold_start_ttft_duration_ms"): + console.print() + console.print("[bold]Startup[/bold]") + console.print( + f" Session load: {float(load.get('session_load_duration_ms') or 0.0):.2f} ms | " + f"Native load: {float(load.get('native_load_duration_ms') or 0.0):.2f} ms" + ) + console.print( + f" Cold TTFT: {float(aggregate.get('cold_start_ttft_duration_ms') or 0.0):.2f} ms | " + f"Cold total: {float(aggregate.get('cold_start_total_duration_ms') or 0.0):.2f} ms" + ) + weight_upload_estimate = float(load.get("weight_upload_estimate_duration_ms") or 0.0) + if weight_upload_estimate: + console.print( + f" Weight upload estimate: {weight_upload_estimate:.2f} ms " + f"[dim]({load.get('weight_upload_estimate_source')})[/dim]" + ) + console.print() console.print("[bold]Time to first token (ms)[/bold]") + model_ttft = aggregate.get("model_ttft_duration_ms", {}) table = Table(show_header=True, header_style="bold cyan") for col in ["Avg", "P50", "P90", "P95", "P99", "Min", "Max"]: table.add_column(col, justify="right") table.add_row( - f"{result.ttft_mean_ms:.2f}", - f"{result.ttft_p50_ms:.2f}", - f"{result.ttft_p90_ms:.2f}", - f"{result.ttft_p95_ms:.2f}", - f"{result.ttft_p99_ms:.2f}", - f"{result.ttft_min_ms:.2f}", - f"{result.ttft_max_ms:.2f}", + f"{model_ttft.get('mean', 0.0):.2f}", + f"{model_ttft.get('p50', 0.0):.2f}", + f"{model_ttft.get('p90', 0.0):.2f}", + f"{model_ttft.get('p95', 0.0):.2f}", + f"{model_ttft.get('p99', 0.0):.2f}", + f"{model_ttft.get('min', 0.0):.2f}", + f"{model_ttft.get('max', 0.0):.2f}", ) console.print(table) + prefill_duration = aggregate.get("prefill_duration_ms", {}) + prefill_tps = aggregate.get("prefill_tokens_per_second", {}) + decode_tps = aggregate.get("steady_state_decode_tokens_per_second", {}) + tpot = aggregate.get("steady_state_tpot_ms", {}) + request_duration = aggregate.get("request_duration_ms", {}) console.print() console.print( - f"[bold]Prefill:[/bold] {result.prefill_mean_ms:.2f} ms avg (prompt processing)" + f"[bold]Prefill:[/bold] {prefill_duration.get('mean', 0.0):.2f} ms avg | " + f"{prefill_tps.get('mean', 0.0):.2f} tokens/sec" ) console.print( - f"[bold]Decode:[/bold] {result.decode_tokens_per_sec:.2f} tokens/sec | " - f"{result.tpot_mean_ms:.2f} ms/token (TPOT)" + f"[bold]Decode:[/bold] {decode_tps.get('mean', 0.0):.2f} tokens/sec | " + f"{tpot.get('mean', 0.0):.2f} ms/token (TPOT)" ) console.print( - f"[bold]Total:[/bold] {result.total_generation_mean_ms:.2f} ms avg per generation" + f"[bold]Warm start:[/bold] {request_duration.get('mean', 0.0):.2f} ms avg per generation" ) + console.print(f"[bold]Latency:[/bold] {request_duration.get('mean', 0.0):.2f} ms avg") if cfg.warmup > 0: console.print( f" [dim]Excluded first {cfg.warmup} warmup generation(s) from statistics[/dim]" ) + + if result.hw_monitor: + console.print() + console.print("[bold]Hardware (during genai benchmark)[/bold]") + cpu = result.hw_monitor.get("cpu", {}) + ram = result.hw_monitor.get("ram", {}) + device_kind = result.hw_monitor.get("device_kind") + if device_kind in ("npu", "gpu"): + adapter = result.hw_monitor.get(device_kind, {}) + console.print( + f" {device_kind.upper()}: {adapter.get('mean_pct', 0):.1f}% avg, " + f"{adapter.get('peak_pct', 0):.1f}% peak | " + f"CPU: {cpu.get('mean_pct', 0):.1f}% avg | " + f"RAM: {ram.get('used_mb', 0):.0f} MB" + ) + else: + console.print( + f" CPU: {cpu.get('mean_pct', 0):.1f}% avg | RAM: {ram.get('used_mb', 0):.0f} MB" + ) + + if result.memory_profile: + mem = result.memory_profile + console.print() + console.print("[bold]Memory:[/bold]") + console.print( + f" RAM: {mem['rss_after_inference_mb']:.1f} MB -> " + f"model load: {mem['rss_model_load_delta_mb']:+.1f} MB | " + f"inference: {mem['rss_inference_delta_mb']:+.1f} MB | " + f"total: {mem['rss_total_delta_mb']:+.1f} MB" + ) + vram_local = mem.get("vram_local_after_inference_mb", 0.0) + vram_shared = mem.get("vram_shared_after_inference_mb", 0.0) + if vram_local > 0 or vram_shared > 0: + console.print( + f" VRAM: {vram_local:.1f}/{vram_shared:.1f} MB (local/shared) -> " + f"model load: {mem['vram_local_model_load_delta_mb']:+.1f}/" + f"{mem['vram_shared_model_load_delta_mb']:+.1f} MB | " + f"inference: {mem['vram_local_inference_delta_mb']:+.1f}/" + f"{mem['vram_shared_inference_delta_mb']:+.1f} MB | " + f"total: {mem['vram_local_total_delta_mb']:+.1f}/" + f"{mem['vram_shared_total_delta_mb']:+.1f} MB" + ) console.print() diff --git a/src/winml/modelkit/commands/perf.py b/src/winml/modelkit/commands/perf.py index 0c5b52129..ee3ec8c4c 100644 --- a/src/winml/modelkit/commands/perf.py +++ b/src/winml/modelkit/commands/perf.py @@ -426,7 +426,9 @@ class BenchmarkResult: def to_dict(self) -> dict[str, Any]: """Convert to dictionary for JSON serialization.""" result: dict[str, Any] = { + "schema_version": 2, "benchmark_info": { + "runtime": "winml", "model_id": self.config.model_id, "running_model_path": self.running_model_path, "task": self.actual_task, @@ -961,11 +963,22 @@ def _run_single(self) -> BenchmarkResult: "rss_baseline_mb": round(rss_baseline, 2), "rss_after_compile_mb": round(rss_after_compile, 2), "rss_after_inference_mb": round(rss_after_inference, 2), + "rss_peak_mb": round(max(rss_baseline, rss_after_compile, rss_after_inference), 2), "rss_model_load_delta_mb": round(rss_after_compile - rss_baseline, 2), "rss_inference_delta_mb": round(rss_after_inference - rss_after_compile, 2), "rss_total_delta_mb": round(rss_after_inference - rss_baseline, 2), + "vram_local_baseline_mb": round(vram_local_baseline, 2), + "vram_shared_baseline_mb": round(vram_shared_baseline, 2), + "vram_local_after_compile_mb": round(vram_local_compile, 2), + "vram_shared_after_compile_mb": round(vram_shared_compile, 2), "vram_local_after_inference_mb": round(vram_local_infer, 2), "vram_shared_after_inference_mb": round(vram_shared_infer, 2), + "vram_local_peak_mb": round( + max(vram_local_baseline, vram_local_compile, vram_local_infer), 2 + ), + "vram_shared_peak_mb": round( + max(vram_shared_baseline, vram_shared_compile, vram_shared_infer), 2 + ), "vram_local_model_load_delta_mb": round( vram_local_compile - vram_local_baseline, 2 ), @@ -2148,7 +2161,6 @@ def _run_simple_loop( "allow_unsupported_nodes": "--allow-unsupported-nodes", "batch_size": "--batch-size", "duration": "--duration", - "memory": "--memory", "op_tracing": "--op-tracing", } @@ -2379,6 +2391,7 @@ def _run_genai_runtime(ctx: click.Context, *, console: Console, json_mode: bool) config = GenaiPerfConfig( bundle_dir=bundle_dir, + model_id=model, ep=ep, device=device, prompt=prompt, @@ -2389,6 +2402,7 @@ def _run_genai_runtime(ctx: click.Context, *, console: Console, json_mode: bool) compile=not p["no_compile"], compile_timeout=p["compile_timeout"], monitor=bool(p.get("monitor")), + memory=bool(p.get("memory")), output_path=output, ) run_genai_perf(config, console=console, json_mode=json_mode) diff --git a/src/winml/modelkit/session/genai_session.py b/src/winml/modelkit/session/genai_session.py index 1a75c4dfd..2be2e56c3 100644 --- a/src/winml/modelkit/session/genai_session.py +++ b/src/winml/modelkit/session/genai_session.py @@ -225,32 +225,42 @@ class GenerationTiming: measurements taken immediately around the library calls. The segmentation mirrors onnxruntime-genai's official ``benchmark_e2e.py``: + * ``generator_create_s`` — cost of constructing ``og.Generator`` and search + parameters for one request. * ``prefill_s`` — cost of ``Generator.append_tokens`` (the prompt forward pass, a.k.a. prompt processing). * ``first_token_s`` — cost of the first ``Generator.generate_next_token``. * ``decode_s`` — cost of each subsequent ``generate_next_token`` (one entry per generated token after the first). - Detokenization is intentionally excluded — only model-compute boundaries - are timed, so the numbers reflect the pipeline rather than tokenizer/string - overhead. + Host sequence fetch and detokenization are measured separately from + model-compute boundaries, so callers can report either request-level or + pure model-compute latency. Attributes: input_tokens: Number of prompt tokens fed to ``append_tokens``. generated_tokens: Number of tokens produced (including the first). + generator_create_s: Generator construction time, in seconds. prefill_s: Prompt-processing time in seconds. first_token_s: Time to produce the first token, in seconds. decode_s: Per-token times for the steady-state decode phase (tokens after the first), in seconds. + sequence_fetch_s: Time spent fetching the generated token sequence from + the native generator after model compute, in seconds. + detokenization_s: Time spent decoding output token IDs to text, in + seconds. response_text: Decoded model output text (empty string when not captured). """ input_tokens: int = 0 generated_tokens: int = 0 + generator_create_s: float = 0.0 prefill_s: float = 0.0 first_token_s: float = 0.0 decode_s: list[float] = field(default_factory=list) + sequence_fetch_s: float = 0.0 + detokenization_s: float = 0.0 response_text: str = "" @property @@ -425,6 +435,7 @@ def __init__( # og.* handles — None until load() is called. self._model: Any = None self._tokenizer: Any = None + self._load_timings_ms: dict[str, float] = {} if not self._bundle_dir.exists(): raise FileNotFoundError(f"Bundle directory not found: {self._bundle_dir}") @@ -482,6 +493,7 @@ def load(self) -> None: if self._model is not None: return + session_load_start = time.perf_counter() og = self._import_og() cfg = self._read_genai_config() @@ -512,8 +524,11 @@ def load(self) -> None: # triggers it — all without a hardcoded EP short-name → behavior map. plugin_eps = self._bundle_plugin_eps(effective_cfg) logger.info("Plugin EPs detected in effective genai_config: %s", plugin_eps) + ep_registration_ms = 0.0 if plugin_eps: + ep_registration_start = time.perf_counter() self._register_eps(og, plugin_eps) + ep_registration_ms = (time.perf_counter() - ep_registration_start) * 1000.0 if self._verbose: og.set_log_options(enabled=True, model_input_values=True, model_output_shapes=True) @@ -528,25 +543,46 @@ def load(self) -> None: # override-only pass (no compilation) merely rewrites JSON + mirrors # files, touches no native accelerator state, and stays in-process. load_dir = self._bundle_dir + bundle_prepare_ms = 0.0 if self._compile: + bundle_prepare_start = time.perf_counter() load_dir = self._prepare_derived_bundle_isolated(effective_cfg, overridden=overridden) + bundle_prepare_ms = (time.perf_counter() - bundle_prepare_start) * 1000.0 elif overridden: + bundle_prepare_start = time.perf_counter() load_dir = self._prepare_derived_bundle(effective_cfg, overridden=overridden) + bundle_prepare_ms = (time.perf_counter() - bundle_prepare_start) * 1000.0 + native_load_start = time.perf_counter() try: config = og.Config(str(load_dir)) + after_config = time.perf_counter() # Per-stage EP routing lives in the (possibly overridden) genai_config # that og.Config loads from ``load_dir``. Do NOT call # clear_providers/append_provider — those only touch the top-level # provider and cannot override per-stage session_options. self._model = og.Model(config) + after_model = time.perf_counter() self._tokenizer = og.Tokenizer(self._model) + after_tokenizer = time.perf_counter() except Exception as exc: self._model = None self._tokenizer = None + self._load_timings_ms = {} raise GenaiLoadError(f"Failed to load genai bundle from {load_dir}: {exc}") from exc self._context_length = self._context_length_override or self._read_context_length() + load_end = time.perf_counter() + native_load_ms = (after_tokenizer - native_load_start) * 1000.0 + self._load_timings_ms = { + "session_load_duration_ms": (load_end - session_load_start) * 1000.0, + "ep_registration_duration_ms": ep_registration_ms, + "bundle_prepare_duration_ms": bundle_prepare_ms, + "native_load_duration_ms": native_load_ms, + "config_create_duration_ms": (after_config - native_load_start) * 1000.0, + "model_create_duration_ms": (after_model - after_config) * 1000.0, + "tokenizer_create_duration_ms": (after_tokenizer - after_model) * 1000.0, + } logger.info( "GenaiSession loaded: ep=%s context_length=%d", self._ep_override or "config", @@ -561,6 +597,7 @@ def unload(self) -> None: self._model = None self._tokenizer = None self._context_length = None + self._load_timings_ms = {} self._effective_device = None self._effective_hardware_ep = None logger.info("GenaiSession unloaded: bundle=%s", self._bundle_dir) @@ -646,9 +683,10 @@ def generate_timed( Unlike :meth:`generate_streaming` (which yields decoded text), this drives the same ``og.Generator`` loop but records wall-clock spans - around the library calls and returns a :class:`GenerationTiming`. It - does **not** decode tokens — only model-compute boundaries are timed, - so tokenizer / string overhead is excluded. + around the library calls and returns a :class:`GenerationTiming`. + Generator construction, host sequence fetch, and detokenization are + timed separately from model-compute spans so callers can report either + request-level or pure model-compute latency. The segmentation matches onnxruntime-genai's official ``benchmark_e2e.py``: ``append_tokens`` is the prefill (prompt @@ -673,14 +711,16 @@ def generate_timed( self._ensure_loaded() cfg = config or GenerationConfig() tokens = self._encode_prompt(prompt) + generator_create_start = clock() generator = self._new_generator(cfg, len(tokens)) + generator_create_end = clock() - # marks[0] = before prefill + # marks[0] = before prefill (after generator creation) # marks[1] = after prefill (append_tokens) # marks[2+k]= after the (k+1)-th generated token marks: list[float] = [] generated = 0 - marks.append(clock()) + marks.append(generator_create_end) generator.append_tokens(tokens) marks.append(clock()) while not generator.is_done(): @@ -693,19 +733,26 @@ def generate_timed( if generated == 0: raise GenaiSessionError("genai: generation produced no tokens (empty bundle output?)") - # Fetch all output tokens *after* the timing loop so that - # get_sequence() (which may trigger host/device copies on hardware EPs) - # does not pollute per-token decode measurements. + # Fetch and decode *after* the timing loop, as separate spans, so host + # copies/string work do not pollute per-token model-compute measurements. + sequence_fetch_start = marks[-1] full_sequence = generator.get_sequence(0) + sequence_fetch_end = clock() output_token_ids = list(full_sequence[len(tokens) :]) + detokenization_start = sequence_fetch_end + response_text = str(self._tokenizer.decode(output_token_ids)) + detokenization_end = clock() timing = GenerationTiming( input_tokens=len(tokens), generated_tokens=generated, + generator_create_s=generator_create_end - generator_create_start, prefill_s=marks[1] - marks[0], first_token_s=marks[2] - marks[1], decode_s=[marks[i + 1] - marks[i] for i in range(2, 1 + generated)], - response_text=str(self._tokenizer.decode(output_token_ids)), + sequence_fetch_s=sequence_fetch_end - sequence_fetch_start, + detokenization_s=detokenization_end - detokenization_start, + response_text=response_text, ) logger.info( "generate_timed: input_tokens=%d generated_tokens=%d " @@ -847,6 +894,11 @@ def context_length(self) -> int | None: """Static KV cache length, populated after :meth:`load`.""" return self._context_length + @property + def load_timings_ms(self) -> dict[str, float]: + """Best-effort wall-clock breakdown for the most recent native load.""" + return dict(self._load_timings_ms) + @property def effective_device(self) -> str | None: """Uniquely resolved hardware device, or ``None`` when routing is ambiguous. diff --git a/tests/unit/commands/test_perf_cli.py b/tests/unit/commands/test_perf_cli.py index af6eb5114..d885525bf 100644 --- a/tests/unit/commands/test_perf_cli.py +++ b/tests/unit/commands/test_perf_cli.py @@ -1742,6 +1742,15 @@ def test_ep_options_none_when_not_set_in_to_dict(self) -> None: assert result.to_dict()["benchmark_info"]["ep_options"] is None + def test_to_dict_includes_schema_version_and_runtime(self) -> None: + """Classic perf reports the same schema markers as GenAI perf.""" + config = BenchmarkConfig(model_id="m") + result = BenchmarkResult(config=config) + d = result.to_dict() + + assert d["schema_version"] == 2 + assert d["benchmark_info"]["runtime"] == "winml" + def test_iterations_reports_configured_count_without_duration(self) -> None: """Without --duration, benchmark_info.iterations is the configured value.""" config = BenchmarkConfig(model_id="m", iterations=100) @@ -1925,6 +1934,89 @@ def test_to_dict_emits_effective_batch_size(self) -> None: assert info["effective_batch_size"] == 1 +class TestClassicMemoryProfile: + def test_memory_profile_includes_additive_peak_and_compile_fields(self, monkeypatch) -> None: + """Classic perf emits the same additive memory fields as GenAI.""" + config = BenchmarkConfig(model_id="m", memory=True, warmup=0) + benchmark = PerfBenchmark(config) + single = MagicMock() + single.io_config = { + "input_names": ["pixel_values"], + "input_shapes": [[1, 3, 224, 224]], + "input_types": ["float32"], + "output_names": ["logits"], + "output_shapes": [[1, 1000]], + } + single.device = "npu" + single.ep_name = "QNNExecutionProvider" + single.task = "image-classification" + single.running_model_path = "model.onnx" + single._session.compile.return_value = None + benchmark._model = single + benchmark._ep_device = MagicMock() + + stats = MagicMock() + stats.mean_ms = 10.0 + stats.min_ms = 9.0 + stats.max_ms = 11.0 + stats.p50_ms = 10.0 + stats.p90_ms = 10.5 + stats.p95_ms = 10.8 + stats.p99_ms = 11.0 + stats.samples_ms = [10.0] + stats.all_samples_ms = [10.0] + + rss_values = iter([100.0, 150.0, 180.0]) + vram_values = iter([(10.0, 20.0), (30.0, 50.0), (40.0, 70.0)]) + + monkeypatch.setattr(benchmark, "_resolve_adapter_luid", lambda: "luid") + monkeypatch.setattr(benchmark, "_run_benchmark", lambda: stats) + monkeypatch.setattr( + benchmark, + "_generate_inputs", + lambda: setattr( + benchmark, + "_inputs", + {"pixel_values": MagicMock(shape=(1, 3, 224, 224))}, + ), + ) + monkeypatch.setattr( + "winml.modelkit.session.monitor.memory_tracker.get_rss_mb", + lambda: next(rss_values), + ) + monkeypatch.setattr( + "winml.modelkit.session.monitor.memory_tracker.get_vram_mb", + lambda _adapter_luid: next(vram_values), + ) + monkeypatch.setattr("winml.modelkit.commands.perf._print_model_info", lambda *_, **__: None) + + result = benchmark._run_single() + + assert result.memory_profile == { + "rss_baseline_mb": 100.0, + "rss_after_compile_mb": 150.0, + "rss_after_inference_mb": 180.0, + "rss_peak_mb": 180.0, + "rss_model_load_delta_mb": 50.0, + "rss_inference_delta_mb": 30.0, + "rss_total_delta_mb": 80.0, + "vram_local_baseline_mb": 10.0, + "vram_shared_baseline_mb": 20.0, + "vram_local_after_compile_mb": 30.0, + "vram_shared_after_compile_mb": 50.0, + "vram_local_after_inference_mb": 40.0, + "vram_shared_after_inference_mb": 70.0, + "vram_local_peak_mb": 40.0, + "vram_shared_peak_mb": 70.0, + "vram_local_model_load_delta_mb": 20.0, + "vram_shared_model_load_delta_mb": 30.0, + "vram_local_inference_delta_mb": 10.0, + "vram_shared_inference_delta_mb": 20.0, + "vram_local_total_delta_mb": 30.0, + "vram_shared_total_delta_mb": 50.0, + } + + # ============================================================================= # --INPUT-DATA TESTS # ============================================================================= diff --git a/tests/unit/commands/test_perf_genai.py b/tests/unit/commands/test_perf_genai.py index 08616777f..98ad4d48c 100644 --- a/tests/unit/commands/test_perf_genai.py +++ b/tests/unit/commands/test_perf_genai.py @@ -50,14 +50,20 @@ def _timing( decode_s: list[float], *, input_tokens: int = 3, + generator_create_s: float = 0.0, + sequence_fetch_s: float = 0.0, + detokenization_s: float = 0.0, ) -> GenerationTiming: """Build a GenerationTiming with ``1 + len(decode_s)`` generated tokens.""" return GenerationTiming( input_tokens=input_tokens, generated_tokens=1 + len(decode_s), + generator_create_s=generator_create_s, prefill_s=prefill_s, first_token_s=first_token_s, decode_s=list(decode_s), + sequence_fetch_s=sequence_fetch_s, + detokenization_s=detokenization_s, ) @@ -79,6 +85,7 @@ def __init__( effective_ep: str | None = None, effective_device: str | None = None, effective_hardware_ep: str | None = None, + load_timings_ms: dict[str, float] | None = None, ) -> None: self._timings = list(timings) self._i = 0 @@ -93,6 +100,11 @@ def __init__( self.effective_ep = effective_ep self.effective_device = effective_device self.effective_hardware_ep = effective_hardware_ep + self.load_timings_ms = load_timings_ms or {} + self.loaded = False + + def load(self) -> None: + self.loaded = True def encode(self, text: str) -> list[int]: self.encoded_text = text @@ -104,7 +116,9 @@ def apply_chat_template(self, prompt: str, **_kwargs: object) -> str: raise GenaiSessionError("bundle ships no chat template") return f"{prompt}" - def generate_timed(self, prompt: object, config: object = None) -> GenerationTiming: + def generate_timed( + self, prompt: object, config: object = None, **_kwargs: object + ) -> GenerationTiming: if self._i >= len(self._timings): raise GenaiSessionError("genai: generation produced no tokens (empty bundle output?)") timing = self._timings[self._i] @@ -241,6 +255,64 @@ def _raise(_target: object) -> object: class TestMetricMath: + def test_load_and_request_submetrics_are_canonical(self) -> None: + cfg = GenaiPerfConfig(bundle_dir=Path("x"), warmup=0, iterations=1, max_new_tokens=2) + # model_compute = 0.4 + 0.6 + 0.5 = 1.5s; response_eval = 1.1s. + timing = _timing( + 0.4, + 0.6, + [0.5], + input_tokens=4, + generator_create_s=0.05, + sequence_fetch_s=0.02, + detokenization_s=0.03, + ) + session = _FakeSession( + [timing], + prompt_ids=[1, 2, 3, 4], + load_timings_ms={ + "session_load_duration_ms": 1240.0, + "ep_registration_duration_ms": 10.0, + "bundle_prepare_duration_ms": 20.0, + "native_load_duration_ms": 800.0, + "config_create_duration_ms": 25.0, + "model_create_duration_ms": 750.0, + "tokenizer_create_duration_ms": 25.0, + }, + ) + # session.load outer span = 1250 ms; template = 100 ms; tokenization = 150 ms. + clock = iter([10.0, 11.25, 11.25, 11.35, 11.50]) + bench = GenaiPerfBenchmark(cfg, session=session, clock=lambda: next(clock)) + + result = bench.run() + + assert session.loaded is True + assert result.load["session_load_duration_ms"] == pytest.approx(1250.0) + assert result.load["native_load_duration_ms"] == pytest.approx(800.0) + assert result.load["model_create_duration_ms"] == pytest.approx(750.0) + assert result.load["weight_upload_duration_ms"] is None + assert result.load["weight_upload_estimate_duration_ms"] == pytest.approx(750.0) + assert result.load["weight_upload_estimate_source"] == "model_create_duration" + + request = result.requests[0] + assert request.kind == "timed" + assert request.template_duration_ms == pytest.approx(100.0) + assert request.tokenization_duration_ms == pytest.approx(150.0) + assert request.generator_create_duration_ms == pytest.approx(50.0) + assert request.model_ttft_duration_ms == pytest.approx(1000.0) + assert request.request_ttft_duration_ms == pytest.approx(1300.0) + assert request.model_compute_duration_ms == pytest.approx(1500.0) + assert request.response_eval_duration_ms == pytest.approx(1100.0) + assert request.request_duration_ms == pytest.approx(1850.0) + assert request.prefill_tokens_per_second == pytest.approx(10.0) + assert request.steady_state_decode_tokens_per_second == pytest.approx(2.0) + assert request.response_eval_tokens_per_second == pytest.approx(1.8181818) + + assert result.aggregate["cold_start_ttft_duration_ms"] == pytest.approx(2550.0) + assert result.aggregate["cold_start_total_duration_ms"] == pytest.approx(3100.0) + assert result.aggregate["request_duration_ms"]["mean"] == pytest.approx(1850.0) + assert result.aggregate["model_compute_duration_ms"]["mean"] == pytest.approx(1500.0) + def test_single_run_metrics(self) -> None: cfg = GenaiPerfConfig(bundle_dir=Path("x"), warmup=0, iterations=1, max_new_tokens=4) # prefill 0.4s + first token 0.6s -> TTFT 1.0s; 3 decode steps of 0.4s. @@ -253,19 +325,21 @@ def test_single_run_metrics(self) -> None: assert result.prompt_tokens == 5 assert result.generated_tokens == 4 assert result.context_length == 256 - assert result.ttft_mean_ms == pytest.approx(1000.0) - assert result.prefill_mean_ms == pytest.approx(400.0) + assert result.aggregate["model_ttft_duration_ms"]["mean"] == pytest.approx(1000.0) + assert result.aggregate["prefill_duration_ms"]["mean"] == pytest.approx(400.0) # total = 0.4 + 0.6 + 3*0.4 = 2.2s - assert result.total_generation_mean_ms == pytest.approx(2200.0) + assert result.aggregate["model_compute_duration_ms"]["mean"] == pytest.approx(2200.0) # decode: 3 steps over 1.2s -> 2.5 tok/s - assert result.decode_tokens_per_sec == pytest.approx(2.5) + assert result.aggregate["steady_state_decode_tokens_per_second"]["mean"] == pytest.approx( + 2.5 + ) # TPOT: mean of [0.4, 0.4, 0.4] = 0.4s - assert result.tpot_mean_ms == pytest.approx(400.0) - # avg per-token latency: 2200 ms / 4 tokens = 550 ms - assert result.avg_token_latency_ms == pytest.approx(550.0) - assert result.raw_ttft_ms == pytest.approx([1000.0]) - assert result.raw_prefill_ms == pytest.approx([400.0]) - assert result.raw_tpot_ms == pytest.approx([400.0]) + assert result.aggregate["steady_state_tpot_ms"]["mean"] == pytest.approx(400.0) + assert result.aggregate["response_eval_tokens_per_second"]["mean"] == pytest.approx(4 / 1.8) + assert result.requests[0].model_ttft_duration_ms == pytest.approx(1000.0) + assert result.requests[0].prefill_duration_ms == pytest.approx(400.0) + assert result.requests[0].steady_state_tpot_ms == pytest.approx(400.0) + assert result.requests[0].prefill_tokens_per_second == pytest.approx(12.5) def test_warmup_runs_excluded(self) -> None: cfg = GenaiPerfConfig(bundle_dir=Path("x"), warmup=1, iterations=2, max_new_tokens=4) @@ -278,11 +352,12 @@ def test_warmup_runs_excluded(self) -> None: result = bench.run() - assert len(result.raw_ttft_ms) == 2 - assert result.raw_ttft_ms == pytest.approx([1000.0, 2000.0]) - assert result.ttft_mean_ms == pytest.approx(1500.0) + assert [s.kind for s in result.requests] == ["warmup", "timed", "timed"] + timed_ttft = [s.model_ttft_duration_ms for s in result.requests if s.kind == "timed"] + assert timed_ttft == pytest.approx([1000.0, 2000.0]) + assert result.aggregate["model_ttft_duration_ms"]["mean"] == pytest.approx(1500.0) # totals 1500 / 3000 ms -> mean 2250 ms - assert result.total_generation_mean_ms == pytest.approx(2250.0) + assert result.aggregate["model_compute_duration_ms"]["mean"] == pytest.approx(2250.0) def test_single_token_generation_has_zero_decode_rate(self) -> None: cfg = GenaiPerfConfig(bundle_dir=Path("x"), warmup=0, iterations=1, max_new_tokens=1) @@ -293,9 +368,9 @@ def test_single_token_generation_has_zero_decode_rate(self) -> None: result = bench.run() assert result.generated_tokens == 1 - assert result.decode_tokens_per_sec == 0.0 - assert result.tpot_mean_ms == 0.0 - assert result.ttft_mean_ms == pytest.approx(2000.0) + assert result.aggregate["steady_state_decode_tokens_per_second"]["mean"] == 0.0 + assert result.aggregate["steady_state_tpot_ms"]["mean"] == 0.0 + assert result.aggregate["model_ttft_duration_ms"]["mean"] == pytest.approx(2000.0) def test_no_tokens_raises(self) -> None: cfg = GenaiPerfConfig(bundle_dir=Path("x"), warmup=0, iterations=1) @@ -320,9 +395,57 @@ def test_percentiles_over_multiple_runs(self) -> None: result = bench.run() - assert result.raw_ttft_ms == pytest.approx([1000.0, 2000.0, 3000.0, 4000.0]) - assert result.ttft_min_ms == pytest.approx(1000.0) - assert result.ttft_max_ms == pytest.approx(4000.0) + assert [s.model_ttft_duration_ms for s in result.requests] == pytest.approx( + [1000.0, 2000.0, 3000.0, 4000.0] + ) + assert result.aggregate["model_ttft_duration_ms"]["min"] == pytest.approx(1000.0) + assert result.aggregate["model_ttft_duration_ms"]["max"] == pytest.approx(4000.0) + + def test_memory_profile_uses_classic_perf_field_names(self, monkeypatch) -> None: + cfg = GenaiPerfConfig( + bundle_dir=Path("x"), + warmup=0, + iterations=1, + max_new_tokens=2, + memory=True, + ) + session = _FakeSession([_timing(0.4, 0.6, [0.5])]) + rss_values = iter([100.0, 150.0, 180.0]) + + monkeypatch.setattr(perf_genai, "_get_rss_mb", lambda: next(rss_values), raising=False) + monkeypatch.setattr( + perf_genai, + "_get_vram_mb", + lambda _adapter_luid: (0.0, 0.0), + raising=False, + ) + monkeypatch.setattr(perf_genai, "_resolve_adapter_luid", lambda *_args: None, raising=False) + + result = GenaiPerfBenchmark(cfg, session=session).run() + + assert result.memory_profile == { + "rss_baseline_mb": 100.0, + "rss_after_compile_mb": 150.0, + "rss_after_inference_mb": 180.0, + "rss_peak_mb": 180.0, + "rss_model_load_delta_mb": 50.0, + "rss_inference_delta_mb": 30.0, + "rss_total_delta_mb": 80.0, + "vram_local_baseline_mb": 0.0, + "vram_shared_baseline_mb": 0.0, + "vram_local_after_compile_mb": 0.0, + "vram_shared_after_compile_mb": 0.0, + "vram_local_after_inference_mb": 0.0, + "vram_shared_after_inference_mb": 0.0, + "vram_local_peak_mb": 0.0, + "vram_shared_peak_mb": 0.0, + "vram_local_model_load_delta_mb": 0.0, + "vram_shared_model_load_delta_mb": 0.0, + "vram_local_inference_delta_mb": 0.0, + "vram_shared_inference_delta_mb": 0.0, + "vram_local_total_delta_mb": 0.0, + "vram_shared_total_delta_mb": 0.0, + } # --------------------------------------------------------------------------- @@ -380,6 +503,7 @@ class TestResultToDict: def _result(self) -> GenaiBenchmarkResult: cfg = GenaiPerfConfig( bundle_dir=Path("bundle"), + model_id="Qwen/Qwen3-0.6B", ep="qnn", device="npu", prompt="Benchmark this exact prompt", @@ -402,15 +526,18 @@ def test_to_dict_shape(self) -> None: d = self._result().to_dict() assert set(d) == { + "schema_version", "benchmark_info", - "ttft_ms", - "prefill_ms", - "decode", - "total_generation_ms", - "raw", + "load", + "requests", + "aggregate", } + assert d["schema_version"] == 2 info = d["benchmark_info"] assert info["runtime"] == "winml-genai" + assert info["model_id"] == "Qwen/Qwen3-0.6B" + assert info["running_model_path"] == "bundle" + assert info["bundle_dir"] == "bundle" assert info["ep"] == "qnn" assert info["device"] == "npu" assert info["effective_device"] == "npu" @@ -422,16 +549,79 @@ def test_to_dict_shape(self) -> None: assert info["monitor"] is False assert info["apply_template"] is True assert info["prompt"] == "Benchmark this exact prompt" - assert set(d["ttft_ms"]) == {"mean", "min", "max", "p50", "p90", "p95", "p99"} - assert set(d["prefill_ms"]) == {"mean"} - assert set(d["decode"]) == {"tokens_per_sec", "avg_token_latency_ms", "tpot_ms"} - assert set(d["raw"]) == { - "ttft_ms", - "prefill_ms", - "decode_tokens_per_sec", - "tpot_ms", - "total_ms", + assert set(d["load"]) == { + "session_load_duration_ms", + "ep_registration_duration_ms", + "bundle_prepare_duration_ms", + "native_load_duration_ms", + "config_create_duration_ms", + "model_create_duration_ms", + "tokenizer_create_duration_ms", + "weight_upload_duration_ms", + "weight_upload_estimate_duration_ms", + "weight_upload_estimate_source", } + assert len(d["requests"]) == 1 + assert set(d["requests"][0]) == { + "kind", + "index", + "prompt_tokens", + "generated_tokens", + "template_duration_ms", + "tokenization_duration_ms", + "generator_create_duration_ms", + "prefill_duration_ms", + "first_token_duration_ms", + "decode_token_durations_ms", + "sequence_fetch_duration_ms", + "detokenization_duration_ms", + "request_ttft_duration_ms", + "model_ttft_duration_ms", + "response_eval_duration_ms", + "model_compute_duration_ms", + "request_duration_ms", + "prefill_tokens_per_second", + "steady_state_decode_tokens_per_second", + "response_eval_tokens_per_second", + "steady_state_tpot_ms", + } + stats_keys = { + "mean", + "std", + "min", + "max", + "p50", + "p90", + "p95", + "p99", + } + assert d["aggregate"]["warmup_excluded"] is True + assert d["aggregate"]["timed_request_count"] == 1 + assert set(d["aggregate"]["request_duration_ms"]) == stats_keys + assert set(d["aggregate"]["model_compute_duration_ms"]) == stats_keys + assert set(d["aggregate"]["model_ttft_duration_ms"]) == stats_keys + assert set(d["aggregate"]["request_ttft_duration_ms"]) == stats_keys + assert set(d["aggregate"]["prefill_duration_ms"]) == stats_keys + assert set(d["aggregate"]["response_eval_duration_ms"]) == stats_keys + assert set(d["aggregate"]["steady_state_tpot_ms"]) == stats_keys + assert set(d["aggregate"]["prefill_tokens_per_second"]) == stats_keys + assert set(d["aggregate"]["steady_state_decode_tokens_per_second"]) == stats_keys + assert set(d["aggregate"]["response_eval_tokens_per_second"]) == stats_keys + assert "accuracy" not in d + + def test_to_dict_includes_optional_memory_and_hw_monitor(self) -> None: + cfg = GenaiPerfConfig(bundle_dir=Path("bundle"), iterations=1, warmup=0) + result = GenaiBenchmarkResult( + config=cfg, + memory_profile={"rss_total_delta_mb": 12.5}, + hw_monitor={"monitor": "HWMonitor", "cpu": {"mean_pct": 1.0}}, + ) + + d = result.to_dict() + + assert d["memory"] == {"rss_total_delta_mb": 12.5} + assert d["hw_monitor"] == {"monitor": "HWMonitor", "cpu": {"mean_pct": 1.0}} + assert "hardware" not in d def test_to_dict_is_json_serializable(self) -> None: # Round-trips without error. @@ -485,7 +675,6 @@ def __exit__(self, *_args: object) -> None: def to_dict(self) -> dict: return metrics - monkeypatch.setattr(perf_genai, "HWMonitor", FakeMonitor) cfg = GenaiPerfConfig( bundle_dir=Path("bundle"), ep="qnn", @@ -495,8 +684,10 @@ def to_dict(self) -> dict: monitor=True, ) session = _FakeSession([_timing(0.4, 0.6, [0.4])], effective_ep="qnn") + bench = GenaiPerfBenchmark(cfg, session=session) + monkeypatch.setattr(bench, "_build_hw_monitor", lambda: FakeMonitor()) - data = GenaiPerfBenchmark(cfg, session=session).run().to_dict() + data = bench.run().to_dict() assert data["benchmark_info"]["monitor"] is True assert data["hw_monitor"] == metrics @@ -542,33 +733,29 @@ def fake_ctor(bundle_dir, ep, *, device=None, **_kwargs): GenaiPerfBenchmark(cfg)._build_session() assert captured == {"ep": "openvino", "device": "npu"} - def test_monitor_uses_bundle_effective_device_for_config(self) -> None: - cfg = GenaiPerfConfig(bundle_dir=Path("bundle"), device="config") - session = _FakeSession([], effective_device="gpu") - assert GenaiPerfBenchmark(cfg, session=session)._monitor_device() == "gpu" + def test_build_hw_monitor_uses_auto_for_config_device(self, monkeypatch) -> None: + captured: dict = {} - def test_monitor_uses_cpu_only_when_bundle_device_is_ambiguous(self) -> None: - cfg = GenaiPerfConfig(bundle_dir=Path("bundle"), device="config") - session = _FakeSession([], effective_device=None) - assert GenaiPerfBenchmark(cfg, session=session)._monitor_device() is None + class FakeMonitor: + @classmethod + def is_available(cls) -> bool: + return True - def test_monitor_uses_session_device_when_override_is_noop(self) -> None: - cfg = GenaiPerfConfig(bundle_dir=Path("bundle"), device="npu", ep="qnn") - session = _FakeSession([], effective_ep=None, effective_device="cpu") - assert GenaiPerfBenchmark(cfg, session=session)._monitor_device() == "cpu" + def __init__(self, **kwargs: object) -> None: + captured.update(kwargs) - def test_monitor_ep_comes_from_effective_config_not_request(self) -> None: - cfg = GenaiPerfConfig(bundle_dir=Path("bundle"), device="gpu", ep="dml") - session = _FakeSession( - [], - effective_ep=None, - effective_device="gpu", - effective_hardware_ep="OpenVINOExecutionProvider", + monkeypatch.setattr( + "winml.modelkit.session.monitor.hw_monitor.HWMonitor", + FakeMonitor, ) + cfg = GenaiPerfConfig(bundle_dir=Path("bundle"), device="config", ep=None) - assert GenaiPerfBenchmark(cfg, session=session)._monitor_ep() == "OpenVINOExecutionProvider" + monitor = GenaiPerfBenchmark(cfg, session=_FakeSession([]))._build_hw_monitor() - def test_accelerator_monitor_requires_unique_effective_ep(self, monkeypatch) -> None: + assert isinstance(monitor, FakeMonitor) + assert captured == {"poll_interval_ms": 200, "device": "auto", "ep_name": None} + + def test_build_hw_monitor_normalizes_requested_ep(self, monkeypatch) -> None: captured: dict = {} class FakeMonitor: @@ -579,28 +766,20 @@ def is_available(cls) -> bool: def __init__(self, **kwargs: object) -> None: captured.update(kwargs) - def __enter__(self): - return self - - def __exit__(self, *_args: object) -> None: - pass - - def to_dict(self) -> dict: - return {} - - monkeypatch.setattr(perf_genai, "HWMonitor", FakeMonitor) - cfg = GenaiPerfConfig( - bundle_dir=Path("bundle"), device="gpu", ep="dml", iterations=1, warmup=0, monitor=True - ) - session = _FakeSession( - [_timing(0.4, 0.6, [0.4])], - effective_device="gpu", - effective_hardware_ep=None, + monkeypatch.setattr( + "winml.modelkit.session.monitor.hw_monitor.HWMonitor", + FakeMonitor, ) + cfg = GenaiPerfConfig(bundle_dir=Path("bundle"), device="gpu", ep="dml") - GenaiPerfBenchmark(cfg, session=session).run() + monitor = GenaiPerfBenchmark(cfg, session=_FakeSession([]))._build_hw_monitor() - assert captured == {"poll_interval_ms": 200, "device": "cpu", "ep_name": None} + assert isinstance(monitor, FakeMonitor) + assert captured == { + "poll_interval_ms": 200, + "device": "gpu", + "ep_name": perf_genai.normalize_ep_name("dml"), + } # --------------------------------------------------------------------------- @@ -748,6 +927,7 @@ def test_dispatches_and_maps_device_to_ep( ) assert result.exit_code == 0, result.output cfg = capture_run["config"] + assert cfg.model_id == str(bundle) assert cfg.ep == "qnn" assert cfg.device == "npu" assert cfg.bundle_dir == bundle @@ -1044,6 +1224,21 @@ def test_compile_flag_forwarded( assert cfg.compile is True assert cfg.compile_timeout == 120 + def test_memory_and_monitor_flags_forwarded( + self, runner: CliRunner, tmp_path: Path, capture_run: dict + ) -> None: + bundle = _make_bundle(tmp_path) + result = runner.invoke( + perf, + ["-m", str(bundle), "--runtime", "winml-genai", "--memory", "--monitor"], + ) + assert result.exit_code == 0, result.output + assert "--memory" not in result.output + assert "--monitor" not in result.output + cfg = capture_run["config"] + assert cfg.memory is True + assert cfg.monitor is True + def test_warns_and_ignores_winml_only_flags( self, runner: CliRunner, tmp_path: Path, capture_run: dict ) -> None: @@ -1144,6 +1339,7 @@ def test_hf_model_id_autobuilds_and_dispatches( assert build_calls["build"]["force_rebuild"] is False # Benchmarked the freshly built cache bundle. cfg = capture_run["config"] + assert cfg.model_id == "Qwen/Qwen3-0.6B" assert cfg.bundle_dir == build_calls["build"]["output_dir"] assert (cfg.bundle_dir / "genai_config.json").exists() # Omitting --device keeps the "respect the bundle" default. @@ -1205,7 +1401,8 @@ def test_autobuild_honored_flags_not_warned_as_ignored( ) -> None: # The build-driving flags (--rebuild/--task) steer the auto-build, so # they must NOT appear in the "options are ignored" warning when a bundle - # is built from a model id. A genuinely ignored flag (--memory) still is. + # is built from a model id. Runtime genai flags such as --memory are + # honored by the benchmark and must not be reported as ignored either. import winml.modelkit.loader as loader_mod import winml.modelkit.models.winml as winml_models @@ -1233,7 +1430,7 @@ def test_autobuild_honored_flags_not_warned_as_ignored( assert result.exit_code == 0, result.output assert "--rebuild" not in result.output assert "--task" not in result.output - assert "--memory" in result.output # still ignored -> still warned + assert "--memory" not in result.output def test_prebuilt_bundle_still_warns_build_flags( self, runner: CliRunner, tmp_path: Path, capture_run: dict diff --git a/tests/unit/session/test_genai_session.py b/tests/unit/session/test_genai_session.py index e9c2a6883..1719f339e 100644 --- a/tests/unit/session/test_genai_session.py +++ b/tests/unit/session/test_genai_session.py @@ -324,6 +324,29 @@ def test_context_length_override(self, bundle_dir: Path, mock_og: MagicMock) -> session.load() assert session.context_length == 512 + def test_load_records_stage_timings( + self, bundle_dir: Path, mock_og: MagicMock, monkeypatch + ) -> None: + values = iter([10.0, 10.0, 10.2, 10.5, 10.7, 10.8]) + monkeypatch.setattr( + "winml.modelkit.session.genai_session.time.perf_counter", + lambda: next(values), + ) + + with _patch_og(mock_og): + session = GenaiSession(bundle_dir) + session.load() + + assert session.load_timings_ms == { + "session_load_duration_ms": pytest.approx(800.0), + "ep_registration_duration_ms": pytest.approx(0.0), + "bundle_prepare_duration_ms": pytest.approx(0.0), + "native_load_duration_ms": pytest.approx(700.0), + "config_create_duration_ms": pytest.approx(200.0), + "model_create_duration_ms": pytest.approx(300.0), + "tokenizer_create_duration_ms": pytest.approx(200.0), + } + def test_load_is_idempotent(self, bundle_dir: Path, mock_og: MagicMock) -> None: with _patch_og(mock_og): session = GenaiSession(bundle_dir) @@ -970,11 +993,7 @@ def test_dml_bundle_routes_monitoring_to_gpu(self) -> None: "model": { "decoder": { "pipeline": [ - { - "decoder": { - "session_options": {"provider_options": [{"dml": {}}]} - } - } + {"decoder": {"session_options": {"provider_options": [{"dml": {}}]}}} ] } } @@ -987,11 +1006,7 @@ def test_ambiguous_multidevice_provider_omits_adapter(self) -> None: "model": { "decoder": { "pipeline": [ - { - "decoder": { - "session_options": {"provider_options": [{"qnn": {}}]} - } - } + {"decoder": {"session_options": {"provider_options": [{"qnn": {}}]}}} ] } } @@ -1003,9 +1018,7 @@ def test_device_type_resolves_multidevice_provider(self) -> None: cfg = { "model": { "decoder": { - "session_options": { - "provider_options": [{"openvino": {"device_type": "GPU"}}] - } + "session_options": {"provider_options": [{"openvino": {"device_type": "GPU"}}]} } } } @@ -1039,9 +1052,7 @@ def test_effective_config_precedes_explicit_fallback(self, bundle_dir: Path) -> cfg = { "model": { "decoder": { - "session_options": { - "provider_options": [{"openvino": {"device_type": "GPU"}}] - } + "session_options": {"provider_options": [{"openvino": {"device_type": "GPU"}}]} } } } @@ -1057,11 +1068,7 @@ def test_config_routing_wins_over_contradictory_requested_device( "model": { "decoder": { "pipeline": [ - { - "decoder": { - "session_options": {"provider_options": [{"dml": {}}]} - } - } + {"decoder": {"session_options": {"provider_options": [{"dml": {}}]}}} ] } } @@ -1078,11 +1085,7 @@ def test_unresolved_multidevice_ep_does_not_trust_requested_device( "model": { "decoder": { "pipeline": [ - { - "decoder": { - "session_options": {"provider_options": [{"qnn": {}}]} - } - } + {"decoder": {"session_options": {"provider_options": [{"qnn": {}}]}}} ] } } @@ -1096,9 +1099,7 @@ def test_unique_configured_ep_is_reported(self) -> None: cfg = { "model": { "decoder": { - "session_options": { - "provider_options": [{"openvino": {"device_type": "GPU"}}] - } + "session_options": {"provider_options": [{"openvino": {"device_type": "GPU"}}]} } } } @@ -1122,13 +1123,7 @@ def test_mixed_hardware_eps_are_unresolved(self) -> None: assert GenaiSession._hardware_ep_from_config(cfg) is None def test_unknown_provider_is_unresolved(self) -> None: - cfg = { - "model": { - "decoder": { - "session_options": {"provider_options": [{"future_ep": {}}]} - } - } - } + cfg = {"model": {"decoder": {"session_options": {"provider_options": [{"future_ep": {}}]}}}} assert GenaiSession._hardware_ep_from_config(cfg) is None @@ -1270,33 +1265,41 @@ def test_segments_prefill_first_token_and_decode( self, bundle_dir: Path, mock_og: MagicMock ) -> None: # mock_og generator yields 2 tokens (is_done: F, F, T). - # clock calls: before append(0.0), after append(1.0), token1(2.5), token2(3.0). - clock = _clock_from([0.0, 1.0, 2.5, 3.0]) + # clock calls: generator start/end, after append, token1, token2, after + # get_sequence, after decode. + clock = _clock_from([0.0, 0.2, 1.2, 2.7, 3.2, 3.3, 3.4]) with _patch_og(mock_og), GenaiSession(bundle_dir) as session: timing = session.generate_timed([1, 2, 3, 4, 5], clock=clock) assert timing.input_tokens == 5 assert timing.generated_tokens == 2 + assert timing.generator_create_s == pytest.approx(0.2) assert timing.prefill_s == pytest.approx(1.0) assert timing.first_token_s == pytest.approx(1.5) assert timing.decode_s == pytest.approx([0.5]) + assert timing.sequence_fetch_s == pytest.approx(0.1) + assert timing.detokenization_s == pytest.approx(0.1) # TTFT = prefill + first token. assert timing.ttft_s == pytest.approx(2.5) assert timing.total_s == pytest.approx(3.0) - def test_does_not_decode_tokens(self, bundle_dir: Path, mock_og: MagicMock) -> None: - """Only model-compute boundaries are timed — no tokenizer detokenization.""" - clock = _clock_from([0.0, 1.0, 2.5, 3.0]) + def test_times_fetch_and_detokenization_after_model_compute( + self, bundle_dir: Path, mock_og: MagicMock + ) -> None: + """Host fetch and detokenization are measured separately from model compute.""" + clock = _clock_from([0.0, 0.2, 1.2, 2.7, 3.2, 3.3, 3.4]) with _patch_og(mock_og), GenaiSession(bundle_dir) as session: - session.generate_timed([1, 2, 3], clock=clock) + timing = session.generate_timed([1, 2, 3], clock=clock) - stream = mock_og.Tokenizer.return_value.create_stream.return_value - stream.decode.assert_not_called() + mock_og.Generator.return_value.get_sequence.assert_called_once_with(0) + mock_og.Tokenizer.return_value.decode.assert_called_once() + assert timing.sequence_fetch_s == pytest.approx(0.1) + assert timing.detokenization_s == pytest.approx(0.1) def test_forwards_token_list_to_append_tokens( self, bundle_dir: Path, mock_og: MagicMock ) -> None: - clock = _clock_from([0.0, 1.0, 2.5, 3.0]) + clock = _clock_from([0.0, 0.2, 1.2, 2.7, 3.2, 3.3, 3.4]) with _patch_og(mock_og), GenaiSession(bundle_dir) as session: session.generate_timed([7, 8, 9], clock=clock) @@ -1306,8 +1309,8 @@ def test_respects_max_new_tokens(self, bundle_dir: Path, mock_og: MagicMock) -> gen = mock_og.Generator.return_value gen.is_done.side_effect = None gen.is_done.return_value = False # never signals done - # max_new_tokens=1 -> single token: clock before(0.0), after append(1.0), token1(2.0) - clock = _clock_from([0.0, 1.0, 2.0]) + # max_new_tokens=1 -> single token. + clock = _clock_from([0.0, 0.2, 1.2, 2.2, 2.3, 2.4]) with _patch_og(mock_og), GenaiSession(bundle_dir) as session: timing = session.generate_timed([1, 2], GenerationConfig(max_new_tokens=1), clock=clock) @@ -1322,7 +1325,7 @@ def test_raises_when_no_tokens(self, bundle_dir: Path, mock_og: MagicMock) -> No gen = mock_og.Generator.return_value gen.is_done.side_effect = None gen.is_done.return_value = True # done immediately -> 0 tokens - clock = _clock_from([0.0, 1.0]) + clock = _clock_from([0.0, 0.2, 1.2]) with ( _patch_og(mock_og), GenaiSession(bundle_dir) as session, @@ -1331,7 +1334,7 @@ def test_raises_when_no_tokens(self, bundle_dir: Path, mock_og: MagicMock) -> No session.generate_timed([1, 2], clock=clock) def test_auto_loads_on_first_call(self, bundle_dir: Path, mock_og: MagicMock) -> None: - clock = _clock_from([0.0, 1.0, 2.5, 3.0]) + clock = _clock_from([0.0, 0.2, 1.2, 2.7, 3.2, 3.3, 3.4]) with _patch_og(mock_og): session = GenaiSession(bundle_dir) assert not session.is_loaded @@ -1340,7 +1343,7 @@ def test_auto_loads_on_first_call(self, bundle_dir: Path, mock_og: MagicMock) -> def test_uses_context_length_as_max_length(self, bundle_dir: Path, mock_og: MagicMock) -> None: """max_length = min(prompt_len + max_new_tokens, context_length).""" - clock = _clock_from([0.0, 1.0, 2.5, 3.0]) + clock = _clock_from([0.0, 0.2, 1.2, 2.7, 3.2, 3.3, 3.4]) with _patch_og(mock_og), GenaiSession(bundle_dir, context_length=128) as session: session.generate_timed([1, 2, 3], clock=clock) @@ -1352,7 +1355,7 @@ def test_max_length_is_prompt_plus_max_new_tokens( self, bundle_dir: Path, mock_og: MagicMock ) -> None: """When context_length is large, max_length = prompt_len + max_new_tokens.""" - clock = _clock_from([0.0, 1.0, 2.5, 3.0]) + clock = _clock_from([0.0, 0.2, 1.2, 2.7, 3.2, 3.3, 3.4]) cfg = GenerationConfig(max_new_tokens=64) with _patch_og(mock_og), GenaiSession(bundle_dir, context_length=131072) as session: session.generate_timed([1, 2, 3, 4, 5], cfg, clock=clock) From 6d851e5bfe7f523d5ad1a4e4e9c27dded1e484de Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" Date: Thu, 13 Aug 2026 13:31:01 +0800 Subject: [PATCH 2/2] Address GenAI perf review feedback --- docs/commands/perf.md | 4 +- src/winml/modelkit/commands/_perf_genai.py | 162 ++++++++++++-------- src/winml/modelkit/commands/perf.py | 8 +- src/winml/modelkit/session/genai_session.py | 33 ++-- tests/unit/commands/test_perf_cli.py | 6 +- tests/unit/commands/test_perf_genai.py | 112 +++++++++++--- tests/unit/session/test_genai_session.py | 25 +++ 7 files changed, 240 insertions(+), 110 deletions(-) diff --git a/docs/commands/perf.md b/docs/commands/perf.md index 318774340..840d8b6b0 100644 --- a/docs/commands/perf.md +++ b/docs/commands/perf.md @@ -65,8 +65,8 @@ With `--runtime winml-genai`, `winml perf` benchmarks the onnxruntime-genai deco | TTFT | `requests[].model_ttft_duration_ms`, `requests[].request_ttft_duration_ms`, `aggregate.*ttft*` | Model TTFT is prefill + first-token compute. Request TTFT also includes template, tokenization, and generator creation. | | Prefill TPS | `requests[].prefill_tokens_per_second`, `aggregate.prefill_tokens_per_second` | Prompt tokens divided by `prefill_duration_ms`. | | Decode TPS | `requests[].steady_state_decode_tokens_per_second`, `aggregate.steady_state_decode_tokens_per_second` | Tokens after the first divided by the sum of per-token decode durations after the first. | -| RAM Usage | `memory.rss_*` | Classic-compatible RSS fields such as `rss_baseline_mb`, `rss_after_compile_mb`, `rss_after_inference_mb`, `rss_model_load_delta_mb`, `rss_inference_delta_mb`, and `rss_total_delta_mb`. GenAI also emits `rss_peak_mb`. Requires `--memory`. | -| VRAM Usage | `memory.vram_*` | Classic-compatible adapter memory fields such as `vram_local_after_inference_mb`, `vram_shared_after_inference_mb`, load/inference/total deltas, plus GenAI extras for baseline, after-compile, and peak. Requires `--memory`. | +| RAM Usage | `memory.rss_*` | Classic-compatible RSS fields such as `rss_baseline_mb`, `rss_after_compile_mb`, `rss_after_inference_mb`, `rss_model_load_delta_mb`, `rss_inference_delta_mb`, and `rss_total_delta_mb`. `rss_checkpoint_peak_mb` is the maximum of the sampled checkpoints, not a continuously sampled peak. Requires `--memory`. | +| VRAM Usage | `memory.vram_*` | Adapter memory fields are emitted only when the effective GenAI route proves a specific accelerator adapter. Fields include baseline, after-compile, after-inference, load/inference/total deltas, and `vram_*_checkpoint_peak_mb` checkpoint maxima. Requires `--memory`. | ## Examples diff --git a/src/winml/modelkit/commands/_perf_genai.py b/src/winml/modelkit/commands/_perf_genai.py index 0b4549fae..ca28b5885 100644 --- a/src/winml/modelkit/commands/_perf_genai.py +++ b/src/winml/modelkit/commands/_perf_genai.py @@ -45,6 +45,7 @@ short_ep_name, ) from ..utils.constants import ( + ACCELERATOR_DEVICE_TYPES, EP_SUPPORTED_DEVICES, EPNameOrAlias, normalize_ep_name, @@ -195,18 +196,14 @@ def _get_vram_mb(adapter_luid: str | None) -> tuple[float, float]: def _resolve_adapter_luid(device: str, ep: EPNameOrAlias | None) -> str | None: """Resolve the adapter LUID used for best-effort process VRAM sampling.""" - if device == "cpu": + if device not in ACCELERATOR_DEVICE_TYPES: return None ep_name = normalize_ep_name(ep) if ep is not None else None - kinds = [device] if device in ("npu", "gpu") else ["npu", "gpu"] try: from ..sysinfo.pdh_adapters import resolve_adapter_luid - for kind in kinds: - luid = resolve_adapter_luid(kind, ep_name=ep_name) - if luid: - return luid + return resolve_adapter_luid(device, ep_name=ep_name) except Exception: logger.debug("Could not resolve adapter LUID for genai memory tracking", exc_info=True) return None @@ -224,8 +221,8 @@ class _MemorySnapshot: class _GenaiMemoryTracker: """Best-effort process memory tracking for the genai benchmark phases.""" - def __init__(self, *, device: str, ep: EPNameOrAlias | None) -> None: - self._adapter_luid = _resolve_adapter_luid(device, ep) + def __init__(self, *, adapter_luid: str | None) -> None: + self._adapter_luid = adapter_luid self._baseline = _MemorySnapshot() self._after_load = _MemorySnapshot() self._after_benchmark = _MemorySnapshot() @@ -233,7 +230,7 @@ def __init__(self, *, device: str, ep: EPNameOrAlias | None) -> None: def _snapshot(self) -> _MemorySnapshot: gc.collect() rss = _get_rss_mb() - local, shared = _get_vram_mb(self._adapter_luid) + local, shared = _get_vram_mb(self._adapter_luid) if self._adapter_luid else (0.0, 0.0) return _MemorySnapshot(rss_mb=rss, vram_local_mb=local, vram_shared_mb=shared) def record_baseline(self) -> None: @@ -253,57 +250,64 @@ def to_dict(self) -> dict[str, float]: baseline = self._baseline after_load = self._after_load after_benchmark = self._after_benchmark - return { + result = { "rss_baseline_mb": round(baseline.rss_mb, 2), "rss_after_compile_mb": round(after_load.rss_mb, 2), "rss_after_inference_mb": round(after_benchmark.rss_mb, 2), - "rss_peak_mb": round( + "rss_checkpoint_peak_mb": round( max(baseline.rss_mb, after_load.rss_mb, after_benchmark.rss_mb), 2 ), "rss_model_load_delta_mb": self._delta(after_load.rss_mb, baseline.rss_mb), "rss_inference_delta_mb": self._delta(after_benchmark.rss_mb, after_load.rss_mb), "rss_total_delta_mb": self._delta(after_benchmark.rss_mb, baseline.rss_mb), - "vram_local_baseline_mb": round(baseline.vram_local_mb, 2), - "vram_shared_baseline_mb": round(baseline.vram_shared_mb, 2), - "vram_local_after_compile_mb": round(after_load.vram_local_mb, 2), - "vram_shared_after_compile_mb": round(after_load.vram_shared_mb, 2), - "vram_local_after_inference_mb": round(after_benchmark.vram_local_mb, 2), - "vram_shared_after_inference_mb": round(after_benchmark.vram_shared_mb, 2), - "vram_local_peak_mb": round( - max( - baseline.vram_local_mb, - after_load.vram_local_mb, - after_benchmark.vram_local_mb, + } + if self._adapter_luid is None: + return result + result.update( + { + "vram_local_baseline_mb": round(baseline.vram_local_mb, 2), + "vram_shared_baseline_mb": round(baseline.vram_shared_mb, 2), + "vram_local_after_compile_mb": round(after_load.vram_local_mb, 2), + "vram_shared_after_compile_mb": round(after_load.vram_shared_mb, 2), + "vram_local_after_inference_mb": round(after_benchmark.vram_local_mb, 2), + "vram_shared_after_inference_mb": round(after_benchmark.vram_shared_mb, 2), + "vram_local_checkpoint_peak_mb": round( + max( + baseline.vram_local_mb, + after_load.vram_local_mb, + after_benchmark.vram_local_mb, + ), + 2, ), - 2, - ), - "vram_shared_peak_mb": round( - max( - baseline.vram_shared_mb, - after_load.vram_shared_mb, - after_benchmark.vram_shared_mb, + "vram_shared_checkpoint_peak_mb": round( + max( + baseline.vram_shared_mb, + after_load.vram_shared_mb, + after_benchmark.vram_shared_mb, + ), + 2, ), - 2, - ), - "vram_local_model_load_delta_mb": self._delta( - after_load.vram_local_mb, baseline.vram_local_mb - ), - "vram_shared_model_load_delta_mb": self._delta( - after_load.vram_shared_mb, baseline.vram_shared_mb - ), - "vram_local_inference_delta_mb": self._delta( - after_benchmark.vram_local_mb, after_load.vram_local_mb - ), - "vram_shared_inference_delta_mb": self._delta( - after_benchmark.vram_shared_mb, after_load.vram_shared_mb - ), - "vram_local_total_delta_mb": self._delta( - after_benchmark.vram_local_mb, baseline.vram_local_mb - ), - "vram_shared_total_delta_mb": self._delta( - after_benchmark.vram_shared_mb, baseline.vram_shared_mb - ), - } + "vram_local_model_load_delta_mb": self._delta( + after_load.vram_local_mb, baseline.vram_local_mb + ), + "vram_shared_model_load_delta_mb": self._delta( + after_load.vram_shared_mb, baseline.vram_shared_mb + ), + "vram_local_inference_delta_mb": self._delta( + after_benchmark.vram_local_mb, after_load.vram_local_mb + ), + "vram_shared_inference_delta_mb": self._delta( + after_benchmark.vram_shared_mb, after_load.vram_shared_mb + ), + "vram_local_total_delta_mb": self._delta( + after_benchmark.vram_local_mb, baseline.vram_local_mb + ), + "vram_shared_total_delta_mb": self._delta( + after_benchmark.vram_shared_mb, baseline.vram_shared_mb + ), + } + ) + return result # ============================================================================= @@ -598,17 +602,10 @@ def _prompt_text(self, session: GenaiSession) -> str: def run(self) -> GenaiBenchmarkResult: """Execute the benchmark and return aggregated metrics.""" - if self._config.monitor: - hw_monitor = self._build_hw_monitor() - if hw_monitor is not None: - with hw_monitor as hw: - result = self._run_unmonitored() - result.hw_monitor = hw.to_dict() - return result return self._run_unmonitored() def _build_hw_monitor(self) -> Any | None: - """Return an HWMonitor for the genai run, or None when unavailable.""" + """Return an HWMonitor for the proven effective genai route, if available.""" try: from ..session.monitor.hw_monitor import HWMonitor except Exception: @@ -619,20 +616,33 @@ def _build_hw_monitor(self) -> Any | None: logger.warning("HWMonitor unavailable; running genai benchmark without monitoring") return None - device = self._config.device - monitor_device = "auto" if device in ("config", "auto") else device - ep_name = normalize_ep_name(self._config.ep) if self._config.ep is not None else None - return HWMonitor(poll_interval_ms=200, device=monitor_device, ep_name=ep_name) + monitor_device, ep_name = self._effective_monitor_route() + return HWMonitor( + poll_interval_ms=_HW_POLL_INTERVAL_MS, + device=monitor_device, + ep_name=ep_name, + ) def _run_unmonitored(self) -> GenaiBenchmarkResult: - """Execute the benchmark without wrapping it in HWMonitor.""" + """Execute the benchmark with optional monitoring and memory tracking.""" if self._session is None: self._session = self._build_session() session = self._session - + session.resolve_effective_route() + + hw_monitor = self._build_hw_monitor() if self._config.monitor else None + if hw_monitor is not None: + with hw_monitor as hw: + result = self._run_benchmark_body(session) + result.hw_monitor = hw.to_dict() + return result + return self._run_benchmark_body(session) + + def _run_benchmark_body(self, session: GenaiSession) -> GenaiBenchmarkResult: + """Run load + generations after the effective route has been resolved.""" memory_tracker: _GenaiMemoryTracker | None = None if self._config.memory: - memory_tracker = _GenaiMemoryTracker(device=self._config.device, ep=self._config.ep) + memory_tracker = _GenaiMemoryTracker(adapter_luid=self._effective_adapter_luid()) memory_tracker.record_baseline() session_load_start = self._clock() @@ -672,6 +682,24 @@ def _run_unmonitored(self) -> GenaiBenchmarkResult: return result + def _effective_monitor_route(self) -> tuple[str, EPName | None]: + """Return a monitor route that is proven by the effective bundle config.""" + session = self._session + effective_device = getattr(session, "effective_device", None) + effective_ep = getattr(session, "effective_hardware_ep", None) + if effective_device in ACCELERATOR_DEVICE_TYPES and effective_ep is not None: + return effective_device, effective_ep + return "cpu", None + + def _effective_adapter_luid(self) -> str | None: + """Return the proven adapter LUID for VRAM tracking, or None to omit VRAM.""" + session = self._session + effective_device = getattr(session, "effective_device", None) + effective_ep = getattr(session, "effective_hardware_ep", None) + if effective_device not in ACCELERATOR_DEVICE_TYPES or effective_ep is None: + return None + return _resolve_adapter_luid(effective_device, effective_ep) + def _time_one_generation( self, session: GenaiSession, @@ -883,8 +911,8 @@ def display_genai_report(result: GenaiBenchmarkResult, console: Console) -> None cpu = result.hw_monitor.get("cpu", {}) ram = result.hw_monitor.get("ram", {}) device_kind = result.hw_monitor.get("device_kind") - if device_kind in ("npu", "gpu"): - adapter = result.hw_monitor.get(device_kind, {}) + if device_kind in ACCELERATOR_DEVICE_TYPES: + adapter = result.hw_monitor.get("adapter") or result.hw_monitor.get(device_kind, {}) console.print( f" {device_kind.upper()}: {adapter.get('mean_pct', 0):.1f}% avg, " f"{adapter.get('peak_pct', 0):.1f}% peak | " diff --git a/src/winml/modelkit/commands/perf.py b/src/winml/modelkit/commands/perf.py index ee3ec8c4c..56dec6774 100644 --- a/src/winml/modelkit/commands/perf.py +++ b/src/winml/modelkit/commands/perf.py @@ -963,7 +963,9 @@ def _run_single(self) -> BenchmarkResult: "rss_baseline_mb": round(rss_baseline, 2), "rss_after_compile_mb": round(rss_after_compile, 2), "rss_after_inference_mb": round(rss_after_inference, 2), - "rss_peak_mb": round(max(rss_baseline, rss_after_compile, rss_after_inference), 2), + "rss_checkpoint_peak_mb": round( + max(rss_baseline, rss_after_compile, rss_after_inference), 2 + ), "rss_model_load_delta_mb": round(rss_after_compile - rss_baseline, 2), "rss_inference_delta_mb": round(rss_after_inference - rss_after_compile, 2), "rss_total_delta_mb": round(rss_after_inference - rss_baseline, 2), @@ -973,10 +975,10 @@ def _run_single(self) -> BenchmarkResult: "vram_shared_after_compile_mb": round(vram_shared_compile, 2), "vram_local_after_inference_mb": round(vram_local_infer, 2), "vram_shared_after_inference_mb": round(vram_shared_infer, 2), - "vram_local_peak_mb": round( + "vram_local_checkpoint_peak_mb": round( max(vram_local_baseline, vram_local_compile, vram_local_infer), 2 ), - "vram_shared_peak_mb": round( + "vram_shared_checkpoint_peak_mb": round( max(vram_shared_baseline, vram_shared_compile, vram_shared_infer), 2 ), "vram_local_model_load_delta_mb": round( diff --git a/src/winml/modelkit/session/genai_session.py b/src/winml/modelkit/session/genai_session.py index 2be2e56c3..8dec657cb 100644 --- a/src/winml/modelkit/session/genai_session.py +++ b/src/winml/modelkit/session/genai_session.py @@ -496,20 +496,10 @@ def load(self) -> None: session_load_start = time.perf_counter() og = self._import_og() - cfg = self._read_genai_config() - - # Apply the ``ep`` override (if any) to obtain the *effective* config that - # actually drives routing. Precedence is explicit arg > bundle config: - # when no override is set this is the bundle config verbatim. - effective_cfg, overridden = self._apply_ep_override(cfg) - - # Record whether the override actually applied so :attr:`effective_ep` - # (and the perf report) never claim an EP that matched no stage. Warn - # when a requested override is a no-op so ``--ep qnn`` on a flat/all-CPU - # bundle is visibly reported as "config" rather than silently ignored. - self._override_effective = self._override_took_effect(effective_cfg) - self._effective_device = self._resolve_effective_device(effective_cfg) - self._effective_hardware_ep = self._hardware_ep_from_config(effective_cfg) + # Resolve effective routing before any native load work. Perf uses the + # same helper ahead of load() so monitor and memory adapter selection do + # not guess from requested CLI values. + effective_cfg, overridden = self._resolve_effective_config() if self._ep_override is not None and not self._override_effective: logger.warning( "EP override %r was requested but did not take effect (flat/empty " @@ -602,6 +592,12 @@ def unload(self) -> None: self._effective_hardware_ep = None logger.info("GenaiSession unloaded: bundle=%s", self._bundle_dir) + def resolve_effective_route(self) -> None: + """Populate effective routing metadata without loading native GenAI handles.""" + if self._model is not None: + return + self._resolve_effective_config() + def __enter__(self) -> GenaiSession: self.load() return self @@ -923,6 +919,15 @@ def _ensure_loaded(self) -> None: if self._model is None: self.load() + def _resolve_effective_config(self) -> tuple[dict[str, Any], bool]: + """Apply overrides and cache the route that will drive native loading.""" + cfg = self._read_genai_config() + effective_cfg, overridden = self._apply_ep_override(cfg) + self._override_effective = self._override_took_effect(effective_cfg) + self._effective_device = self._resolve_effective_device(effective_cfg) + self._effective_hardware_ep = self._hardware_ep_from_config(effective_cfg) + return effective_cfg, overridden + def _encode_prompt(self, prompt: str | list[int]) -> list[int]: """Return prompt token IDs, encoding via the bundle tokenizer if needed.""" if isinstance(prompt, str): diff --git a/tests/unit/commands/test_perf_cli.py b/tests/unit/commands/test_perf_cli.py index d885525bf..c829a5850 100644 --- a/tests/unit/commands/test_perf_cli.py +++ b/tests/unit/commands/test_perf_cli.py @@ -1996,7 +1996,7 @@ def test_memory_profile_includes_additive_peak_and_compile_fields(self, monkeypa "rss_baseline_mb": 100.0, "rss_after_compile_mb": 150.0, "rss_after_inference_mb": 180.0, - "rss_peak_mb": 180.0, + "rss_checkpoint_peak_mb": 180.0, "rss_model_load_delta_mb": 50.0, "rss_inference_delta_mb": 30.0, "rss_total_delta_mb": 80.0, @@ -2006,8 +2006,8 @@ def test_memory_profile_includes_additive_peak_and_compile_fields(self, monkeypa "vram_shared_after_compile_mb": 50.0, "vram_local_after_inference_mb": 40.0, "vram_shared_after_inference_mb": 70.0, - "vram_local_peak_mb": 40.0, - "vram_shared_peak_mb": 70.0, + "vram_local_checkpoint_peak_mb": 40.0, + "vram_shared_checkpoint_peak_mb": 70.0, "vram_local_model_load_delta_mb": 20.0, "vram_shared_model_load_delta_mb": 30.0, "vram_local_inference_delta_mb": 10.0, diff --git a/tests/unit/commands/test_perf_genai.py b/tests/unit/commands/test_perf_genai.py index 98ad4d48c..bbff01565 100644 --- a/tests/unit/commands/test_perf_genai.py +++ b/tests/unit/commands/test_perf_genai.py @@ -13,6 +13,7 @@ from __future__ import annotations import json +from io import StringIO from pathlib import Path from unittest.mock import MagicMock @@ -106,6 +107,9 @@ def __init__( def load(self) -> None: self.loaded = True + def resolve_effective_route(self) -> None: + pass + def encode(self, text: str) -> list[int]: self.encoded_text = text return list(self._prompt_ids) @@ -427,24 +431,66 @@ def test_memory_profile_uses_classic_perf_field_names(self, monkeypatch) -> None "rss_baseline_mb": 100.0, "rss_after_compile_mb": 150.0, "rss_after_inference_mb": 180.0, - "rss_peak_mb": 180.0, + "rss_checkpoint_peak_mb": 180.0, + "rss_model_load_delta_mb": 50.0, + "rss_inference_delta_mb": 30.0, + "rss_total_delta_mb": 80.0, + } + + def test_memory_profile_includes_vram_only_for_proven_adapter(self, monkeypatch) -> None: + cfg = GenaiPerfConfig( + bundle_dir=Path("x"), + warmup=0, + iterations=1, + max_new_tokens=2, + memory=True, + ) + session = _FakeSession( + [_timing(0.4, 0.6, [0.5])], + effective_device="gpu", + effective_hardware_ep="DmlExecutionProvider", + ) + rss_values = iter([100.0, 150.0, 180.0]) + vram_values = iter([(10.0, 20.0), (30.0, 50.0), (40.0, 70.0)]) + + monkeypatch.setattr(perf_genai, "_get_rss_mb", lambda: next(rss_values), raising=False) + monkeypatch.setattr( + perf_genai, + "_get_vram_mb", + lambda _adapter_luid: next(vram_values), + raising=False, + ) + monkeypatch.setattr( + perf_genai, + "_resolve_adapter_luid", + lambda device, ep: "luid" if (device, ep) == ("gpu", "DmlExecutionProvider") else None, + raising=False, + ) + + result = GenaiPerfBenchmark(cfg, session=session).run() + + assert result.memory_profile == { + "rss_baseline_mb": 100.0, + "rss_after_compile_mb": 150.0, + "rss_after_inference_mb": 180.0, + "rss_checkpoint_peak_mb": 180.0, "rss_model_load_delta_mb": 50.0, "rss_inference_delta_mb": 30.0, "rss_total_delta_mb": 80.0, - "vram_local_baseline_mb": 0.0, - "vram_shared_baseline_mb": 0.0, - "vram_local_after_compile_mb": 0.0, - "vram_shared_after_compile_mb": 0.0, - "vram_local_after_inference_mb": 0.0, - "vram_shared_after_inference_mb": 0.0, - "vram_local_peak_mb": 0.0, - "vram_shared_peak_mb": 0.0, - "vram_local_model_load_delta_mb": 0.0, - "vram_shared_model_load_delta_mb": 0.0, - "vram_local_inference_delta_mb": 0.0, - "vram_shared_inference_delta_mb": 0.0, - "vram_local_total_delta_mb": 0.0, - "vram_shared_total_delta_mb": 0.0, + "vram_local_baseline_mb": 10.0, + "vram_shared_baseline_mb": 20.0, + "vram_local_after_compile_mb": 30.0, + "vram_shared_after_compile_mb": 50.0, + "vram_local_after_inference_mb": 40.0, + "vram_shared_after_inference_mb": 70.0, + "vram_local_checkpoint_peak_mb": 40.0, + "vram_shared_checkpoint_peak_mb": 70.0, + "vram_local_model_load_delta_mb": 20.0, + "vram_shared_model_load_delta_mb": 30.0, + "vram_local_inference_delta_mb": 10.0, + "vram_shared_inference_delta_mb": 20.0, + "vram_local_total_delta_mb": 30.0, + "vram_shared_total_delta_mb": 50.0, } @@ -733,7 +779,9 @@ def fake_ctor(bundle_dir, ep, *, device=None, **_kwargs): GenaiPerfBenchmark(cfg)._build_session() assert captured == {"ep": "openvino", "device": "npu"} - def test_build_hw_monitor_uses_auto_for_config_device(self, monkeypatch) -> None: + def test_build_hw_monitor_uses_cpu_when_effective_adapter_is_unproven( + self, monkeypatch + ) -> None: captured: dict = {} class FakeMonitor: @@ -753,9 +801,9 @@ def __init__(self, **kwargs: object) -> None: monitor = GenaiPerfBenchmark(cfg, session=_FakeSession([]))._build_hw_monitor() assert isinstance(monitor, FakeMonitor) - assert captured == {"poll_interval_ms": 200, "device": "auto", "ep_name": None} + assert captured == {"poll_interval_ms": 200, "device": "cpu", "ep_name": None} - def test_build_hw_monitor_normalizes_requested_ep(self, monkeypatch) -> None: + def test_build_hw_monitor_uses_effective_route_not_requested_values(self, monkeypatch) -> None: captured: dict = {} class FakeMonitor: @@ -770,15 +818,20 @@ def __init__(self, **kwargs: object) -> None: "winml.modelkit.session.monitor.hw_monitor.HWMonitor", FakeMonitor, ) - cfg = GenaiPerfConfig(bundle_dir=Path("bundle"), device="gpu", ep="dml") + cfg = GenaiPerfConfig(bundle_dir=Path("bundle"), device="npu", ep="qnn") + session = _FakeSession( + [], + effective_device="gpu", + effective_hardware_ep="DmlExecutionProvider", + ) - monitor = GenaiPerfBenchmark(cfg, session=_FakeSession([]))._build_hw_monitor() + monitor = GenaiPerfBenchmark(cfg, session=session)._build_hw_monitor() assert isinstance(monitor, FakeMonitor) assert captured == { "poll_interval_ms": 200, "device": "gpu", - "ep_name": perf_genai.normalize_ep_name("dml"), + "ep_name": "DmlExecutionProvider", } @@ -820,6 +873,23 @@ def test_display_genai_report_ep_none_does_not_crash(self) -> None: result = GenaiPerfBenchmark(cfg, session=session).run() display_genai_report(result, Console()) + def test_display_genai_report_prefers_adapter_block_over_gpu_aggregate(self) -> None: + result = self._result() + result.hw_monitor = { + "device_kind": "gpu", + "adapter": {"mean_pct": 91.2, "peak_pct": 98.8, "sample_count": 5}, + "gpu": {"mean_pct": 1.1, "peak_pct": 2.2, "sample_count": 11}, + "cpu": {"mean_pct": 12.3, "peak_pct": 34.5, "sample_count": 5}, + "ram": {"used_mb": 1024.0, "peak_mb": 2048.0}, + } + console = Console(file=StringIO(), width=200, force_terminal=False, record=True) + + display_genai_report(result, console) + + out = console.export_text() + assert "GPU: 91.2% avg, 98.8% peak" in out + assert "GPU: 1.1% avg, 2.2% peak" not in out + def test_genai_output_path_uses_bundle_name(self) -> None: path = genai_output_path(Path("/some/dir/my-bundle")) assert path.parent.name == "my-bundle" diff --git a/tests/unit/session/test_genai_session.py b/tests/unit/session/test_genai_session.py index 1719f339e..bc26850ba 100644 --- a/tests/unit/session/test_genai_session.py +++ b/tests/unit/session/test_genai_session.py @@ -1128,6 +1128,31 @@ def test_unknown_provider_is_unresolved(self) -> None: assert GenaiSession._hardware_ep_from_config(cfg) is None +class TestResolveEffectiveRoute: + def test_resolves_config_route_without_loading_native_handles( + self, bundle_dir_dml_pipeline: Path + ) -> None: + session = GenaiSession(bundle_dir_dml_pipeline) + + session.resolve_effective_route() + + assert session.effective_ep is None + assert session.effective_device == "gpu" + assert session.effective_hardware_ep == "DmlExecutionProvider" + assert session.context_length is None + + def test_noop_override_stays_unresolved_for_cpu_config( + self, bundle_dir_cpu_pipeline: Path + ) -> None: + session = GenaiSession(bundle_dir_cpu_pipeline, ep="qnn", device="npu") + + session.resolve_effective_route() + + assert session.effective_ep is None + assert session.effective_device == "cpu" + assert session.effective_hardware_ep is None + + # --------------------------------------------------------------------------- # Tests: generate / generate_streaming # ---------------------------------------------------------------------------