Add option to disable operator profiling (#5720)

Summary:
X-link: pytorch/pytorch#136838


For smaller models the overhead of profiling ops might be prohibitively large (distorting the inference execution time significantly) so we provide users an option to disable op profiling and essentially only profile the important events such as inference execution time.

To disable operator profiling users need to do:
```
etdump_gen.set_event_tracer_profiling_level(executorch::runtime::EventTracerProfilingLevel::kNoOperatorProfiling);
```

Reviewed By: Vysarat

Differential Revision: D61883224

Author: tarun292

runtime/core/event_tracer.h

@@ -67,6 +67,13 @@ enum class EventTracerDebugLogLevel {
   kIntermediateOutputs,
 };
 
+enum class EventTracerProfilingLevel {
+  /// No operator profiling.
+  kProfileMethodOnly,
+  /// All profiling events enabled.
+  kProfileAllEvents,
+};
+
 /**
  * This is the struct which should be returned when a profiling event is
  * started. This is used to uniquely identify that profiling event and will be
@@ -423,6 +430,22 @@ class EventTracer {
     return event_tracer_debug_level_;
   }
 
+  /**
+   * Set the level of event tracer profiling that is desired.
+   *
+   */
+  void set_event_tracer_profiling_level(
+      EventTracerProfilingLevel profiling_level) {
+    event_tracer_profiling_level_ = profiling_level;
+  }
+
+  /**
+   * Return the current level of event tracer profiling.
+   */
+  EventTracerProfilingLevel event_tracer_profiling_level() {
+    return event_tracer_profiling_level_;
+  }
+
   /**
    * Return the current status of intermediate outputs logging mode.
    */
@@ -458,6 +481,8 @@ class EventTracer {
   int bundled_input_index_ = kUnsetBundledInputIndex;
   EventTracerDebugLogLevel event_tracer_debug_level_ =
       EventTracerDebugLogLevel::kNoLogging;
+  EventTracerProfilingLevel event_tracer_profiling_level_ =
+      EventTracerProfilingLevel::kProfileAllEvents;
 };
 
 } // namespace runtime

runtime/core/event_tracer_hooks.h

