Add support for delegate profiling in event_tracer

tarun292 · facebook-github-bot · commit bf5e6f98be89 · 2023-09-20T10:34:56.000-07:00
Differential Revision: D49360145

fbshipit-source-id: 1a73170869c459cb6c863721c31df56a5ef32938
diff --git a/runtime/core/event_tracer.h b/runtime/core/event_tracer.h
@@ -28,6 +28,19 @@ typedef uint32_t DebugHandle;
 constexpr ChainID kUnsetChainId = -1;
 constexpr DebugHandle kUnsetDebugHandle = 0;
 
+/// Different types of delegate debug identifiers that are supported currently.
+enum class DelegateDebugIdType {
+  /// Default value, indicates that it's not a delegate event.
+  kNone,
+  /// Indicates a delegate event logged using an integer delegate debug
+  /// identifier.
+  kInt,
+  /// Indicates a delegate event logged using a string delegate debug
+  /// identifier i.e. the delegate debug id is a pointer to a string table
+  /// managed by the class implementing EventTracer functionality.
+  kStr
+};
+
 /**
  * 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
@@ -44,8 +57,16 @@ struct EventTracerEntry {
   DebugHandle debug_handle;
   /// The time at which this event was started to be tracked.
   et_timestamp_t start_time;
+  /// When delegate_event_id_type != DelegateDebugIdType::kNone it indicates
+  /// that event_id represents a delegate event. If delegate_event_id_type is:
+  /// 1) kInt then event_id contains an integer delegate debug id.
+  /// 2) kStr then event_id contains a string table index into a string table
+  /// maintained by the class implementing EventTracer functionality that will
+  /// give us the string identifier of this delegate event. For more details
+  /// refer to the DelegateMappingBuilder library present in
+  /// executorch/exir/backend/utils.py.
+  DelegateDebugIdType delegate_event_id_type;
 };
-
 /**
  * EventTracer is a class that users can inherit and implement to
  * log/serialize/stream etc. the profiling and debugging events that are
@@ -79,8 +100,9 @@ class EventTracer {
    * around. The string must be copied over into internal memory during this
    * call.
    * @param[in] chain_id The id of the chain to which this event belongs to. If
-   * -1 is passed in the chain_id and debug_handle stored in the class
-   * internally will be used.
+   * kUnsetChainId is passed in the chain_id and kUnsetDebugHandle for
+   * debug_handle then the values stored in the class internally for these
+   * properties will be used.
    * @param[in] debug_handle Debug handle generated ahead-of-time during model
    * compilation.
    *
@@ -92,6 +114,73 @@ class EventTracer {
       ChainID chain_id = kUnsetChainId,
       DebugHandle debug_handle = kUnsetDebugHandle) = 0;
 
+  /**
+   * Start the profiling of a delegate event. Similar to start_profiling it will
+   * return an instance of EventTracerEntry that contains the details of this
+   * event.
+   *
+   * @param[in] name Human readable name for the delegate event. This name has
+   * to be the same name that was passed in during the Debug delegate mapping
+   * generation in the export/ahead-of-time process. If indices and not names
+   * are used by this delegate to identify ops executed in the backend then
+   * nullptr can be passed in. Users calling this interface do not need to keep
+   * the memory pointed to by this pointer around. The string must be copied
+   * over into internal memory during this call.
+   * @param[in] delegate_debug_index The id of the delegate event. If string
+   * based names are used by this delegate to identify ops executed in the
+   * backend then kUnsetDebugHandle should be passed in here.
+   */
+  virtual EventTracerEntry start_profiling_delegate(
+      const char* name,
+      DebugHandle delegate_debug_index) = 0;
+
+  /**
+   * Signal the end of the delegate profiling event contained in
+   * event_tracer_entry. Users also have the option to log some some free-from
+   * string based metadata along with this.
+   *
+   * @param[in] event_tracer_entry The EventTracerEntry returned by a call to
+   * start_profiling_delegate().
+   * @param[in] metadata Optional free-form metadata associated with the
+   * delegate event. This should be a null terminated ASCII string. Users
+   * calling this interface do not need to keep the memory pointed to by this
+   * pointer around. The string must be copied over into internal memory during
+   * this call.
+   */
+  virtual void end_profiling_delegate(
+      EventTracerEntry event_tracer_entry,
+      const char* metadata = nullptr) = 0;
+
+  /**
+   * Some delegates get access to the profiling details only after the complete
+   * graph has been executed. This interface is to support such use cases. It
+   * can be called in a loop etc. to log any number of profiling events that are
+   * part of this delegate.
+   *
+   * @param[in] name Human readable name for the delegate event. This name has
+   * to be the same name that was passed in during the Debug delegate mapping
+   * generation in the export/ahead-of-time process. If indices and not names
+   * are used by this delegate to identify ops executed in the backend then
+   * nullptr can be passed in. Users calling this interface do not need to keep
+   * the memory pointed to by this pointer around. The string must be copied
+   * over into internal memory during this call.
+   * @param[in] delegate_debug_index The id of the delegate event. If string
+   * based names are used by this delegate to identify ops executed in the
+   * backend then kUnsetDebugHandle should be passed in here.
+   * @param[in] start_time The timestamp when the delegate event started.
+   * @param[in] end_time The timestamp when the delegate event finished.
+   * @param[in] metadata Optional data relevant to the execution that the user
+   * wants to log along with this event. Pointer to metadata doesn't need to be
+   * valid after the call to this function. This should be a null terminated
+   * ASCII string.
+   */
+  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) = 0;
+
   /**
    * End the profiling of the event identified by prof_entry
    *
diff --git a/runtime/core/event_tracer_hooks_delegate.h b/runtime/core/event_tracer_hooks_delegate.h
@@ -0,0 +1,142 @@
+/*
+ * Copyright (c) Meta Platforms, Inc. and affiliates.
+ * All rights reserved.
+ *
+ * This source code is licensed under the BSD-style license found in the
+ * LICENSE file in the root directory of this source tree.
+ */
+
+#pragma once
+
+#include <executorch/runtime/core/event_tracer.h>
+
+/**
+ * @file
+ *
+ * This file contains the hooks that can be used by runtime delegate backend
+ * authors to log profiling and debugging events from backend code. In order to
+ * use these hooks delegate authors would have needed to generate a delegate
+ * debug identifier mapping using the DelegateMappingBuilder library present in
+ * executorch/exir/backend/utils.py. The delegate debug identifiers generated by
+ * that library are the ones that need to be passed to these hooks to log
+ * events. Using any other identifiers will cause post-processing of the events
+ * data to not properly link back to the nodes in the original lowered graph.
+ *
+ * The benefit of defining these hooks is that we can easily control whether or
+ * not we want to compile in the EventTracer code based on the status of the
+ * ET_EVENT_TRACER_ENABLED flag.
+ */
+
+namespace torch {
+namespace executor {
+
+/**
+ * Start the profiling of a delegate event. Similar to start_profiling it will
+ * return an instance of EventTracerEntry that contains the details of this
+ * event. Can be left in production code as these hooks compile conditionally.
+ *
+ * @param[in] event_tracer The event tracer instance that is doing the logging.
+ * @param[in] name Human readable name for the delegate event. This name has
+ * to be the same name that was passed in during the Debug delegate mapping
+ * generation in the export/ahead-of-time process. If indices and not names
+ * are used by this delegate to identify ops executed in the backend then
+ * nullptr can be passed in. Users calling this interface do not need to keep
+ * the memory pointed to by this pointer around. The string must be copied over
+ * into internal memory during this call.
+ * @param[in] delegate_debug_id The id of the delegate event. If string
+ * based names are used by this delegate to identify ops executed in the
+ * backend then kUnsetDebugHandle should be passed in here.
+ */
+inline EventTracerEntry event_tracer_start_profiling_delegate(
+    EventTracer* event_tracer,
+    const char* name,
+    DebugHandle delegate_debug_id) {
+#ifdef ET_EVENT_TRACER_ENABLED
+  if (event_tracer) {
+    return event_tracer->start_profiling_delegate(name, delegate_debug_id);
+  }
+#else //! ET_EVENT_TRACER_ENABLED
+  (void)name;
+  (void)delegate_debug_id;
+#endif
+  // There is no active tracer; this value will be ignored.
+  return EventTracerEntry();
+}
+/**
+ * Signal the end of the delegate profiling event contained in
+ * event_tracer_entry. Users also have the option to log some some free-from
+ * string based metadata along with this. Can be left in production code as
+ * these hooks compile conditionally.
+ *
+ * @param[in] event_tracer The event tracer instance that is doing the logging.
+ * @param[in] event_tracer_entry The EventTracerEntry returned by a call to
+ * start_profiling_delegate().
+ * @param[in] metadata Free-form metadata associated with the delegate event.
+ * Users calling this interface do not need to keep the memory pointed to by
+ * this pointer around. The string must be copied over into internal memory
+ * during this call. The input string must also be null terminated.
+ */
+inline void event_tracer_end_profiling_delegate(
+    EventTracer* event_tracer,
+    EventTracerEntry event_tracer_entry,
+    const char* metadata = nullptr) {
+#ifdef ET_EVENT_TRACER_ENABLED
+  if (event_tracer) {
+    event_tracer->end_profiling_delegate(event_tracer_entry, metadata);
+  }
+#else //! ET_EVENT_TRACER_ENABLED
+  (void)event_tracer_entry;
+  (void)metadata;
+#endif
+}
+
+/**
+ * Some delegates get access to the profiling details only after the complete
+ * graph has been executed. This interface is to support such use cases. It
+ * can be called in a loop etc. to log any number of profiling events that are
+ * part of this delegate. Can be left in production code as these hooks
+ * compile conditionally.
+ *
+ * @param[in] event_tracer The event tracer instance that is doing the logging.
+ * @param[in] name Human readable name for the delegate event. This name has
+ * to be the same name that was passed in during the Debug delegate mapping
+ * generation in the export/ahead-of-time process. If indices and not names
+ * are used by this delegate to identify ops executed in the backend then
+ * nullptr can be passed in. Users calling this interface do not need to keep
+ * the memory pointed to by this pointer around. The string must
+ * be copied over into internal memory during this call.
+ * @param[in] delegate_debug_id The id of the delegate event. If string
+ * based names are used by this delegate to identify ops executed in the
+ * backend then -1 should be passed in here.
+ * @param[in] start_time The timestamp when the delegate event started.
+ * @param[in] end_time The timestamp when the delegate event finished.
+ * @param[in] metadata Any extra data relevant to the execution that the user
+ * wants to log along with this event. Pointer to metadata doesn't need to be
+ * valid after the call to this function. Users calling this interface do not
+ * need to keep the memory pointed to by this pointer around. The string must
+ * be copied over into internal memory during this call. The input string must
+ * also be a null terminated.
+ */
+inline void event_tracer_log_profiling_delegate(
+    EventTracer* event_tracer,
+    const char* name,
+    DebugHandle delegate_debug_id,
+    et_timestamp_t start_time,
+    et_timestamp_t end_time,
+    const char* metadata = nullptr) {
+#ifdef ET_EVENT_TRACER_ENABLED
+  if (event_tracer) {
+    event_tracer->log_profiling_delegate(
+        name, delegate_debug_id, start_time, end_time, metadata);
+  }
+#else //! ET_EVENT_TRACER_ENABLED
+  (void)name;
+  (void)delegate_debug_id;
+  (void)start_time;
+  (void)end_time;
+  (void)metadata;
+#endif
+}
+
+} // namespace executor
+} // namespace torch
diff --git a/runtime/core/targets.bzl b/runtime/core/targets.bzl
@@ -24,6 +24,7 @@ def define_common_targets():
             "error.h",
             "event_tracer.h",
             "event_tracer_hooks.h",
