Add ETDump tracing to CpuBackend (#23926)

backends/cpu/runtime/CPUBackend.cpp

@@ -95,7 +95,10 @@ class CPUExecution {
       return error;
     }
     plan_ = std::make_unique<CPUPlan>(
-        graph, buffers_, std::move(configuration), execution_context());
+        graph,
+        buffers_,
+        std::move(configuration),
+        execution_context(context.event_tracer()));
     error = plan_->select();
     if (error != Error::Ok) {
       return error;

backends/cpu/runtime/CPUPlan.cpp

@@ -5,6 +5,7 @@
 // LICENSE file in the root directory of this source tree.
 
 #include <executorch/backends/cpu/runtime/CPUPlan.h>
+#include <executorch/runtime/core/event_tracer_hooks_delegate.h>
 
 #include <algorithm>
 #include <cstring>
@@ -172,7 +173,13 @@ Error CPUPlan::execute(const ExecutionContext& context) {
     }
   }
   for (auto& step : steps_) {
+    const auto entry = event_tracer_start_profiling_delegate(
+        context.event_tracer,
+        step.trace_name.c_str(),
+        kUnsetDelegateDebugIntId);
     const auto error = step.executable->run(context);
+    event_tracer_end_profiling_delegate(context.event_tracer, entry);
+    step.executable->submit_trace();
     if (error != Error::Ok) {
       return error;
     }
@@ -342,7 +349,7 @@ Error CPUPlan::select() {
     // cycle.
     if (steps_.empty() || steps_.back().implementation != selected ||
         !selected->accepts_regions() || !connected) {
-      steps_.push_back({selected_provider, selected, {}, nullptr, {}});
+      steps_.push_back({selected_provider, selected, {}, nullptr, {}, {}});
     }
     steps_.back().region.nodes.push_back(id);
     node_regions.at(id) = steps_.size() - 1;
@@ -380,6 +387,14 @@ Error CPUPlan::select() {
     step.region.outputs.assign(outputs.begin(), outputs.end());
     std::sort(step.region.inputs.begin(), step.region.inputs.end());
     std::sort(step.region.outputs.begin(), step.region.outputs.end());
+#ifdef ET_EVENT_TRACER_ENABLED
+    step.trace_name = std::string(step.provider->name()) + "/" +
+        std::string(step.implementation->name()) + ":" +
+        graph.node(step.region.nodes.front()).name;
+    if (step.region.nodes.size() > 1) {
+      step.trace_name += "+" + std::to_string(step.region.nodes.size() - 1);
+    }
+#endif
   }
   requirements_.resize(graph.values.size());
   for (size_t id = 0; id < graph.values.size(); ++id) {

backends/cpu/runtime/CPUPlan.h

@@ -18,6 +18,8 @@ struct PlanStep {
   KernelRegion region;
   std::unique_ptr<Executable> executable;
   StorageRequirements storage;
+  /// ETDump delegate event name: provider/implementation:first_node[+N].
+  std::string trace_name;
 };
 
 /// One static prepared plan. Graph, bindings and allocator outlive the plan.

backends/cpu/runtime/KernelProvider.h

@@ -66,6 +66,8 @@ struct ExecutionContext {
   size_t threads = 1;
   bool avx2_fma = false;
   pthreadpool* threadpool = nullptr;
+  /// Providers enable internal profiling when set during preparation. The plan
+  /// records one delegate event per step when set during execution.
   runtime::EventTracer* event_tracer = nullptr;
 };
 
@@ -118,6 +120,9 @@ class Executable {
   virtual runtime::Error reshape() = 0;
   virtual runtime::Error bind(const Buffer& scratch = {}) = 0;
   virtual runtime::Error run(const ExecutionContext& context) = 0;
+  /// Called after the plan closes the step's trace event, so internal events
+  /// are logged without inflating it. Called even when run fails.
+  virtual void submit_trace() {}
 };
 
 class KernelImplementation {

backends/cpu/runtime/providers/xnnpack/XNNPACKProvider.cpp

@@ -6,20 +6,27 @@
 
 #include <executorch/backends/cpu/runtime/op_helpers/Convolution.h>
 #include <executorch/backends/cpu/runtime/providers/xnnpack/XNNPACKProvider.h>
+#include <executorch/backends/xnnpack/runtime/profiling/XNNProfiler.h>
 #include <xnnpack.h>
+#ifdef ET_EVENT_TRACER_ENABLED
+#include "src/xnnpack/subgraph.h" // @manual
+#endif
 
 #include <algorithm>
 #include <array>
 #include <cmath>
 #include <limits>
 #include <map>
 #include <numeric>
+#include <string>
 #include <string_view>
+#include <unordered_map>
 #include <unordered_set>
 
 namespace executorch::backends::cpu {
 namespace {
 using namespace executorch::runtime;
+using executorch::backends::xnnpack::delegate::profiling::XNNProfiler;
 
 Error check(xnn_status status, const char* operation) {
   if (status == xnn_status_success) {
@@ -39,6 +46,17 @@ Error check(xnn_status status, const char* operation) {
     }                                                            \
   } while (false)
 
+bool profiling_ok(Error error, const char* operation) {
+  if (error != Error::Ok) {
+    ET_LOG(
+        Error,
+        "CPU XNNPACK profiling %s failed: %u",
+        operation,
+        static_cast<unsigned int>(error));
+  }
+  return error == Error::Ok;
+}
+
 bool constant(const ptn::Value& value) {
   return value.role == ptn::ValueRole::Parameter ||
       value.role == ptn::ValueRole::ConstantTensor ||
@@ -101,6 +119,8 @@ class XNNState {
     return Error::Ok;
   }
   std::map<std::pair<ptn::ValueId, bool>, Buffer> converted_weights;
+  /// Numbers ETDump operator names uniquely across the provider's regions.
+  std::unordered_map<std::string, uint32_t> operator_counts;
   xnn_workspace_t workspace = nullptr;
   xnn_weights_cache_t cache = nullptr;
 };
@@ -184,13 +204,27 @@ class XNNExecutable final : public Executable {
         return error;
       }
     }
+    uint32_t runtime_flags = 0;
+#ifdef ET_EVENT_TRACER_ENABLED
+    auto* tracer = context_.execution.event_tracer;
+    if (tracer &&
+        tracer->event_tracer_profiling_level() >
+            EventTracerProfilingLevel::kProfileMethodOnly) {
+      runtime_flags |= XNN_FLAG_BASIC_PROFILING;
+    }
+#endif
     CPU_XNN_CHECK(xnn_create_runtime_v4(
         subgraph_,
         state_.cache,
         state_.workspace,
         context_.execution.threadpool,
-        0,
+        runtime_flags,
         &runtime_));
+    if (runtime_flags & XNN_FLAG_BASIC_PROFILING) {
+      profiling_ = profiling_ok(
+          profiler_.initialize(runtime_, &state_.operator_counts),
+          "initialization");
+    }
     return Error::Ok;
   }
 
@@ -209,6 +243,11 @@ class XNNExecutable final : public Executable {
           "XNNPACK inferred a different semantic shape for %s",
           context_.graph.value(binding.id).name.c_str());
     }
+#ifdef ET_EVENT_TRACER_ENABLED
+    if (profiling_) {
+      profiling_ok(describe_operators(), "metadata");
+    }
+#endif
     return Error::Ok;
   }
 
@@ -231,19 +270,65 @@ class XNNExecutable final : public Executable {
     return Error::Ok;
   }
 
-  Error run(const ExecutionContext&) override {
+  Error run(const ExecutionContext& context) override {
     ET_CHECK_OR_RETURN_ERROR(
         bound_, InvalidState, "XNNPACK requires a successful bind");
     // Shared workspace growth can relocate another region's internal values.
     CPU_XNN_CHECK(
         xnn_setup_runtime_v2(runtime_, external_.size(), external_.data()));
+    tracing_ = profiling_ &&
+        profiling_ok(profiler_.start(context.event_tracer), "start");
     CPU_XNN_CHECK(xnn_invoke_runtime(runtime_));
     return Error::Ok;
   }
 
+  void submit_trace() override {
+    if (tracing_) {
+      tracing_ = false;
+      profiling_ok(profiler_.end(), "end");
+    }
+  }
+
  private:
   friend const XNNOp* find_op(std::string_view target);
 
+#ifdef ET_EVENT_TRACER_ENABLED
+  // Reads XNNPACK's internal runtime, which the public API does not expose.
+  // xnn_get_runtime_profiling_info reports names and timings for opdata with a
+  // primary operator, in opdata order; this must apply the same filter.
+  Error describe_operators() {
+    std::vector<std::string> shapes;
+    for (size_t index = 0; index < runtime_->num_ops; ++index) {
+      const auto& op = runtime_->opdata[index];
+      if (op.operator_objects[0] != nullptr) {
+        shapes.push_back(
+            "{\"inputs\":" + value_shapes(op.inputs, op.num_inputs) +
+            ",\"outputs\":" + value_shapes(op.outputs, op.num_outputs) + "}");
+      }
+    }
+    return profiler_.set_operator_metadata(std::move(shapes));
+  }
+
+  std::string value_shapes(const uint32_t* ids, uint32_t count) const {
+    std::string text = "[";
+    for (uint32_t index = 0; index < count; ++index) {
+      text += index ? "," : "";
+      if (ids == nullptr || ids[index] == XNN_INVALID_VALUE_ID ||
+          ids[index] >= runtime_->num_values) {
+        text += "null";
+        continue;
+      }
+      const auto& shape = runtime_->values[ids[index]].shape;
+      text += "[";
+      for (size_t dim = 0; dim < shape.num_dims; ++dim) {
+        text += (dim ? "," : "") + std::to_string(shape.dim[dim]);
+      }
+      text += "]";
+    }
+    return text + "]";
+  }
+#endif
+
   std::vector<size_t> dimensions(ptn::ValueId id) const {
     const auto& sizes = context_.graph.value(id).tensor_meta().sizes;
     return {sizes.begin(), sizes.end()};
@@ -849,6 +934,9 @@ class XNNExecutable final : public Executable {
   bool bound_ = false;
   std::vector<Binding> bindings_;
   std::vector<xnn_external_value> external_;
+  XNNProfiler profiler_;
+  bool profiling_ = false;
+  bool tracing_ = false;
 };
 
 const XNNOp* find_op(std::string_view target) {