Add option to disable operator profiling (#5720)

Summary:
X-link: pytorch/pytorch#136838

Pull Request resolved: #5720

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: dbort

Differential Revision: D61883224

fbshipit-source-id: f4fdcb67be00762152ca90b10239d10c2664a926

Author: tarun292

runtime/core/event_tracer.h

@@ -67,6 +67,18 @@ enum class EventTracerDebugLogLevel {
   kIntermediateOutputs,
 };
 
+/**
+ * Indicates the level of profiling that should be enabled. Profiling
+ * events will be logged in increasing order of verbosity as we go down the
+ * enum list. Thus it is important to keep the enum values in the right order.
+ */
+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 +435,21 @@ 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 +485,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,14 +33,58 @@ 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 EventTracerProfileOpScope final {
+ public:
+  EventTracerProfileOpScope(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
+  }
+
+  ~EventTracerProfileOpScope() {
+#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
+};
+
+using EventTracerProfileScope = EventTracerProfileOpScope;
+
 /**
  * This class enables scope based profiling where needed using RAII.
  * Profiling will be started when the object is created and will end
- * when the object goes out of scope.
+ * when the object goes out of scope. This is specifically intended to
+ * be used for profiling methods in the runtime.
  */
-class EventTracerProfileScope final {
+class EventTracerProfileMethodScope final {
  public:
-  EventTracerProfileScope(EventTracer* event_tracer, const char* name) {
+  EventTracerProfileMethodScope(EventTracer* event_tracer, const char* name) {
 #ifdef ET_EVENT_TRACER_ENABLED
     event_tracer_ = event_tracer;
     if (event_tracer_ == nullptr) {
@@ -53,7 +97,7 @@ class EventTracerProfileScope final {
 #endif
   }
 
-  ~EventTracerProfileScope() {
+  ~EventTracerProfileMethodScope() {
 #ifdef ET_EVENT_TRACER_ENABLED
     if (event_tracer_ == nullptr) {
       return;
@@ -111,6 +155,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.
@@ -271,7 +322,10 @@ using ::executorch::runtime::internal::event_tracer_set_bundled_input_index;
 using ::executorch::runtime::internal::event_tracer_track_allocation;
 using ::executorch::runtime::internal::event_tracer_track_allocator;
 using ::executorch::runtime::internal::EventTracerProfileInstructionScope;
+using ::executorch::runtime::internal::EventTracerProfileMethodScope;
+using ::executorch::runtime::internal::EventTracerProfileOpScope;
 using ::executorch::runtime::internal::EventTracerProfileScope;
+
 } // namespace internal
 } // namespace executor
 } // namespace torch

runtime/core/test/event_tracer_test.cpp

@@ -44,14 +44,16 @@ class DummyEventTracer : public EventTracer {
       const char* name,
       ChainID chain_id = kUnsetChainId,
       DebugHandle debug_handle = kUnsetDebugHandle) override {
-    (void)name;
     (void)chain_id;
     (void)debug_handle;
+    ET_CHECK(strlen(name) + 1 < sizeof(event_name_));
+    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 +158,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];
 };
 
 /**
@@ -175,15 +182,15 @@ void RunSimpleTracerTest(EventTracer* event_tracer) {
   using executorch::runtime::internal::event_tracer_track_allocation;
   using executorch::runtime::internal::event_tracer_track_allocator;
   using executorch::runtime::internal::EventTracerProfileInstructionScope;
-  using executorch::runtime::internal::EventTracerProfileScope;
+  using executorch::runtime::internal::EventTracerProfileMethodScope;
 
   event_tracer_create_event_block(event_tracer, "ExampleEvent");
   event_tracer_create_event_block(event_tracer, "ExampleEvent");
   EventTracerEntry event_entry =
       event_tracer_begin_profiling_event(event_tracer, "ExampleEvent");
   event_tracer_end_profiling_event(event_tracer, event_entry);
   {
-    EventTracerProfileScope event_tracer_profile_scope(
+    EventTracerProfileMethodScope event_tracer_profile_scope(
         event_tracer, "ExampleScope");
   }
   {
@@ -282,3 +289,39 @@ TEST(TestEventTracer, SimpleEventTracerTestLogging) {
 
 // TODO(T163645377): Add more test coverage to log and verify events passed into
 // DummyTracer.
+TEST(TestEventTracer, EventTracerProfileOpControl) {
+  DummyEventTracer dummy;
+  // Op profiling is enabled by default. Test that it works.
+  {
+    {
+      executorch::runtime::internal::EventTracerProfileOpScope
+          event_tracer_op_scope(&dummy, "ExampleOpScope");
+      EXPECT_EQ(strcmp(dummy.get_event_name(), "ExampleOpScope"), 0);
+    }
+    EXPECT_EQ(strcmp(dummy.get_event_name(), ""), 0);
+
+    // Normal profiling should still work.
+    {
+      executorch::runtime::internal::EventTracerProfileMethodScope
+          event_tracer_profiler_scope(&dummy, "ExampleProfilerScope");
+      EXPECT_EQ(strcmp(dummy.get_event_name(), "ExampleProfilerScope"), 0);
+    }
+
+    dummy.set_event_tracer_profiling_level(
+        executorch::runtime::EventTracerProfilingLevel::kProfileMethodOnly);
+
+    // Op profiling should be disabled now.
+    {
+      executorch::runtime::internal::EventTracerProfileOpScope
+          event_tracer_op_scope(&dummy, "ExampleOpScope");
+      EXPECT_EQ(strcmp(dummy.get_event_name(), ""), 0);
+    }
+
+    // Normal profiling should still work.
+    {
+      executorch::runtime::internal::EventTracerProfileMethodScope
+          event_tracer_profiler_scope(&dummy, "1ExampleProfilerScope");
+      EXPECT_EQ(strcmp(dummy.get_event_name(), "1ExampleProfilerScope"), 0);
+    }
+  }
+}

runtime/executor/method.cpp

@@ -572,8 +572,8 @@ Result<Method> Method::load(
 
 Error Method::init(executorch_flatbuffer::ExecutionPlan* s_plan) {
   EXECUTORCH_SCOPE_PROF("Method::init");
-  internal::EventTracerProfileScope event_tracer_profile_scope =
-      internal::EventTracerProfileScope(event_tracer_, "Method::init");
+  internal::EventTracerProfileMethodScope event_tracer_profile_scope =
+      internal::EventTracerProfileMethodScope(event_tracer_, "Method::init");
   ET_CHECK_OR_RETURN_ERROR(
       // Don't use !initialized() here because we also want to fail on the
       // InitializationFailed state.
@@ -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::EventTracerProfileOpScope event_tracer_op_scope =
+          internal::EventTracerProfileOpScope(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::EventTracerProfileOpScope event_tracer_op_scope =
+          internal::EventTracerProfileOpScope(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::EventTracerProfileOpScope event_tracer_op_scope =
+          internal::EventTracerProfileOpScope(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::EventTracerProfileOpScope event_tracer_op_scope =
+          internal::EventTracerProfileOpScope(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::EventTracerProfileOpScope event_tracer_op_scope =
+          internal::EventTracerProfileOpScope(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();
@@ -1191,8 +1191,8 @@ Error Method::step() {
           static_cast<int32_t>(step_state_.chain_idx),
           static_cast<uint32_t>(step_state_.instr_idx));
   EXECUTORCH_SCOPE_PROF("Method::step");
-  internal::EventTracerProfileScope event_tracer_profile_scope =
-      internal::EventTracerProfileScope(event_tracer_, "Method::step");
+  internal::EventTracerProfileMethodScope event_tracer_profile_scope =
+      internal::EventTracerProfileMethodScope(event_tracer_, "Method::step");
   ET_CHECK_OR_RETURN_ERROR(
       initialized(),
       InvalidState,
@@ -1233,8 +1233,8 @@ Error Method::experimental_step() {
 
 Error Method::execute() {
   internal::event_tracer_create_event_block(event_tracer_, "Execute");
-  internal::EventTracerProfileScope event_tracer_profile_scope =
-      internal::EventTracerProfileScope(event_tracer_, "Method::execute");
+  internal::EventTracerProfileMethodScope event_tracer_profile_scope =
+      internal::EventTracerProfileMethodScope(event_tracer_, "Method::execute");
   EXECUTORCH_SCOPE_PROF("Method::execute");
   ET_CHECK_OR_RETURN_ERROR(
       initialized(),

runtime/executor/program.cpp

@@ -241,8 +241,9 @@ Result<Method> Program::load_method(
     EventTracer* event_tracer) const {
   EXECUTORCH_SCOPE_PROF("Program::load_method");
   internal::event_tracer_create_event_block(event_tracer, "Default");
-  internal::EventTracerProfileScope event_tracer_scope =
-      internal::EventTracerProfileScope(event_tracer, "Program::load_method");
+  internal::EventTracerProfileMethodScope event_tracer_scope =
+      internal::EventTracerProfileMethodScope(
+          event_tracer, "Program::load_method");
   // If we can't create a MethodMeta for the Method, the Method is corrupt;
   // Method::method_meta() assumes success, so we must fail here.
   Result<MethodMeta> meta = method_meta(method_name);