ETDump changes for delegate logging.

Differential Revision: D48993977

fbshipit-source-id: ff7323bc51d347b46c022b47a710603243a12da1

Author: tarun292

sdk/etdump/etdump_flatcc.cpp

@@ -7,6 +7,7 @@
  */
 
 #include "executorch/sdk/etdump/etdump_flatcc.h"
+#include <stdio.h>
 #include <string.h>
 #include "executorch/runtime/platform/assert.h"
 
@@ -18,7 +19,7 @@ ETDumpGen::ETDumpGen(void* buffer, size_t buf_size) {
   // Initialize the flatcc builder using the buffer and buffer size
   flatcc_builder_init(&builder);
   flatbuffers_buffer_start(&builder, etdump_ETDump_file_identifier);
-  etdump_ETDump_start(&builder);
+  etdump_ETDump_start_as_root_with_size(&builder);
   etdump_ETDump_version_add(&builder, ETDUMP_VERSION);
   etdump_ETDump_run_data_start(&builder);
   etdump_ETDump_run_data_push_start(&builder);
@@ -49,6 +50,19 @@ int64_t ETDumpGen::create_string_entry(const char* name) {
   return flatbuffers_string_create_str(&builder, name);
 }
 
+// ETDumpGen has the following possible states, ETDumpGen_Init,
+// ETDumpGen_Block_Created, ETDumpGen_Adding_Allocators,
+// ETDumpGen_Adding_Events. Right after boot-up the state of ETDump will be
+// ETDumpGen_Init. At this point we have an option of adding allocators that
+// we want to track. Once we've completed adding the allocators we want to track
+// we will close the allocators table and move ETDumpGen to the
+// ETDumpGen_Adding_Events state. After this point we can start adding events to
+// ETDump as we wish.
+// The reason we need to maintain this state machine inside of ETDumpGen is
+// because, once a table of one type has been closed and another table of a
+// different type is opened after it we cannot open another table of the first
+// type again. In this case once we close the allocators table and start pushing
+// to the events table we cannot push to the allocators table again.
 void ETDumpGen::check_ready_to_add_events() {
   if (etdump_gen_state != ETDumpGen_Adding_Events) {
     ET_CHECK_MSG(
@@ -68,12 +82,12 @@ EventTracerEntry ETDumpGen::start_profiling(
     ChainID chain_id,
     DebugHandle debug_handle) {
   EventTracerEntry prof_entry;
-  prof_entry.event_id = create_string_entry(name);
+  prof_entry.event_id = name != nullptr ? create_string_entry(name) : -1;
+  prof_entry.delegate_event_id_type = DelegateDebugIdType::kNone;
 
-  if (chain_id == -1 && debug_handle == 0) {
+  if (chain_id == -1) {
     prof_entry.chain_id = chain_id_;
     prof_entry.debug_handle = debug_handle_;
-
   } else {
     prof_entry.chain_id = chain_id;
     prof_entry.debug_handle = debug_handle;
@@ -84,22 +98,116 @@ EventTracerEntry ETDumpGen::start_profiling(
 
 // TODO: Update all occurrences of the ProfileEvent calls once the
 // EventTracerEntry struct is updated.
-void ETDumpGen::end_profiling(EventTracerEntry prof_entry) {
+EventTracerEntry ETDumpGen::start_profiling_delegate(
+    const char* name,
+    DebugHandle delegate_debug_index) {
+  ET_CHECK_MSG(
+      (name == nullptr) ^ (delegate_debug_index == -1),
+      "Only name or delegate_debug_index can be valid. Check DelegateMappingBuilder documentation for more details.");
+  check_ready_to_add_events();
+  EventTracerEntry prof_entry;
+  DelegateDebugIdType delegate_event_id_type =
+      name == nullptr ? DelegateDebugIdType::kInt : DelegateDebugIdType::kStr;
+  prof_entry.delegate_event_id_type = delegate_event_id_type;
+  prof_entry.chain_id = chain_id_;
+  prof_entry.debug_handle = debug_handle_;
+  prof_entry.event_id = delegate_debug_index == static_cast<unsigned int>(-1)
+      ? create_string_entry(name)
+      : delegate_debug_index;
+  prof_entry.start_time = et_pal_current_ticks();
+  return prof_entry;
+}
+
+void ETDumpGen::end_profiling_delegate(
+    EventTracerEntry event_tracer_entry,
+    const char* metadata) {
   et_timestamp_t end_time = et_pal_current_ticks();
   check_ready_to_add_events();
+
+  int64_t string_id_metadata =
+      metadata == nullptr ? -1 : create_string_entry(metadata);
+
+  // Start building the ProfileEvent entry.
+  etdump_ProfileEvent_start(&builder);
+  etdump_ProfileEvent_start_time_add(&builder, event_tracer_entry.start_time);
+  etdump_ProfileEvent_end_time_add(&builder, end_time);
+  etdump_ProfileEvent_chain_id_add(&builder, chain_id_);
+  etdump_ProfileEvent_instruction_id_add(&builder, debug_handle_);
+  // Delegate debug identifier can either be of a string type or an integer
+  // type. If it's a string type then it's a value of type
+  // flatbuffers_string_ref_t type, whereas if it's an integer type then we
+  // write the integer value directly.
+  if (event_tracer_entry.delegate_event_id_type == DelegateDebugIdType::kInt) {
+    etdump_ProfileEvent_delegate_debug_id_int_add(
+        &builder, event_tracer_entry.event_id);
+  } else {
+    etdump_ProfileEvent_delegate_debug_id_str_add(
+        &builder, event_tracer_entry.event_id);
+  }
+  // String metadata is optional and if a nullptr is passed in then we don't
+  // add anything.
+  if (string_id_metadata != -1) {
+    etdump_ProfileEvent_delegate_debug_metadata_add(
+        &builder, string_id_metadata);
+  }
+  etdump_ProfileEvent_ref_t id = etdump_ProfileEvent_end(&builder);
   etdump_RunData_events_push_start(&builder);
+  etdump_Event_profile_event_add(&builder, id);
+  etdump_RunData_events_push_end(&builder);
+}
 
-  etdump_Event_profile_event_create(
-      &builder,
-      prof_entry.event_id, // see todo - change to prof_entry.name
-      prof_entry.chain_id,
-      -1, // see todo - change to prof_entry.instruction_id
-      prof_entry.debug_handle, // see todo - change to
-                               // prof_entry.delegate_debug_id_int
-      flatbuffers_string_create_str(
-          &builder, ""), // see todo - change to prof_entry.dlegate_debug_id_str
-      prof_entry.start_time,
-      end_time);
+void ETDumpGen::log_profiling_delegate(
+    const char* name,
+    DebugHandle delegate_debug_index,
+    et_timestamp_t start_time,
+    et_timestamp_t end_time,
+    const char* metadata) {
+  ET_CHECK_MSG(
+      (name == nullptr) ^ (delegate_debug_index == -1),
+      "Only name or delegate_debug_index can be valid. Check DelegateMappingBuilder documentation for more details.");
+  check_ready_to_add_events();
+  int64_t string_id = name != nullptr ? create_string_entry(name) : -1;
+  int64_t string_id_metadata =
+      metadata == nullptr ? -1 : create_string_entry(metadata);
+  etdump_ProfileEvent_start(&builder);
+  etdump_ProfileEvent_start_time_add(&builder, start_time);
+  etdump_ProfileEvent_end_time_add(&builder, end_time);
+  etdump_ProfileEvent_chain_id_add(&builder, chain_id_);
+  etdump_ProfileEvent_instruction_id_add(&builder, debug_handle_);
+  if (string_id == -1) {
+    etdump_ProfileEvent_delegate_debug_id_int_add(
+        &builder, delegate_debug_index);
+  } else {
+    etdump_ProfileEvent_delegate_debug_id_str_add(&builder, string_id);
+  }
+  if (string_id_metadata != -1) {
+    etdump_ProfileEvent_delegate_debug_metadata_add(
+        &builder, string_id_metadata);
+  }
+  etdump_ProfileEvent_ref_t id = etdump_ProfileEvent_end(&builder);
+  etdump_RunData_events_push_start(&builder);
+  etdump_Event_profile_event_add(&builder, id);
+  etdump_RunData_events_push_end(&builder);
+}
+
+void ETDumpGen::end_profiling(EventTracerEntry prof_entry) {
+  et_timestamp_t end_time = et_pal_current_ticks();
+  ET_CHECK_MSG(
+      prof_entry.delegate_event_id_type == DelegateDebugIdType::kNone,
+      "Delegate events must use end_profiling_delegate to mark the end of a delegate profiling event.");
+  check_ready_to_add_events();
+
+  etdump_ProfileEvent_start(&builder);
+  etdump_ProfileEvent_start_time_add(&builder, prof_entry.start_time);
+  etdump_ProfileEvent_end_time_add(&builder, end_time);
+  etdump_ProfileEvent_chain_id_add(&builder, prof_entry.chain_id);
+  etdump_ProfileEvent_instruction_id_add(&builder, prof_entry.debug_handle);
+  if (prof_entry.event_id != -1) {
+    etdump_ProfileEvent_name_add(&builder, prof_entry.event_id);
+  }
+  etdump_ProfileEvent_ref_t id = etdump_ProfileEvent_end(&builder);
+  etdump_RunData_events_push_start(&builder);
+  etdump_Event_profile_event_add(&builder, id);
   etdump_RunData_events_push_end(&builder);
 }
 
@@ -122,8 +230,6 @@ void ETDumpGen::track_allocation(
     size_t allocation_size) {
   check_ready_to_add_events();
 
-  // etdump_AllocationEvent_ref_t alloc_event_ref =
-  //     etdump_AllocationEvent_create(&builder, allocator_id, allocation_size);
   etdump_RunData_events_push_start(&builder);
   etdump_Event_allocation_event_create(&builder, allocator_id, allocation_size);
   etdump_RunData_events_push_end(&builder);
@@ -151,5 +257,6 @@ etdump_result ETDumpGen::get_etdump_data() {
 size_t ETDumpGen::get_num_blocks() {
   return num_blocks;
 }
+
 } // namespace executor
 } // namespace torch

sdk/etdump/etdump_flatcc.h

@@ -43,22 +43,20 @@ class ETDumpGen : public EventTracer {
       ChainID chain_id = -1,
       DebugHandle debug_handle = 0) override;
   virtual void end_profiling(EventTracerEntry prof_entry) override;
-  virtual void track_allocation(AllocatorID id, size_t size) override;
-  virtual AllocatorID track_allocator(const char* name) override;
   virtual EventTracerEntry start_profiling_delegate(
       const char* name,
-      DebugHandle delegate_debug_index) override {
-    return EventTracerEntry();
-  };
+      DebugHandle delegate_debug_index) override;
   virtual void end_profiling_delegate(
-      EventTracerEntry event_tracer_entry,
-      const char* metadata = nullptr) override{};
+      EventTracerEntry prof_entry,
+      const char* metadata) override;
   virtual void log_profiling_delegate(
       const char* name,
       DebugHandle delegate_debug_index,
       et_timestamp_t start_time,
       et_timestamp_t end_time,
-      const char* metadata = nullptr) override{};
+      const char* metadata) override;
+  virtual void track_allocation(AllocatorID id, size_t size) override;
+  virtual AllocatorID track_allocator(const char* name) override;
   etdump_result get_etdump_data();
   size_t get_num_blocks();
 

sdk/etdump/etdump_schema_flatcc.fbs

@@ -97,6 +97,9 @@ table ProfileEvent {
   // String based delegate debug identifier.
   delegate_debug_id_str:string;
 
+  // Delegate debug metadata free form string.
+  delegate_debug_metadata:string;
+
   // Time at which this event started. Could be in units of time or CPU cycles.
   start_time:ulong;
 

sdk/etdump/schema_flatcc.py

@@ -90,11 +90,12 @@ class PROFILE_EVENT_ENUM(Enum):
 
 @dataclass
 class ProfileEvent:
-    name: str
+    name: Optional[str]
     chain_id: int
     instruction_id: int
-    delegate_debug_id_int: int
-    delegate_debug_id_str: str
+    delegate_debug_id_int: Optional[int]
+    delegate_debug_id_str: Optional[str]
+    delegate_debug_metadata: Optional[str]
     start_time: int
     end_time: int