From: Jihoon Lee <jhoon.it.lee@samsung.com>
Date: Fri, 18 Dec 2020 01:52:14 +0000 (+0900)
Subject: [Profiler] Add event registerator
X-Git-Tag: accepted/tizen/unified/20210122.084701~25
X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=2710e049e055116f46848021db8ccaeccbea6977;p=platform%2Fcore%2Fml%2Fnntrainer.git

[Profiler] Add event registerator

Profiler can now dynamically register event and send it to
profileListenr as of this patch with fixing few bugs

resolves #814

**Self evaluation:**
1. Build test: [X]Passed [ ]Failed [ ]Skipped
2. Run test: [X]Passed [ ]Failed [ ]Skipped

Signed-off-by: Jihoon Lee <jhoon.it.lee@samsung.com>
---

diff --git a/nntrainer/utils/profiler.cpp b/nntrainer/utils/profiler.cpp
index 2d9caf7..06aed17 100644
--- a/nntrainer/utils/profiler.cpp
+++ b/nntrainer/utils/profiler.cpp
@@ -16,6 +16,7 @@
 #include <sstream>
 #include <tuple>
 
+#include <nntrainer_error.h>
 #include <nntrainer_log.h>
 #include <profiler.h>
 
@@ -83,7 +84,7 @@ GenericProfileListener::result(const int event) {
   if (iter == time_taken.end() ||
       std::get<GenericProfileListener::CNT>(iter->second) == 0) {
     std::stringstream ss;
-    ss << "event has never recorded" << event_to_str(event);
+    ss << "event has never recorded" << profiler->eventToStr(event);
     throw std::invalid_argument("event has never recorded");
   }
 
@@ -91,7 +92,13 @@ GenericProfileListener::result(const int event) {
 }
 
 void GenericProfileListener::report(std::ostream &out) const {
-  const std::vector<unsigned int> column_size = {10, 23, 23, 23};
+  std::vector<unsigned int> column_size = {10, 23, 23, 23};
+
+  for (auto &entry : time_taken) {
+    auto title = profiler->eventToStr(entry.first);
+    column_size[0] =
+      std::max(column_size[0], static_cast<unsigned int>(title.length()));
+  }
   auto total_col_size =
     std::accumulate(column_size.begin(), column_size.end(), 0);
 
@@ -115,16 +122,18 @@ void GenericProfileListener::report(std::ostream &out) const {
     auto &cnt_ = std::get<GenericProfileListener::CNT>(entry.second);
     auto &min_ = std::get<GenericProfileListener::MIN>(entry.second);
     auto &max_ = std::get<GenericProfileListener::MAX>(entry.second);
-    auto &sum_ = std::get<GenericProfileListener::SUM>(time_iter->second);
+    auto &sum_ = std::get<GenericProfileListener::SUM>(entry.second);
+
+    auto title = profiler->eventToStr(entry.first);
 
     if (warmups >= cnt_) {
-      out << std::left << std::setw(total_col_size) << event_to_str(entry.first)
+      out << std::left << std::setw(total_col_size) << title
           << "less data then warmup\n";
       continue;
     }
 
     // clang-format off
-    out << std::setw(column_size[0]) << event_to_str(entry.first)
+    out << std::setw(column_size[0]) << title
         << std::setw(column_size[1]) << sum_.count() / (cnt_ - warmups)
         << std::setw(column_size[2]) << min_.count()
         << std::setw(column_size[3]) << max_.count() << '\n';
@@ -137,19 +146,6 @@ Profiler &Profiler::Global() {
   return instance;
 }
 
-std::string event_to_str(const int event) {
-  switch (event) {
-  case EVENT::NN_FORWARD:
-    return "nn_forward";
-  case EVENT::TEMP:
-    return "temp";
-  }
-
-  std::stringstream ss;
-  ss << "undef(" << event << ')';
-  return ss.str();
-}
-
 void Profiler::start(const int &event) {
 #ifdef DEBUG
   /// @todo: consider race condition
@@ -236,6 +232,38 @@ void Profiler::unsubscribe(ProfileListener *listener) {
   }
 }
 
+std::string Profiler::eventToStr(const int event) {
+
+  /// reserved event
+  if (event >= 0) {
+    switch (event) {
+    case EVENT::NN_FORWARD:
+      return "nn_forward";
+    }
+  }
+  /// custom events
+  else if (event < 0) {
+    std::lock_guard<std::mutex> lk(event_registration_mutex);
+    int actual_idx = -event + 1;
+
+    if (actual_idx > static_cast<int>(custom_events.size()) - 1) {
+      std::stringstream ss;
+      ss << "undef(" << event << ')';
+      return ss.str();
+    }
+    return custom_events[actual_idx];
+  }
+
+  throw std::logic_error("control should not reach here");
+}
+
+int Profiler::registerEvent(const std::string &name) {
+  std::lock_guard<std::mutex> lk(event_registration_mutex);
+  custom_events.push_back(name);
+
+  return -custom_events.size();
+}
+
 } // namespace profile
 
 } // namespace nntrainer
diff --git a/nntrainer/utils/profiler.h b/nntrainer/utils/profiler.h
index 955e1b5..046bf27 100644
--- a/nntrainer/utils/profiler.h
+++ b/nntrainer/utils/profiler.h
@@ -16,6 +16,7 @@
 
 #define START_PROFILE(event_key)
 #define END_PROFILE(event_key)
+#define REGISTER_EVENT(event_key, ret)
 
 #else
 
@@ -31,6 +32,12 @@
     prof.end(event_key);                                 \
   } while (0);
 
