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);