[Profile] Add memory statiscs & annotation

It add two functions:
- provide PROFILE_MEM_ANNOTATE macro
- print average and maximum usage of memory.

Signed-off-by: Jiho Chu <jiho.chu@samsung.com>

diff --git a/nntrainer/utils/profiler.cpp b/nntrainer/utils/profiler.cpp
index 167f8a1643fbab80035edc46360492efd2601535..98a83dc952b7f25cf824668d3b3f587c61b0215a 100644 (file)
--- a/nntrainer/utils/profiler.cpp
+++ b/nntrainer/utils/profiler.cpp
@@ -54,9 +54,16 @@ void GenericProfileListener::onNotifyTimeEvent(
 }
 
 void GenericProfileListener::onNotifyMemoryEvent(
-  PROFILE_EVENT event, const size_t total_alloc_size, const std::string &str,
-  const std::chrono::microseconds &duration) {
-  mem_taken.emplace_back(event, total_alloc_size, str, duration);
+  PROFILE_EVENT event, const size_t alloc_current, const size_t alloc_total,
+  const std::string &str, const std::chrono::microseconds &duration) {
+
+  if (event != EVENT_MEM_ANNOTATE) {
+    mem_max = std::max(mem_max, alloc_total);
+    mem_sum += alloc_total;
+    mem_average = mem_sum / ++mem_count;
+  }
+
+  mem_taken.emplace_back(event, alloc_current, alloc_total, str, duration);
 }
 
 void GenericProfileListener::notify(
@@ -70,8 +77,9 @@ void GenericProfileListener::notify(
     break;
   case EVENT_MEM_ALLOC:
   case EVENT_MEM_DEALLOC:
-    onNotifyMemoryEvent(event, data->total_alloc_size, data->event_str,
-                        data->duration);
+  case EVENT_MEM_ANNOTATE:
+    onNotifyMemoryEvent(event, data->alloc_current, data->alloc_total,
+                        data->event_str, data->duration);
     break;
   default:
     throw std::runtime_error("Invalid PROFILE_EVENT");
@@ -188,9 +196,11 @@ void GenericProfileListener::report(std::ostream &out) const {
   /// creating header
   // clang-format off
   out << std::setw(column_size[0]) << "event"
-      << std::setw(column_size[1]) << "current size"
-      << std::setw(column_size[2]) << "info"
-      << std::setw(column_size[3]) << "dur" << '\n';
+      << std::setw(column_size[1]) << "size"
+      << std::setw(column_size[2]) << "total"
+      << std::setw(column_size[2]) << ""
+      << std::setw(column_size[3]) << "info"
+      << std::setw(column_size[4]) << "dur" << '\n';
   // clang-format on
   out << std::string(total_col_size, '=') << '\n';
 
@@ -198,17 +208,21 @@ void GenericProfileListener::report(std::ostream &out) const {
   for (auto &mem : mem_taken) {
     auto func = [&](std::ostream &out_) {
       auto &event = std::get<PROFILE_EVENT>(mem);
-      auto &size = std::get<size_t>(mem);
+      auto &cur = std::get<1>(mem);
+      auto &total = std::get<2>(mem);
       auto &info = std::get<std::string>(mem);
       auto &dur = std::get<std::chrono::microseconds>(mem);
 
       out_.setf(std::ios::fixed);
       std::streamsize default_precision = out_.precision(2);
       // clang-format off
-      out_ << std::setw(column_size[0]) << ((event == EVENT_MEM_ALLOC) ? "ALLOC" : "DEALLOC")
-          << std::setw(column_size[1]) << size
-          << std::setw(column_size[2]) << info
-          << std::setw(column_size[3]) << dur.count() << '\n';
+      out_ << std::setw(column_size[0]) << ((event == EVENT_MEM_ALLOC) ? "ALLOC" :
+                                            (event == EVENT_MEM_DEALLOC) ? "DEALLOC" : "")
+          << std::setw(column_size[1]) << ((event != EVENT_MEM_ANNOTATE) ? std::to_string(cur) : "")
+          << std::setw(column_size[2]) << ((event != EVENT_MEM_ANNOTATE) ? std::to_string(total) : "")
+          << std::setw(column_size[3]) << ((event == EVENT_MEM_ANNOTATE) ? "\n" + info : "")
+          << std::setw(column_size[3]) << ((event != EVENT_MEM_ANNOTATE) ? info : "")
+          << std::setw(column_size[4]) << ((event == EVENT_MEM_DEALLOC) ? std::to_string(dur.count()) : "") << '\n';
       // clang-format on
       out_.precision(default_precision);
       out_.unsetf(std::ios::fixed);
@@ -218,6 +232,9 @@ void GenericProfileListener::report(std::ostream &out) const {
 
   for (auto &entry : ordered_report)
     entry.second(out);
+
+  out << "Max Memory Size = " << mem_max << std::endl;
+  out << "Average Memory Size = " << mem_average << std::endl;
 }
 
 Profiler &Profiler::Global() {
@@ -238,7 +255,7 @@ void Profiler::start(const int item) {
 
   time_item_times[item] = std::chrono::steady_clock::now();
 
-  auto data = std::make_shared<ProfileEventData>(item, 0, name->second,
+  auto data = std::make_shared<ProfileEventData>(item, 0, 0, name->second,
                                                  std::chrono::microseconds(0));
   notifyListeners(EVENT_TIME_START, data);
 }
@@ -260,7 +277,7 @@ void Profiler::end(const int item) {
   auto duration =
     std::chrono::duration_cast<std::chrono::microseconds>(end - start);
   auto data =
-    std::make_shared<ProfileEventData>(item, 0, name->second, duration);
+    std::make_shared<ProfileEventData>(item, 0, 0, name->second, duration);
 
   notifyListeners(EVENT_TIME_END, data);
 
@@ -332,8 +349,8 @@ void Profiler::alloc(const void *ptr, size_t size, const std::string &str) {
 
   total_size += size;
 
-  auto data = std::make_shared<ProfileEventData>(0, total_size.load(), str,
-                                                 std::chrono::microseconds(0));
+  auto data = std::make_shared<ProfileEventData>(
+    0, size, total_size.load(), str, std::chrono::microseconds(0));
   notifyListeners(EVENT_MEM_ALLOC, data);
 }
 
@@ -355,13 +372,22 @@ void Profiler::dealloc(const void *ptr) {
 
   auto str = std::get<std::string>(found->second);
   auto data =
-    std::make_shared<ProfileEventData>(0, total_size.load(), str, duration);
+    std::make_shared<ProfileEventData>(0, 0, total_size.load(), str, duration);
 
   notifyListeners(EVENT_MEM_DEALLOC, data);
 
   allocates.erase(found);
 }
 
+void Profiler::annotate(const std::string &str) {
+  std::lock_guard<std::mutex> lock(allocates_mutex);
+
+  auto data = std::make_shared<ProfileEventData>(0, 0, 0, str,
+                                                 std::chrono::microseconds(0));
+
+  notifyListeners(EVENT_MEM_ANNOTATE, data);
+}
+
 } // namespace profile
 
 } // namespace nntrainer

diff --git a/nntrainer/utils/profiler.h b/nntrainer/utils/profiler.h
index 3da19e71b3779a5b65abcd6e1b41a361b24c797f..af808fb593ac82fbc9e16028301ccab4177f8d4a 100644 (file)
--- a/nntrainer/utils/profiler.h
+++ b/nntrainer/utils/profiler.h
@@ -35,6 +35,8 @@ using timepoint = std::chrono::time_point<std::chrono::steady_clock>;
 #define PROFILE_MEM_DEALLOC(ptr)
 #define PROFILE_BEGIN(listener)
 #define PROFILE_END(listener)
+#define PROFILE_MEM_ANNOTATE(str)
+
 #else /** PROFILE */
 
 #define PROFILE_TIME_START(event_key) \
@@ -65,6 +67,9 @@ using timepoint = std::chrono::time_point<std::chrono::steady_clock>;
     std::cout << *listener;   \
   } while (0)
 
+#define PROFILE_MEM_ANNOTATE(str) \
+  nntrainer::profile::Profiler::Global().annotate(str)
+
 #endif /** PROFILE */
 
 namespace nntrainer {
@@ -76,6 +81,7 @@ enum PROFILE_EVENT {
   EVENT_TIME_END = 1,
   EVENT_MEM_ALLOC = 2,
   EVENT_MEM_DEALLOC = 3,
+  EVENT_MEM_ANNOTATE = 4,
 };
 
 /**
@@ -88,18 +94,22 @@ public:
    * @brief Construct a new ProfileEventData struct
    *
    */
-  ProfileEventData(int item, size_t size, std::string str,
+  ProfileEventData(int item, size_t cur, size_t total, std::string str,
                    std::chrono::microseconds dur) :
     time_item(item),
-    total_alloc_size(size),
+    alloc_current(cur),
+    alloc_total(total),
     event_str(str),
     duration(dur) {}
 
   /* for time profile */
   int time_item;
 
-  /* for memory profile */
-  size_t total_alloc_size;
+  /* current allocation size */
+  size_t alloc_current;
+
+  /* total allocation size */
+  size_t alloc_total;
 
   /* common data */
   std::string event_str;
@@ -172,7 +182,11 @@ public:
   explicit GenericProfileListener(int warmups_ = 0) :
     ProfileListener(),
     start_time(std::chrono::steady_clock::now()),
-    warmups(warmups_) {}
+    warmups(warmups_),
+    mem_max(0),
+    mem_sum(0),
+    mem_average(0),
+    mem_count(0) {}
 
   /**
    * @brief Destroy the Generic Profile Listener object
@@ -217,8 +231,8 @@ private:
    * @brief Called when memory event occurs
    *
    */
-  void onNotifyMemoryEvent(PROFILE_EVENT event, const size_t total_alloc_size,
-                           const std::string &str,
+  void onNotifyMemoryEvent(PROFILE_EVENT event, const size_t alloc_current,
+                           const size_t alloc_total, const std::string &str,
                            const std::chrono::microseconds &duration);
 
   std::chrono::time_point<std::chrono::steady_clock> start_time;
@@ -237,9 +251,13 @@ private:
                                      unsigned int /** CNT */>>
     time_taken;
 
-  std::list<
-    std::tuple<PROFILE_EVENT, size_t, std::string, std::chrono::microseconds>>
-    mem_taken;
+  std::list<std::tuple<PROFILE_EVENT, size_t, size_t, std::string,
+                       std::chrono::microseconds>>
+    mem_taken;        /**< taken memory information */
+  size_t mem_max;     /**< memory max size */
+  size_t mem_sum;     /**< memory sum */
+  size_t mem_average; /**< memory average */
+  size_t mem_count;   /**< memory count */
 
   std::unordered_map<int, std::string> names;
 };
@@ -312,6 +330,13 @@ public:
    */
   void dealloc(const void *ptr);
 
+  /**
+   * @brief add annotation on memory profile data
+   *
+   * @param str annotate message
+   */
+  void annotate(const std::string &str);
+
   /**
    * @brief subscribe a listener to the profiler
    *

diff --git a/test/unittest/unittest_nntrainer_profiler.cpp b/test/unittest/unittest_nntrainer_profiler.cpp
index f72d400525a9b513eaf3dd90c26a8fc6aa2654eb..294a84e5d8e0452ce25064adba0ef73aeb7de882 100644 (file)
--- a/test/unittest/unittest_nntrainer_profiler.cpp
+++ b/test/unittest/unittest_nntrainer_profiler.cpp
@@ -28,7 +28,9 @@ using namespace nntrainer::profile;
 class MockProfileListener : public ProfileListener {
 public:
   MockProfileListener() :
-    ProfileListener(), time_event_cnt(0), memory_alloc(0) {
+    ProfileListener(),
+    time_event_cnt(0),
+    memory_alloc(0) {
     ON_CALL(*this, notify)
       .WillByDefault(
         [&](PROFILE_EVENT event, const std::shared_ptr<ProfileEventData> data) {
@@ -40,7 +42,9 @@ public:
             break;
           case EVENT_MEM_ALLOC:
           case EVENT_MEM_DEALLOC:
-            this->memory_alloc = data->total_alloc_size;
+            this->memory_alloc = data->alloc_total;
+            break;
+          default:
             break;
           }
         });
@@ -61,18 +65,24 @@ public:
     return last;
   };
 
+  /**
+   * @brief mock method for notify
+   */
   MOCK_METHOD(void, notify,
               (PROFILE_EVENT event,
                const std::shared_ptr<ProfileEventData> data));
 
 private:
-  int time_event_cnt;  /**< time event count */
-  size_t memory_alloc; /**< allocated memory size */
+  int time_event_cnt;             /**< time event count */
+  size_t memory_alloc;            /**< allocated memory size */
   std::chrono::microseconds last; /** last event duration */
 };
 
+/**
+ * @brief Test class for ProfileTest
+ */
 class ProfileTest : public ::testing::Test {
- protected:
+protected:
   void SetUp() override {
     listener = std::make_shared<MockProfileListener>();
     profiler = std::make_shared<Profiler>();
@@ -82,44 +92,39 @@ class ProfileTest : public ::testing::Test {
   std::shared_ptr<Profiler> profiler;
 };
 
-
 TEST_F(ProfileTest, subscribe_01_n) {
-  EXPECT_CALL(*listener, notify(testing::_, testing::_))
-    .Times(0);
+  EXPECT_CALL(*listener, notify(testing::_, testing::_)).Times(0);
 
   EXPECT_THROW(profiler->subscribe(nullptr), std::invalid_argument);
 }
 
 TEST_F(ProfileTest, subscribe_02_n) {
-  EXPECT_CALL(*listener, notify(testing::_, testing::_))
-    .Times(0);
+  EXPECT_CALL(*listener, notify(testing::_, testing::_)).Times(0);
 
   EXPECT_THROW(profiler->subscribe(nullptr, {1}), std::invalid_argument);
 }
 
 TEST_F(ProfileTest, subscribe_03_p) {
-  EXPECT_CALL(*listener, notify(testing::_, testing::_))
-    .Times(0);
+  EXPECT_CALL(*listener, notify(testing::_, testing::_)).Times(0);
 
   EXPECT_NO_THROW(profiler->subscribe(listener));
 }
 
 TEST_F(ProfileTest, notify_01_p) {
-  EXPECT_CALL(*listener, notify(testing::_, testing::_))
-    .Times(3);
+  EXPECT_CALL(*listener, notify(testing::_, testing::_)).Times(3);
 
   EXPECT_NO_THROW(profiler->subscribe(listener));
 
-  auto data1 =
-    std::make_shared<ProfileEventData>(1, 0, "", std::chrono::microseconds{10});
+  auto data1 = std::make_shared<ProfileEventData>(
+    1, 0, 0, "", std::chrono::microseconds{10});
   listener->notify(PROFILE_EVENT::EVENT_TIME_START, data1);
 
   auto data2 = std::make_shared<ProfileEventData>(
-    1, 0, "", std::chrono::microseconds{100});
+    1, 0, 0, "", std::chrono::microseconds{100});
   listener->notify(PROFILE_EVENT::EVENT_TIME_END, data2);
 
   auto data3 = std::make_shared<ProfileEventData>(
-    1, 0, "", std::chrono::microseconds{150});
+    1, 0, 0, "", std::chrono::microseconds{150});
   listener->notify(PROFILE_EVENT::EVENT_TIME_END, data3);
 
   auto result = listener->result(1);
@@ -131,22 +136,19 @@ TEST_F(ProfileTest, notify_01_p) {
 }
 
 TEST_F(ProfileTest, start_01_n) {
-  EXPECT_CALL(*listener, notify(testing::_, testing::_))
-    .Times(0);
+  EXPECT_CALL(*listener, notify(testing::_, testing::_)).Times(0);
 
   EXPECT_THROW(profiler->start(1), std::invalid_argument);
 }
 
 TEST_F(ProfileTest, end_01_n) {
-  EXPECT_CALL(*listener, notify(testing::_, testing::_))
-    .Times(0);
+  EXPECT_CALL(*listener, notify(testing::_, testing::_)).Times(0);
 
   EXPECT_THROW(profiler->end(1), std::invalid_argument);
 }
 
 TEST_F(ProfileTest, timeTest_01_p) {
-  EXPECT_CALL(*listener, notify(testing::_, testing::_))
-    .Times(2);
+  EXPECT_CALL(*listener, notify(testing::_, testing::_)).Times(2);
 
   int nn_forward = profiler->registerTimeItem("nn_forward");
 
@@ -161,8 +163,7 @@ TEST_F(ProfileTest, timeTest_01_p) {
 }
 
 TEST_F(ProfileTest, timeTest_02_n) {
-  EXPECT_CALL(*listener, notify(testing::_, testing::_))
-    .Times(0);
+  EXPECT_CALL(*listener, notify(testing::_, testing::_)).Times(0);
 
   int nn_forward = profiler->registerTimeItem("nn_forward");
 
@@ -175,8 +176,7 @@ TEST_F(ProfileTest, timeTest_02_n) {
 }
 
 TEST_F(ProfileTest, timeTest_01_n) {
-  EXPECT_CALL(*listener, notify(testing::_, testing::_))
-    .Times(2);
+  EXPECT_CALL(*listener, notify(testing::_, testing::_)).Times(2);
 
   int nn_forward = profiler->registerTimeItem("nn_forward");