From e9f28bf7756fde3300a652fa66ba67d8096b2c7f Mon Sep 17 00:00:00 2001 From: hualxie Date: Thu, 27 Aug 2026 17:36:53 +0800 Subject: [PATCH] fix(optrace): include QNN CPU fallback operators --- .../modelkit/session/monitor/ep_monitor.py | 7 + .../modelkit/session/monitor/op_metrics.py | 3 +- .../modelkit/session/monitor/qnn_monitor.py | 123 ++++++++++++++- src/winml/modelkit/session/session.py | 15 +- .../unit/session/monitor/test_qnn_monitor.py | 144 ++++++++++++++++++ .../session/test_build_session_options.py | 12 ++ .../session/test_perf_monitor_integration.py | 42 +++++ 7 files changed, 335 insertions(+), 11 deletions(-) diff --git a/src/winml/modelkit/session/monitor/ep_monitor.py b/src/winml/modelkit/session/monitor/ep_monitor.py index 04509b494..b910a0033 100644 --- a/src/winml/modelkit/session/monitor/ep_monitor.py +++ b/src/winml/modelkit/session/monitor/ep_monitor.py @@ -110,6 +110,13 @@ def get_provider_options(self) -> dict[str, str]: """ return {} + def configure_session_options(self, session_options: Any) -> None: # noqa: B027 - intentional no-op default; profiling monitors override + """Apply monitor settings that are not session config entries. + + Default: no-op. Profiling monitors override this for native + ``SessionOptions`` properties such as ``enable_profiling``. + """ + def set_onnx_op_types(self, onnx_op_types: dict[str, str]) -> None: # noqa: B027 - intentional no-op default; op-tracing monitors override """Inject the ONNX ``node.name -> node.op_type`` map. diff --git a/src/winml/modelkit/session/monitor/op_metrics.py b/src/winml/modelkit/session/monitor/op_metrics.py index b0134bbac..e5b1b0d95 100644 --- a/src/winml/modelkit/session/monitor/op_metrics.py +++ b/src/winml/modelkit/session/monitor/op_metrics.py @@ -94,6 +94,7 @@ class OperatorMetrics: onnx_attributes: dict[str, Any] | None = None onnx_inputs: dict[str, dict[str, Any]] | None = None onnx_outputs: dict[str, dict[str, Any]] | None = None + ep: str | None = None @property def sample_count(self) -> int: @@ -125,7 +126,7 @@ def p90_us(self) -> float: def to_dict(self) -> dict[str, Any]: """Serialize to dict, omitting only unset opt-in ONNX metadata.""" result = asdict(self) - for key in ("onnx_op_type", "onnx_attributes", "onnx_inputs", "onnx_outputs"): + for key in ("ep", "onnx_op_type", "onnx_attributes", "onnx_inputs", "onnx_outputs"): if result[key] is None: del result[key] return result diff --git a/src/winml/modelkit/session/monitor/qnn_monitor.py b/src/winml/modelkit/session/monitor/qnn_monitor.py index a4385d06f..4dc530ce6 100644 --- a/src/winml/modelkit/session/monitor/qnn_monitor.py +++ b/src/winml/modelkit/session/monitor/qnn_monitor.py @@ -214,6 +214,11 @@ def __init__( self._csv_path: Path = ( self._output_dir / f"profiling_output_{uuid.uuid4().hex}.csv" ).resolve() + self._ort_profile_prefix: Path = ( + self._output_dir / f"onnxruntime_profile_{uuid.uuid4().hex}" + ).resolve() + self._ort_profile_path: Path | None = None + self._require_ort_profile: bool = False self._extra: dict[str, str] = dict(extra_provider_options or {}) self._entered: bool = False self._result: OpTraceResult | None = None @@ -339,6 +344,12 @@ def get_provider_options(self) -> dict[str, str]: opts["profiling_file_path"] = str(self._csv_path) return opts + def configure_session_options(self, session_options: Any) -> None: + """Enable ORT profiling so CPU fallback nodes can be merged.""" + session_options.enable_profiling = True + session_options.profile_file_prefix = str(self._ort_profile_prefix) + self._require_ort_profile = True + # ------------------------------------------------------------------ # Context manager # ------------------------------------------------------------------ @@ -522,10 +533,10 @@ def parse_existing_artifacts( Args: level: ``"basic"`` (CSV only) or ``"detail"`` (CSV + QHAS JSON). - artifacts: Mapping of artifact kind to absolute path. Must - contain ``"csv"``; may contain ``"qhas"`` for the detail - path. When ``"qhas"`` is provided, the QHAS viewer - shell-out is skipped and the JSON is parsed directly. + artifacts: Mapping of artifact kind to absolute path. Must contain + ``"csv"``; may contain ``"qhas"`` and ``"ort_profile"``. + When ``"qhas"`` is provided, the QHAS viewer shell-out is + skipped and the JSON is parsed directly. onnx_op_types: Optional ONNX node.name -> op_type map for L1 resolution. Defaults to empty (L2/L3/L4 only). @@ -545,6 +556,10 @@ def parse_existing_artifacts( # with arbitrary names. instance._csv_path = csv_path.resolve() instance.set_onnx_op_types(onnx_op_types or {}) + ort_profile_path = artifacts.get("ort_profile") + if ort_profile_path is not None: + instance._ort_profile_path = Path(ort_profile_path).resolve() + instance._require_ort_profile = True qhas_path = artifacts.get("qhas") # Route through _parse_artifacts_safe so the offline path honours the @@ -732,6 +747,20 @@ def _metadata_mean(field: str) -> float: status = "basic_fallback" logger.warning("QNNMonitor: QHAS unavailable; detail mode degraded to basic") + cpu_operators, ort_profile_path = self._parse_cpu_operators() + if ort_profile_path is not None: + artifacts["ort_profile"] = str(ort_profile_path) + operators.extend(cpu_operators) + if cpu_operators: + total_duration_us = sum(operator.duration_us for operator in operators) + for operator in operators: + operator.percent_of_total = ( + operator.duration_us / total_duration_us * 100 + if total_duration_us > 0 + else 0.0 + ) + operators.sort(key=lambda op: op.duration_us, reverse=True) + return OpTraceResult( model=None, device="npu", @@ -746,6 +775,92 @@ def _metadata_mean(field: str) -> float: fallback_reason=fallback_reason, ) + def _parse_cpu_operators(self) -> tuple[list[OperatorMetrics], Path | None]: + """Parse CPU fallback node timings from this run's ORT profile.""" + if self._ort_profile_path is not None: + candidates = [self._ort_profile_path] if self._ort_profile_path.is_file() else [] + else: + candidates = sorted( + self._ort_profile_prefix.parent.glob( + f"{self._ort_profile_prefix.name}*.json" + ) + ) + if not candidates: + if self._require_ort_profile: + expected = self._ort_profile_path or self._ort_profile_prefix + raise ValueError(f"ORT profile was not produced at {expected}") + return [], None + if len(candidates) > 1: + raise ValueError( + f"multiple ORT profiles matched {self._ort_profile_prefix}: {candidates}" + ) + + profile_path = candidates[0] + profile = json.loads(profile_path.read_text(encoding="utf-8")) + if not isinstance(profile, list): + raise TypeError(f"ORT profile must contain a list of events: {profile_path}") + + samples_by_node: dict[str, dict[str, Any]] = {} + suffix = "_kernel_time" + for event in profile: + if not isinstance(event, dict): + continue + name = event.get("name") + args = event.get("args") + if ( + not isinstance(name, str) + or not name.endswith(suffix) + or not isinstance(args, dict) + or args.get("provider") != "CPUExecutionProvider" + ): + continue + + raw_op_path = name[: -len(suffix)] + normalized_op_path = _TOKEN_SUFFIX.sub("", raw_op_path) + op_path = ( + normalized_op_path + if normalized_op_path in self._onnx_op_types + else raw_op_path + ) + duration = event.get("dur") + if not isinstance(duration, int | float): + raise TypeError(f"CPU operator {name!r} has invalid duration {duration!r}") + entry = samples_by_node.setdefault( + op_path, + { + "op_type": args.get("op_name"), + "samples_us": [], + }, + ) + entry["samples_us"].append(float(duration)) + + operators: list[OperatorMetrics] = [] + for op_path, entry in samples_by_node.items(): + samples_us = entry["samples_us"] + if self._expected_measured_samples is not None: + expected_total = self._warmup_samples + self._expected_measured_samples + if len(samples_us) != expected_total: + raise ValueError( + f"ORT profile sample count mismatch for CPU operator {op_path!r}: " + f"expected {expected_total}, got {len(samples_us)}" + ) + samples_us = samples_us[self._warmup_samples :] + op_type = entry["op_type"] + operators.append( + OperatorMetrics( + name=( + op_type + if isinstance(op_type, str) and op_type + else self._resolve_op_type(op_path) + ), + op_path=op_path, + ep="CPUExecutionProvider", + duration_us=sum(samples_us) / len(samples_us), + samples_us=samples_us, + ) + ) + return operators, profile_path + def _epcontext_partition_count(self) -> int: """Return the number of EPContext partitions represented in each inference.""" if self._running_model_path is None: diff --git a/src/winml/modelkit/session/session.py b/src/winml/modelkit/session/session.py index d62a74fe5..a44ba6340 100644 --- a/src/winml/modelkit/session/session.py +++ b/src/winml/modelkit/session/session.py @@ -341,6 +341,9 @@ def _build_session_options( for key, value in session_option_entries.items(): so.add_session_config_entry(key, value) + if ep_monitor is not None: + ep_monitor.configure_session_options(so) + handle = ep_device.device._ort options = ( dict(provider_options) @@ -502,7 +505,7 @@ def __init__( so = _build_session_options( self._ep_device, self._ep_config, - None, + self._ep_monitor, self._session_options_factory, session_option_entries=self._active_session_option_entries, provider_options=self._provider_options, @@ -548,7 +551,7 @@ def compile(self) -> None: sess_options=_build_session_options( self._ep_device, self._ep_config, - None, + self._ep_monitor, self._session_options_factory, session_option_entries=self._active_session_option_entries, provider_options=self._provider_options, @@ -591,7 +594,7 @@ def compile(self) -> None: runtime_so = _build_session_options( self._ep_device, self._ep_config, - None, + self._ep_monitor, self._session_options_factory, session_option_entries=self._active_session_option_entries, provider_options=self._provider_options, @@ -714,7 +717,7 @@ def _prepare_epcontext_model( so = _build_session_options( self._ep_device, self._ep_config, - None, + self._ep_monitor, self._session_options_factory, session_option_entries=self._active_session_option_entries, provider_options=self._provider_options, @@ -1539,7 +1542,7 @@ def _restore_baseline() -> Exception | None: sess_options=_build_session_options( self._ep_device, self._ep_config, - None, + self._ep_monitor, self._session_options_factory, session_option_entries=saved_sess_entries, provider_options=saved_prov, @@ -1563,7 +1566,7 @@ def _restore_baseline() -> Exception | None: so = _build_session_options( self._ep_device, self._ep_config, - None, + effective_monitor, self._session_options_factory, session_option_entries=desired_sess_entries, provider_options=new_prov, diff --git a/tests/unit/session/monitor/test_qnn_monitor.py b/tests/unit/session/monitor/test_qnn_monitor.py index 6fa86c0f9..a20e952f1 100644 --- a/tests/unit/session/monitor/test_qnn_monitor.py +++ b/tests/unit/session/monitor/test_qnn_monitor.py @@ -291,6 +291,34 @@ def test_get_provider_options_detail(): assert QNNMonitor(level="detail").get_provider_options()["profiling_level"] == "optrace" +def test_configure_session_options_enables_ort_profiling(tmp_path): + from winml.modelkit.session.monitor.qnn_monitor import QNNMonitor + + monitor = QNNMonitor(output_dir=tmp_path) + session_options = MagicMock() + + monitor.configure_session_options(session_options) + + assert session_options.enable_profiling is True + assert session_options.profile_file_prefix == str(monitor._ort_profile_prefix) + + +def test_configured_monitor_reports_missing_ort_profile(tmp_path): + from winml.modelkit.session.monitor.qnn_monitor import QNNMonitor + + monitor = QNNMonitor(output_dir=tmp_path) + monitor.configure_session_options(MagicMock()) + monitor.__enter__() + _write_named_profile(monitor._csv_path, "qnn_node") + + monitor.__exit__(None, None, None) + + assert monitor.result is not None + assert monitor.result.status == "parse_failed" + assert monitor.result.error is not None + assert "ORT profile was not produced" in monitor.result.error + + def test_extra_provider_options_pass_through(): """User-supplied extras are honored (e.g. backend_path for bundled ORT QNN).""" from winml.modelkit.session.monitor.qnn_monitor import QNNMonitor @@ -485,6 +513,122 @@ def test_basic_metrics_exclude_warmup_samples(tmp_path): ) +def test_basic_metrics_include_cpu_fallback_ops(tmp_path): + from winml.modelkit.session.monitor.qnn_monitor import QNNMonitor + + samples = [ + { + "hvx_threads": 4, + "accel_execute_cycles": 100, + "accel_execute_us": 10, + "operator_cycles": 50, + } + for _ in range(3) + ] + monitor = QNNMonitor(output_dir=tmp_path) + monitor.set_onnx_op_types({"fallback_node": "QLinearConv"}) + monitor.set_perf_window(warmup=1, measured_iterations=2) + monitor.__enter__() + _write_basic_profile(monitor._csv_path, samples) + ort_profile = monitor._ort_profile_prefix.with_name( + f"{monitor._ort_profile_prefix.name}_generated.json" + ) + ort_profile.write_text( + json.dumps( + [ + { + "name": "fallback_node_token_7_kernel_time", + "dur": duration, + "args": { + "op_name": "QLinearConv", + "provider": "CPUExecutionProvider", + }, + } + for duration in (10, 20, 30) + ] + ), + encoding="utf-8", + ) + + monitor.__exit__(None, None, None) + + assert monitor.result is not None + assert monitor.result.status == "ok" + operators = {operator.op_path: operator for operator in monitor.result.operators} + cpu_operator = operators["fallback_node"] + assert cpu_operator.name == "QLinearConv" + assert cpu_operator.ep == "CPUExecutionProvider" + assert cpu_operator.samples_us == [20.0, 30.0] + assert cpu_operator.duration_us == 25.0 + assert monitor.result.artifacts["ort_profile"] == str(ort_profile) + assert sum(operator.percent_of_total for operator in operators.values()) == pytest.approx( + 100.0 + ) + + +def test_cpu_fallback_preserves_unmapped_optimizer_token_names(tmp_path): + from winml.modelkit.session.monitor.qnn_monitor import QNNMonitor + + monitor = QNNMonitor(output_dir=tmp_path) + ort_profile = monitor._ort_profile_prefix.with_suffix(".json") + ort_profile.write_text( + json.dumps( + [ + { + "name": f"Transpose_token_{token}_kernel_time", + "dur": 10, + "args": { + "op_name": "Transpose", + "provider": "CPUExecutionProvider", + }, + } + for token in (21, 24) + ] + ), + encoding="utf-8", + ) + + operators, _ = monitor._parse_cpu_operators() + + assert {operator.op_path for operator in operators} == { + "Transpose_token_21", + "Transpose_token_24", + } + + +def test_parse_existing_artifacts_includes_ort_cpu_profile(tmp_path): + from winml.modelkit.session.monitor.qnn_monitor import QNNMonitor + + csv_path = tmp_path / "profile.csv" + _write_named_profile(csv_path, "qnn_node") + ort_profile = tmp_path / "ort_profile.json" + ort_profile.write_text( + json.dumps( + [ + { + "name": "cpu_node_kernel_time", + "dur": 12, + "args": { + "op_name": "Add", + "provider": "CPUExecutionProvider", + }, + } + ] + ), + encoding="utf-8", + ) + + result = QNNMonitor.parse_existing_artifacts( + level="basic", + artifacts={"csv": csv_path, "ort_profile": ort_profile}, + ) + + cpu_operator = next(operator for operator in result.operators if operator.ep) + assert cpu_operator.op_path == "cpu_node" + assert cpu_operator.ep == "CPUExecutionProvider" + assert result.artifacts["ort_profile"] == str(ort_profile.resolve()) + + def test_basic_metrics_coalesce_multiple_epcontext_partitions(tmp_path): from winml.modelkit.session.monitor.qnn_monitor import QNNMonitor diff --git a/tests/unit/session/test_build_session_options.py b/tests/unit/session/test_build_session_options.py index cf08734e1..1e044e51e 100644 --- a/tests/unit/session/test_build_session_options.py +++ b/tests/unit/session/test_build_session_options.py @@ -130,6 +130,18 @@ def test_build_session_options_monitor_plumbs_session_options(qnn_npu: WinMLEPDe assert args[1]["profiling_level"] == "detailed" +def test_build_session_options_allows_monitor_native_configuration( + qnn_npu: WinMLEPDevice, +) -> None: + monitor = _stub_monitor(prov={}) + fake_so = MagicMock() + + with patch("winml.modelkit.session.session.ort.SessionOptions", return_value=fake_so): + _build_session_options(qnn_npu, ep_monitor=monitor) + + monitor.configure_session_options.assert_called_once_with(fake_so) + + def test_build_session_options_info_log_omits_provider_option_values( qnn_npu: WinMLEPDevice, caplog: pytest.LogCaptureFixture ) -> None: diff --git a/tests/unit/session/test_perf_monitor_integration.py b/tests/unit/session/test_perf_monitor_integration.py index 0e4fbe318..a93b4b5a7 100644 --- a/tests/unit/session/test_perf_monitor_integration.py +++ b/tests/unit/session/test_perf_monitor_integration.py @@ -582,6 +582,48 @@ def get_session_options(self): assert session._active_session_option_entries == baseline_session_entries +def test_constructor_monitor_native_configuration_is_reused_by_perf(): + from unittest.mock import MagicMock, patch + + from winml.modelkit.session.monitor.ep_monitor import NullEPMonitor + from winml.modelkit.session.session import WinMLSession + + from .conftest import make_stub_winml_ep_device + + class _NativeMonitor(NullEPMonitor): + def __init__(self): + self.configured: list[object] = [] + + def configure_session_options(self, session_options): + self.configured.append(session_options) + session_options.enable_profiling = True + + monitor = _NativeMonitor() + session_options = MagicMock() + runtime_session = MagicMock() + cpu_ep_device = make_stub_winml_ep_device( + _get_real_cpu_ort_device(), + "CPUExecutionProvider", + ) + + with patch( + "winml.modelkit.session.session.ort.InferenceSession", + return_value=runtime_session, + ) as inference_session: + session = WinMLSession( + get_minimal_onnx_model_path(), + ep_device=cpu_ep_device, + ep_monitor=monitor, + session_options=lambda: session_options, + ) + with session.perf(monitor=monitor): + pass + + assert monitor.configured == [session_options] + assert session_options.enable_profiling is True + inference_session.assert_called_once() + + def test_constructor_monitor_snapshots_restore_after_perf_rebuild(): """Constructor-applied monitor options are tracked and restored after perf rebuilds.""" from unittest.mock import MagicMock, patch