From 00627747827dccd3db20183968f54d2ae79c5bba Mon Sep 17 00:00:00 2001 From: Tarun Karuturi Date: Fri, 4 Oct 2024 00:48:04 -0700 Subject: [PATCH] Add option to disable operator profiling (#5720) Summary: X-link: https://github.com/pytorch/pytorch/pull/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: dbort Differential Revision: D61883224 --- runtime/core/event_tracer.h | 29 ++++++++++++ runtime/core/event_tracer_hooks.h | 62 +++++++++++++++++++++++-- runtime/core/test/event_tracer_test.cpp | 49 +++++++++++++++++-- runtime/executor/method.cpp | 32 ++++++------- runtime/executor/program.cpp | 5 +- 5 files changed, 152 insertions(+), 25 deletions(-) diff --git a/runtime/core/event_tracer.h b/runtime/core/event_tracer.h index 5a26d24ca45..ff483b1f77d 100644 --- a/runtime/core/event_tracer.h +++ b/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 diff --git a/runtime/core/event_tracer_hooks.h b/runtime/core/event_tracer_hooks.h index 76fa17f62af..40754160c41 100644 --- a/runtime/core/event_tracer_hooks.h +++ b/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 diff --git a/runtime/core/test/event_tracer_test.cpp b/runtime/core/test/event_tracer_test.cpp index 29081c337fd..6422f9b668e 100644 --- a/runtime/core/test/event_tracer_test.cpp +++ b/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,6 +158,10 @@ class DummyEventTracer : public EventTracer { return logged_evalue_type_; } + char* get_event_name() { + return event_name_; + } + void reset_logged_value() { logged_evalue_ = EValue(false); } @@ -163,6 +169,7 @@ class DummyEventTracer : public EventTracer { private: EValue logged_evalue_ = EValue(false); LoggedEValueType logged_evalue_type_; + char event_name_[1024]; }; /** @@ -175,7 +182,7 @@ 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"); @@ -183,7 +190,7 @@ void RunSimpleTracerTest(EventTracer* event_tracer) { 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); + } + } +} diff --git a/runtime/executor/method.cpp b/runtime/executor/method.cpp index bddcdc3173e..0838529bc51 100644 --- a/runtime/executor/method.cpp +++ b/runtime/executor/method.cpp @@ -572,8 +572,8 @@ Result 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,8 +1120,8 @@ 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(); @@ -1129,8 +1129,8 @@ Error Method::execute_instruction() { } 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(step_state_.chain_idx), static_cast(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(), diff --git a/runtime/executor/program.cpp b/runtime/executor/program.cpp index 48d36602d33..0a15b0d0f7f 100644 --- a/runtime/executor/program.cpp +++ b/runtime/executor/program.cpp @@ -241,8 +241,9 @@ Result 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 meta = method_meta(method_name);