@@ -33,6 +33,49 @@ namespace executorch {
 namespace runtime {
 namespace internal {
 
+/**
+ * This class enables scope based profiling where needed using RAII for
+ * operators only. If operator profiling is disabled then this class is a no-op.
+ */
+class EventTracerOpProfileScope final {
+ public:
+  EventTracerOpProfileScope(EventTracer* event_tracer, const char* name) {
+#ifdef ET_EVENT_TRACER_ENABLED
+    event_tracer_ = event_tracer;
+    if (event_tracer_ == nullptr) {
+      return;
+    }
+    if (event_tracer_->event_tracer_profiling_level() >
+            executorch::runtime::EventTracerProfilingLevel::
+                kProfileMethodOnly, ) {
+      event_entry_ = event_tracer->start_profiling(name);
+    }
+#else //! ET_EVENT_TRACER_ENABLED
+    (void)event_tracer;
+    (void)name;
+#endif
+  }
+
+  ~EventTracerOpProfileScope() {
+#ifdef ET_EVENT_TRACER_ENABLED
+    if (event_tracer_ == nullptr) {
+      return;
+    }
+    if (event_tracer_->event_tracer_profiling_level() >
+            executorch::runtime::EventTracerProfilingLevel::
+                kProfileMethodOnly, ) {
+      event_tracer_->end_profiling(event_entry_);
+    }
+#endif
+  }
+
+ private:
+#ifdef ET_EVENT_TRACER_ENABLED
+  EventTracer* event_tracer_;
+  EventTracerEntry event_entry_;
+#endif
+};
+
 /**
  * This class enables scope based profiling where needed using RAII.
  * Profiling will be started when the object is created and will end
@@ -111,6 +154,13 @@ class EventTracerProfileInstructionScope final {
 #endif
 };
 
+inline bool event_tracer_enabled() {
+#ifdef ET_EVENT_TRACER_ENABLED
+  return true;
+#else //! ET_EVENT_TRACER_ENABLED
+  return false;
+#endif
+}
 /**
  * Create a new event block with the specified name. Any events logged
  * after this will be associated with this new event block.

runtime/core/test/event_tracer_test.cpp

@@ -44,14 +44,15 @@ class DummyEventTracer : public EventTracer {
       const char* name,
       ChainID chain_id = kUnsetChainId,
       DebugHandle debug_handle = kUnsetDebugHandle) override {
-    (void)name;
     (void)chain_id;
     (void)debug_handle;
+    memcpy(event_name_, name, strlen(name) + 1);
     return EventTracerEntry();
   }
 
   void end_profiling(EventTracerEntry prof_entry) override {
     (void)prof_entry;
+    memset(event_name_, 0, sizeof(event_name_));
     return;
   }
 
@@ -156,13 +157,18 @@ class DummyEventTracer : public EventTracer {
     return logged_evalue_type_;
   }
 
+  char* get_event_name() {
+    return event_name_;
+  }
+
   void reset_logged_value() {
     logged_evalue_ = EValue(false);
   }
 
  private:
   EValue logged_evalue_ = EValue(false);
   LoggedEValueType logged_evalue_type_;
+  char event_name_[1024];
 };
 
 /**
@@ -282,3 +288,54 @@ TEST(TestEventTracer, SimpleEventTracerTestLogging) {
 
 // TODO(T163645377): Add more test coverage to log and verify events passed into
 // DummyTracer.
+TEST(TestEventTracer, EventTracerOpProfileControl) {
+  DummyEventTracer dummy;
+  // Op profiling is enabled by default. Test that it works.
+  {
+    {
+      executorch::runtime::internal::EventTracerOpProfileScope
+          event_tracer_op_scope(&dummy, "ExampleOpScope");
+      EXPECT_EQ(
+          memcmp(
+              dummy.get_event_name(),
+              "ExampleOpScope",
+              strlen("ExampleOpScope")),
+          0);
+    }
+    EXPECT_EQ(memcmp(dummy.get_event_name(), "", 1), 0);
+
+    // Normal profiling should still work.
+    {
+      executorch::runtime::internal::EventTracerProfileScope
+          event_tracer_profiler_scope(&dummy, "ExampleProfilerScope");
+      EXPECT_EQ(
+          memcmp(
+              dummy.get_event_name(),
+              "ExampleProfilerScope",
+              strlen("ExampleProfilerScope")),
+          0);
+    }
+
+    dummy.set_event_tracer_profiling_level(
+        executorch::runtime::EventTracerProfilingLevel::kNoOperatorProfiling);
+
+    // Op profiling should be disabled now.
+    {
+      executorch::runtime::internal::EventTracerOpProfileScope
+          event_tracer_op_scope(&dummy, "ExampleOpScope");
+      EXPECT_EQ(memcmp(dummy.get_event_name(), "", 1), 0);
+    }
+
+    // Normal profiling should still work.
+    {
+      executorch::runtime::internal::EventTracerProfileScope
+          event_tracer_profiler_scope(&dummy, "1ExampleProfilerScope");
+      EXPECT_EQ(
+          memcmp(
+              dummy.get_event_name(),
+              "1ExampleProfilerScope",
+              strlen("1ExampleProfilerScope")),
+          0);
+    }
+  }
+}

runtime/executor/method.cpp

@@ -1022,8 +1022,8 @@ Error Method::execute_instruction() {
   switch (instruction->instr_args_type()) {
     case executorch_flatbuffer::InstructionArguments::KernelCall: {
       EXECUTORCH_SCOPE_PROF("OPERATOR_CALL");
-      internal::EventTracerProfileScope event_tracer_scope =
-          internal::EventTracerProfileScope(event_tracer_, "OPERATOR_CALL");
+      internal::EventTracerOpProfileScope event_tracer_op_scope =
+          internal::EventTracerOpProfileScope(event_tracer_, "OPERATOR_CALL");
       // TODO(T147221312): Also expose tensor resizer via the context.
       KernelRuntimeContext context(event_tracer_, temp_allocator_);
       auto args = chain.argument_lists_[step_state_.instr_idx];
@@ -1057,8 +1057,8 @@ Error Method::execute_instruction() {
     } break;
     case executorch_flatbuffer::InstructionArguments::DelegateCall: {
       EXECUTORCH_SCOPE_PROF("DELEGATE_CALL");
-      internal::EventTracerProfileScope event_tracer_profile_scope =
-          internal::EventTracerProfileScope(event_tracer_, "DELEGATE_CALL");
+      internal::EventTracerOpProfileScope event_tracer_op_scope =
+          internal::EventTracerOpProfileScope(event_tracer_, "DELEGATE_CALL");
       // We know that instr_args_as_DelegateCall is non-null because it was
       // checked at init time.
       auto delegate_idx =
@@ -1101,8 +1101,8 @@ Error Method::execute_instruction() {
     } break;
     case executorch_flatbuffer::InstructionArguments::JumpFalseCall: {
       EXECUTORCH_SCOPE_PROF("JF_CALL");
-      internal::EventTracerProfileScope event_tracer_profile_scope =
-          internal::EventTracerProfileScope(event_tracer_, "JF_CALL");
+      internal::EventTracerOpProfileScope event_tracer_op_scope =
+          internal::EventTracerOpProfileScope(event_tracer_, "JF_CALL");
       // We know that instr_args_as_JumpFalseCall is non-null because it was
       // checked at init time.
       auto jf_call = instruction->instr_args_as_JumpFalseCall();
@@ -1120,17 +1120,17 @@ Error Method::execute_instruction() {
     } break;
     case executorch_flatbuffer::InstructionArguments::MoveCall: {
       EXECUTORCH_SCOPE_PROF("MOVE_CALL");
-      internal::EventTracerProfileScope event_tracer_profile_scope =
-          internal::EventTracerProfileScope(event_tracer_, "MOVE_CALL");
+      internal::EventTracerOpProfileScope event_tracer_op_scope =
+          internal::EventTracerOpProfileScope(event_tracer_, "MOVE_CALL");
       // We know that instr_args_as_MoveCall is non-null because it was checked
       // at init time.
       auto move_call = instruction->instr_args_as_MoveCall();
       mutable_value(move_call->move_to()) = get_value(move_call->move_from());
     } break;
     case executorch_flatbuffer::InstructionArguments::FreeCall: {
       EXECUTORCH_SCOPE_PROF("FREE_CALL");
-      internal::EventTracerProfileScope event_tracer_profile_scope =
-          internal::EventTracerProfileScope(event_tracer_, "FREE_CALL");
+      internal::EventTracerOpProfileScope event_tracer_op_scope =
+          internal::EventTracerOpProfileScope(event_tracer_, "FREE_CALL");
       // We know that instr_args_as_FreeCall is non-null because it was checked
       // at init time.
       auto free_call = instruction->instr_args_as_FreeCall();