Initial print profiling for xnnpack ops (#227)

Summary:
Pull Request resolved: #227

Currently debugging the mv2 q8 vs mv2 fp32. (there is not much difference in performance). Adding some general utils for grabbing per-op profiling data from XNNPACK.

Private fns that interact with XNNPACK runtime to grab op info:
```
Error get_runtime_operator_names(std::vector<char>& operator_names);
Error get_runtime_num_operators(size_t& num_operators);
Error get_runtime_operator_timings(std::vector<uint64_t>& timing_stats);
```
these get operator names, number of operators, and per-operator timings

Delegate Public fns to initialize, log, and print profiling data

```
Error init_profiler()
Error log_op_timings()
Error print_avg_op_timings()
```

Reviewed By: digantdesai

Differential Revision: D48992397

fbshipit-source-id: a89a3a323ada1e8ab5ea4f2f028cf5d9355dc5a8

Author: mcr229

backends/xnnpack/runtime/XNNCompiler.cpp

@@ -1485,12 +1485,17 @@ __ET_NODISCARD Error XNNCompiler::compileModel(
       return err;
     }
   }
+  uint32_t runtime_flags = 0;
+
+#ifdef ENABLE_XNNPACK_PROFILING
+  runtime_flags |= XNN_FLAG_BASIC_PROFILING;
+#endif
 
   xnn_runtime_t runtime_ptr = nullptr;
   status = xnn_create_runtime_v2(
       subgraph.get(),
       torch::executorch::threadpool::get_pthreadpool(),
-      0,
+      runtime_flags,
       &runtime_ptr);
   ET_CHECK_OR_RETURN_ERROR(
       xnn_status_success == status,
@@ -1502,6 +1507,10 @@ __ET_NODISCARD Error XNNCompiler::compileModel(
       std::unique_ptr<xnn_runtime, decltype(&xnn_delete_runtime)>(
           runtime_ptr, xnn_delete_runtime);
 
+#ifdef ENABLE_XNNPACK_PROFILING
+  executor->init_profiler();
+#endif
+
   for (auto old_id : *flatbuffer_graph->input_ids()) {
     executor->input_ids_.emplace_back(remapped_ids.at(old_id));
   }

backends/xnnpack/runtime/XNNExecutor.cpp

@@ -73,6 +73,91 @@ Error XNNExecutor::set_external_input(uint32_t id, Tensor* input) {
   return Error::Ok;
 }
 
+inline void XNNExecutor::get_runtime_operator_names(
+    std::vector<char>& operator_names) {
+  size_t required_size = 0;
+  // First call returns xnn_status_out_of_memory, but sets required_size to
+  // the correct size of the buffer to store the result
+  xnn_status status = xnn_get_runtime_profiling_info(
+      runtime_.get(), // runtime
+      xnn_profile_info_operator_name, // param_name
+      0, // param_value_size
+      nullptr, // param_value
+      &required_size // param_value_size_ret
+  );
+
+  if (status == xnn_status_out_of_memory) {
+    operator_names.resize(required_size);
+    status = xnn_get_runtime_profiling_info(
+        runtime_.get(),
+        xnn_profile_info_operator_name,
+        operator_names.size(),
+        operator_names.data(),
+        &required_size);
+  }
+  if (status != xnn_status_success) {
+    ET_LOG(Error, "Failed to get XNNPACK Operator Timings");
+  }
+}
+
+inline void XNNExecutor::get_runtime_num_operators(size_t& num_operators) {
+  size_t required_size = 0;
+  xnn_status status = xnn_get_runtime_profiling_info(
+      runtime_.get(),
+      xnn_profile_info_num_operators,
+      sizeof(num_operators),
+      &num_operators,
+      &required_size);
+  if (status != xnn_status_success) {
+    ET_LOG(Error, "Failed to get XNNPACK Operator Timings");
+  }
+}
+
+inline void XNNExecutor::get_runtime_operator_timings(
+    std::vector<uint64_t>& timing_stats) {
+  size_t required_size;
+  // Get number of runtime operators for timing_stats.size
+  timing_stats.resize(num_ops_);
+  xnn_status status = xnn_get_runtime_profiling_info(
+      runtime_.get(),
+      xnn_profile_info_operator_timing,
+      timing_stats.size() * sizeof(uint64_t),
+      timing_stats.data(),
+      &required_size);
+  if (status != xnn_status_success) {
+    ET_LOG(Error, "Failed to get XNNPACK Operator Timings");
+  }
+}
+
+void XNNExecutor::init_profiler() {
+  get_runtime_operator_names(op_names_);
+  get_runtime_num_operators(num_ops_);
+}
+
+void XNNExecutor::log_op_timings() {
+  std::vector<uint64_t> op_stats;
+  get_runtime_operator_timings(op_stats);
+  op_timings_.emplace_back(op_stats);
+}
+
+void XNNExecutor::print_avg_op_timings() {
+  size_t num_iterations = op_timings_.size();
+  size_t name_len = 0;
+  const char* op_name = nullptr;
+  float avg_total = 0;
+  for (size_t xnn_node_idx = 0; xnn_node_idx < num_ops_; xnn_node_idx++) {
+    op_name = &op_names_[name_len];
+    name_len += strlen(op_name) + 1;
+    float total_op_time = 0;
+    for (size_t it = 0; it < num_iterations; it++) {
+      total_op_time += op_timings_[it][xnn_node_idx];
+    }
+    float avg_op_time = total_op_time / static_cast<float>(num_iterations);
+    ET_LOG(Info, ">>, %s, %f", op_name, avg_op_time);
+    avg_total += avg_op_time;
+  }
+  ET_LOG(Info, ">>, Total Time, %f", avg_total);
+}
 } // namespace delegate
 } // namespace xnnpack
 } // namespace executor