+#define REGISTER_EVENT(event_str, ret)                   \
+  do {                                                   \
+    auto &prof = nntrainer::profile::Profiler::Global(); \
+    ret = prof.registerEvent(event_str);                 \
+  } while (0);
+
 #endif /** PROFILE */
 
 #include <chrono>
@@ -45,17 +52,9 @@ namespace nntrainer {
 namespace profile {
 
 typedef enum {
-  NN_FORWARD = 0 /**< Neuralnet single inference without loss calculation */,
-  TEMP = 999 /**< Temporary event */
+  NN_FORWARD = 1 /**< Neuralnet single inference without loss calculation */,
 } EVENT;
 
-/**
- * @brief get string representation of event
- *
- * @return std::string name
- */
-std::string event_to_str(const int event);
-
 class Profiler;
 /**
  * @brief Generic profile listener class to attach to a profiler,
@@ -109,7 +108,7 @@ public:
    */
   virtual void report(std::ostream &out) const = 0;
 
-private:
+protected:
   Profiler *profiler;
 };
 
@@ -239,6 +238,21 @@ public:
    */
   void unsubscribe(ProfileListener *listener);
 
+  /**
+   * @brief registerEvent to record.
+   * @note Call to the function shouldn't be inside a critical path
+   *
+   * @return int return NEGATIVE integer to distinguish from reserved events
+   */
+  int registerEvent(const std::string &name);
+
+  /**
+   * @brief get string representation of an event
+   *
+   * @return std::string name
+   */
+  std::string eventToStr(const int event);
+
 private:
   /**
    * @brief notify the result
@@ -260,6 +274,12 @@ private:
   std::unordered_map<int, std::chrono::time_point<std::chrono::steady_clock>>
     start_time; /**< start_time of the clock */
 
+  std::vector<std::string>
+    custom_events; /**< integer indexed custom events. Actual key is negative to
+                      avoid clashing */
+
+  std::mutex event_registration_mutex; /**< protect custom event registration */
+
   std::mutex subscription_mutex; /**< protect sub/unsub routine to
                                              gaurantee invarient */
 };
diff --git a/test/unittest/unittest_nntrainer_profiler.cpp b/test/unittest/unittest_nntrainer_profiler.cpp
index 0e40da9..ae68701 100644
--- a/test/unittest/unittest_nntrainer_profiler.cpp
+++ b/test/unittest/unittest_nntrainer_profiler.cpp
@@ -35,7 +35,7 @@ public:
 
   void reset(const int event) override { hit = false; }
 
-  void report(std::ostream &out) const override {
+  virtual void report(std::ostream &out) const override {
     out << (hit ? "hit" : "no hit");
   }
 
@@ -97,8 +97,8 @@ TEST(Profiler, profilePositiveTests_p) {
   /// measure that are not registered for event listener
   all_listener->reset(EVENT::NN_FORWARD);
   event_listener->reset(EVENT::NN_FORWARD);
-  prof.start(EVENT::TEMP);
-  prof.end(EVENT::TEMP);
+  prof.start(-1);
+  prof.end(-1);
 
   /// Check if notified on event profiler does not hit
   {
@@ -107,6 +107,13 @@ TEST(Profiler, profilePositiveTests_p) {
     EXPECT_EQ(ss.str(), "no hit");
   }
 
+  /// register a event key to profiler and check event to str
+  {
+    int key = prof.registerEvent("hello_world");
+    EXPECT_LT(key, 0);
+    EXPECT_EQ(prof.eventToStr(key), "hello_world");
+  }
+
   /// unsubscribe event_listener
   event_listener->reset(EVENT::NN_FORWARD);
   prof.unsubscribe(event_listener.get());