Add ETDump profiling workflow for CpuBackend (#24335)

Summary:
Pull Request resolved: #24335

`etdump_cpu` runs a CPU delegate model through a traced runner with `ET_CPU_ETDUMP`, drops warmup samples, and writes `profile.json` with median/min/max latency per plan step and XNNPACK operator, plus each XNNPACK operator's input and output shapes. Each CPU delegate's plan is reassembled from the runner log, so a program with several CPU delegates is profiled as a whole. Events with an unexpected sample count are reported with a warning, and malformed operator metadata degrades to no shapes. It fails if any plan step or, for XNNPACK regions, operator events are missing from the ETDump.

The model runner gains configurable warmups (`ET_CPU_WARMUP_RUNS`), timed iterations (`ET_CPU_TIMED_RUNS`), golden tolerances (`ET_CPU_ATOL`, `ET_CPU_RTOL`) and a latency summary. The workflows README now covers export and profiling.

Authored with Claude Code.

Differential Revision: D128598106

Author: JakeStevens

backends/cpu/BUCK

@@ -88,6 +88,28 @@ fbcode_target(
     ],
 )
 
+fbcode_target(
+    _kind = runtime.python_library,
+    name = "etdump_lib",
+    srcs = ["workflows/etdump.py"],
+    deps = ["//executorch/devtools/inspector:lib"],
+)
+
+fbcode_target(
+    _kind = runtime.python_binary,
+    name = "etdump_cpu",
+    par_style = "xar",
+    main_module = "executorch.backends.cpu.workflows.etdump",
+    deps = [":etdump_lib"],
+)
+
+fbcode_target(
+    _kind = runtime.python_test,
+    name = "test_etdump",
+    srcs = ["test/test_etdump.py"],
+    deps = [":etdump_lib"],
+)
+
 fbcode_target(
     _kind = runtime.python_test,
     name = "test_aot",

backends/cpu/test/runner.cpp

@@ -11,6 +11,7 @@
 #include <executorch/extension/threadpool/threadpool_guard.h>
 
 #include <algorithm>
+#include <chrono>
 #include <cmath>
 #include <cstdio>
 #include <cstdlib>
@@ -40,8 +41,25 @@ int run_against_golden(
     data[index] = static_cast<float>(index % 251) / 250.0f;
   }
   auto input = executorch::extension::from_blob(data.data(), sizes);
-  for (int run = 0; run < 2; ++run) {
+  const int warmup_runs = std::getenv("ET_CPU_WARMUP_RUNS")
+      ? std::max(0, std::atoi(std::getenv("ET_CPU_WARMUP_RUNS")))
+      : 1;
+  const int timed_runs = std::getenv("ET_CPU_TIMED_RUNS")
+      ? std::max(1, std::atoi(std::getenv("ET_CPU_TIMED_RUNS")))
+      : 1;
+  const float atol = std::getenv("ET_CPU_ATOL")
+      ? std::max(0.0f, std::strtof(std::getenv("ET_CPU_ATOL"), nullptr))
+      : 1e-4f;
+  const float rtol = std::getenv("ET_CPU_RTOL")
+      ? std::max(0.0f, std::strtof(std::getenv("ET_CPU_RTOL"), nullptr))
+      : 1e-4f;
+  std::vector<double> latencies;
+  for (int run = 0; run < warmup_runs + timed_runs; ++run) {
+    const auto start = std::chrono::steady_clock::now();
     auto outputs = module.forward(executorch::runtime::EValue(*input));
+    const double latency_ms = std::chrono::duration<double, std::milli>(
+                                  std::chrono::steady_clock::now() - start)
+                                  .count();
     if (!outputs.ok()) {
       fprintf(
           stderr,
@@ -65,7 +83,7 @@ int run_against_golden(
       const float error = std::abs(actual[index] - golden[index]);
       max_error = std::max(max_error, error);
       if (!std::isfinite(actual[index]) || !std::isfinite(golden[index]) ||
-          error > 1e-4f + 1e-4f * std::abs(golden[index])) {
+          error > atol + rtol * std::abs(golden[index])) {
         fprintf(
             stderr,
             "Mismatch at %zu: actual=%g golden=%g\n",
@@ -80,7 +98,19 @@ int run_against_golden(
         run,
         golden.size(),
         max_error);
+    printf("Inference: run=%d latency_ms=%.9g\n", run, latency_ms);
+    if (run >= warmup_runs) {
+      latencies.push_back(latency_ms);
+    }
   }
+  std::sort(latencies.begin(), latencies.end());
+  printf(
+      "Latency: median_ms=%g min_ms=%g max_ms=%g warmup=%d iterations=%d\n",
+      latencies[latencies.size() / 2],
+      latencies.front(),
+      latencies.back(),
+      warmup_runs,
+      timed_runs);
   return 0;
 }
 

backends/cpu/test/test_etdump.py

@@ -0,0 +1,122 @@
+# Copyright (c) Meta Platforms, Inc. and affiliates.
+# All rights reserved.
+#
+# This source code is licensed under the BSD-style license found in the
+# LICENSE file in the root directory of this source tree.
+
+from __future__ import annotations
+
+import json
+import unittest
+from pathlib import Path
+from types import SimpleNamespace
+from unittest.mock import patch
+
+from executorch.backends.cpu.workflows import etdump
+
+PLAN = {
+    "regions": [
+        {"provider": "XNNPACK", "implementation": "subgraph", "nodes": ["conv", "norm"]}
+    ]
+}
+STEP = "XNNPACK/subgraph:conv+1"
+
+
+def chunk_lines(plan: dict) -> list[str]:
+    payload = json.dumps(plan).encode()
+    chunks = [payload[start : start + 16] for start in range(0, len(payload), 16)]
+    return [
+        f"I CPUBackend.cpp:259] CPU_PLAN_CHUNK {index} {len(chunks)} {chunk.hex()}"
+        for index, chunk in enumerate(chunks)
+    ]
+
+
+def event(name, samples, delegated=True, metadata=b""):
+    return SimpleNamespace(
+        name=name,
+        perf_data=SimpleNamespace(raw=samples),
+        is_delegated_op=delegated,
+        raw_delegate_debug_metadatas=[metadata],
+    )
+
+
+class ETDumpTest(unittest.TestCase):
+    def summarize(self, events):
+        inspector = SimpleNamespace(event_blocks=[SimpleNamespace(events=events)])
+        with patch.object(etdump, "Inspector", return_value=inspector):
+            return etdump.summarize(
+                Path("model.etdump"), [PLAN], warmup=1, iterations=2
+            )
+
+    def test_decode_plans_reassembles_each_delegate(self):
+        other = {
+            "regions": [
+                {
+                    "provider": "Reference",
+                    "implementation": "registry",
+                    "nodes": ["gelu"],
+                }
+            ]
+        }
+        log = "\n".join(chunk_lines(PLAN) + ["unrelated"] + chunk_lines(other))
+        self.assertEqual(etdump.decode_plans(log), [PLAN, other])
+
+    def test_decode_plans_rejects_incomplete_or_inconsistent_traces(self):
+        lines = chunk_lines(PLAN)
+        total = f" {len(lines)} "
+        mixed = lines[:1] + [
+            line.replace(total, f" {len(lines) + 1} ") for line in lines[1:]
+        ]
+        for invalid in (lines[:-1], lines[1:], list(reversed(lines)), mixed, []):
+            with self.subTest(invalid=invalid), self.assertRaises(RuntimeError):
+                etdump.decode_plans("\n".join(invalid))
+
+    def test_summarize_drops_warmup_and_reports_shapes(self):
+        shapes = {"inputs": [[1, 3]], "outputs": [[1, 3]]}
+        profile = self.summarize(
+            [
+                event(STEP, [9.0, 2.0, 4.0]),
+                event(
+                    "Convolution #1",
+                    [8.0, 1.0, 3.0],
+                    metadata=json.dumps(shapes).encode(),
+                ),
+                event("Method::init", [5.0], delegated=False),
+            ]
+        )
+        rows = {row["name"]: row for row in profile["events"]}
+        self.assertEqual(rows[STEP]["kind"], "step")
+        self.assertEqual(rows[STEP]["median_ms"], 3.0)
+        self.assertEqual(rows["Convolution #1"]["shapes"], shapes)
+        self.assertEqual(rows["Method::init"]["kind"], "init")
+        self.assertEqual(profile["totals_ms"], {"step": 3.0, "provider": 2.0})
+
+    def test_summarize_skips_empty_samples_and_ignores_malformed_metadata(self):
+        with self.assertLogs(etdump.logger, "WARNING"):
+            profile = self.summarize(
+                [
+                    event(STEP, [9.0, 2.0, 4.0]),
+                    event("Convolution #1", [8.0, 1.0, 3.0], metadata=b"not json"),
+                    event("Empty #1", []),
+                ]
+            )
+        rows = {row["name"]: row for row in profile["events"]}
+        self.assertNotIn("Empty #1", rows)
+        self.assertIsNone(rows["Convolution #1"]["shapes"])
+
+    def test_summarize_warns_about_unexpected_delegate_sample_counts(self):
+        with self.assertLogs(etdump.logger, "WARNING") as logs:
+            profile = self.summarize(
+                [
+                    event(STEP, [9.0, 2.0, 4.0]),
+                    event("Convolution #1", [8.0, 1.0, 3.0]),
+                    event("Transpose #1", [1.0] * 5),
+                ]
+            )
+        self.assertIn("Transpose #1 has 5 samples", logs.output[0])
+        rows = {row["name"]: row for row in profile["events"]}
+        self.assertEqual(rows["Transpose #1"]["kind"], "init")
+
+    def test_summarize_rejects_missing_steps(self):
+        with self.assertRaisesRegex(RuntimeError, "lacks CPU plan steps"):
+            self.summarize([event("Convolution #1", [8.0, 1.0, 3.0])])

backends/cpu/workflows/README.md

@@ -1,4 +1,4 @@
-# CPU torchvision exports
+# Torchvision CPU workflows
 
 List classifiers or export a model with the registered CPU or XNNPACK FP32 recipe:
 
@@ -31,3 +31,32 @@ preprocessing provenance, and runtime/artifact identity. `golden.bin` holds the
 edge-program logits for ET exports and matches `eager.bin` for Native exports. A
 runner can feed `input.bin` to either artifact and compare its output against
 `eager.bin` to validate it before measuring latency.
+
+The local CPU runners support repeatable warm-latency checks through
+`ET_CPU_WARMUP_RUNS` and `ET_CPU_TIMED_RUNS`. Golden checks use `ET_CPU_ATOL` and
+`ET_CPU_RTOL`; both default to `1e-4`.
+
+## ETDump
+
+Every CPU plan step records a delegate event named
+`provider/implementation:first_node[+N]`, so all providers are traced without
+provider changes. The XNNPACK provider also enables XNNPACK runtime profiling and
+records `<operator> #<n>` events, such as `Transpose (ND, X32) #3`, inside its
+step. With `-c executorch.cpu_xnnpack_operator_shapes=true`, each operator
+event also carries its input and output shapes as JSON delegate metadata
+(`shapes` in `profile.json`). Tracing compiles out unless the runner is built
+with the event tracer enabled, and the shapes, which read XNNPACK's internal
+runtime, compile out unless that option is also set:
+
+```bash
+buck build -j 2 @fbcode//mode/opt -c executorch.event_tracer_enabled=true -c executorch.cpu_xnnpack_operator_shapes=true fbcode//executorch/backends/cpu:runner fbcode//executorch/backends/cpu:etdump_cpu --show-full-json-output
+"$CPU_ETDUMP" --runner "$CPU_TRACED_RUNNER" --model artifacts/cpu/model.pte --golden artifacts/cpu/golden.bin --output results/etdump
+```
+
+`:runner` links only XNNPACK and ET, so XNNPACK takes the whole ConvNeXt graph.
+
+The runner writes `model.etdump` when `ET_CPU_ETDUMP` is set. The workflow drops
+warmup samples and writes `profile.json` with median/min/max per event. Provider
+operator events nest inside their step, so step and provider totals are reported
+separately. Trailing positional arguments are passed to the runner as provider
+preferences.