backends/xnnpack/runtime/XNNExecutor.h

@@ -38,9 +38,28 @@ class XNNExecutor {
 
   Error set_external_input(uint32_t id, Tensor* input);
 
+  // XNNPACK Profiling
+  // Used to hold profiling data
+  //  * To hold op names and duration (in usec) for each operator execution
+  //  * Both indexed with xnn_node_idx (0.. node_id)
+  using microsecond_t = uint64_t;
+  size_t num_ops_;
+  std::vector<char> op_names_;
+  // op_timings[i][j] represents the runtime of operator j on the ith run
+  std::vector<std::vector<microsecond_t>> op_timings_;
+
+  void get_runtime_operator_names(std::vector<char>& operator_names);
+  void get_runtime_num_operators(size_t& num_operators);
+  void get_runtime_operator_timings(std::vector<uint64_t>& timing_stats);
+
  public:
   XNNExecutor() = default;
 
+  // XNNPACK Profiling public fn
+  void init_profiler();
+  void log_op_timings();
+  void print_avg_op_timings();
+
   inline void append_arg(uint32_t id) {
     external_id_args_.push_back(id);
     // Insertion order is not guaranteed here.

backends/xnnpack/runtime/XNNPACKBackend.cpp

@@ -88,6 +88,9 @@ class XnnpackBackend final : public PyTorchBackendInterface {
     }
 
     err = executor->forward();
+#ifdef ENABLE_XNNPACK_PROFILING
+    executor->log_op_timings(); // Log the op execution time.
+#endif
 
     for (int i = executor->getNumInputs();
          i < executor->getNumInputs() + executor->getNumOutputs();
@@ -113,6 +116,9 @@ class XnnpackBackend final : public PyTorchBackendInterface {
   void destroy(DelegateHandle* handle) const override {
     if (handle != nullptr) {
       auto executor = static_cast<xnnpack::delegate::XNNExecutor*>(handle);
+#ifdef ENABLE_XNNPACK_PROFILING
+      executor->print_avg_op_timings();
+#endif
       // XNNExecutor is not trivially destructible. Since this was constructed
       // manually in init(), we must destroy it manually here.
       executor->~XNNExecutor();

backends/xnnpack/targets.bzl

@@ -65,7 +65,9 @@ def define_common_targets():
             "//executorch/extension/pybindings/...",
             "@EXECUTORCH_CLIENTS",
         ],
-        preprocessor_flags = [] if runtime.is_oss else ["-DENABLE_DYNAMIC_QUANTIZATION"],
+        preprocessor_flags = [
+            # "-DENABLE_XNNPACK_PROFILING",
+        ] + ([] if runtime.is_oss else ["-DENABLE_DYNAMIC_QUANTIZATION"]),
         deps = [
             third_party_dep("XNNPACK"),
             ":xnnpack_schema",