+            "event_tracer_hooks_delegate.h",
             "freeable_buffer.h",
             "function_ref.h",
             "result.h",
diff --git a/runtime/core/test/event_tracer_test.cpp b/runtime/core/test/event_tracer_test.cpp
@@ -12,6 +12,7 @@
 // Enable flag for test
 #define ET_EVENT_TRACER_ENABLED
 #include <executorch/runtime/core/event_tracer_hooks.h>
+#include <executorch/runtime/core/event_tracer_hooks_delegate.h>
 
 namespace torch {
 namespace executor {
@@ -54,8 +55,39 @@ class DummyEventTracer : public EventTracer {
     (void)name;
     return 0;
   }
+
+  EventTracerEntry start_profiling_delegate(
+      const char* name,
+      DebugHandle delegate_debug_id) override {
+    (void)name;
+    (void)delegate_debug_id;
+    return EventTracerEntry();
+  }
+
+  void end_profiling_delegate(
+      EventTracerEntry event_tracer_entry,
+      const char* metadata) override {
+    (void)event_tracer_entry;
+    (void)metadata;
+  }
+
+  void log_profiling_delegate(
+      const char* name,
+      DebugHandle delegate_debug_id,
+      et_timestamp_t start_time,
+      et_timestamp_t end_time,
+      const char* metadata = nullptr) override {
+    (void)name;
+    (void)delegate_debug_id;
+    (void)start_time;
+    (void)end_time;
+    (void)metadata;
+  }
 };
 
+/**
+ * Exercise all the event_tracer API's for a basic sanity check.
+ */
 void RunSimpleTracerTest(EventTracer* event_tracer) {
   event_tracer_create_event_block(event_tracer, "ExampleEvent");
   event_tracer_create_event_block(event_tracer, "ExampleEvent");
@@ -86,6 +118,33 @@ TEST(TestEventTracer, SimpleEventTracerTest) {
   }
 }
 
+/**
+ * Exercise all the event_tracer API's for delegates as a basic sanity check.
+ */
+void RunSimpleTracerTestDelegate(EventTracer* event_tracer) {
+EventTracerEntry event_tracer_entry = event_tracer_start_profiling_delegate(
+      event_tracer, "test_event", kUnsetDebugHandle);
+  event_tracer_end_profiling_delegate(
+      event_tracer, event_tracer_entry, nullptr);
+  event_tracer_start_profiling_delegate(event_tracer, nullptr, 1);
+  event_tracer_end_profiling_delegate(
+      event_tracer, event_tracer_entry, "test_metadata");
+  event_tracer_log_profiling_delegate(
+      event_tracer, "test_event", kUnsetDebugHandle, 0, 1, nullptr);
+  event_tracer_log_profiling_delegate(event_tracer, nullptr, 1, 0, 1, nullptr);
+}
+
+TEST(TestEventTracer, SimpleEventTracerTestDelegate) {
+  // Call all the EventTracer macro's with a valid pointer to an event tracer
+  // and also with a null pointer (to test that the null case works).
+  DummyEventTracer dummy;
+  std::vector<DummyEventTracer*> dummy_event_tracer_arr = {&dummy, nullptr};
+  for (size_t i = 0; i < dummy_event_tracer_arr.size(); i++) {
+    RunSimpleTracerTestDelegate(&dummy);
+    RunSimpleTracerTestDelegate(nullptr);
+  }
+}
+
 } // namespace executor
 } // namespace torch
 // TODO : (T163645377) Add more test coverage to log and verify events passed
