From 6c88a3080376bc7d158f496b8583b966987ca609 Mon Sep 17 00:00:00 2001 From: Jiho Chu Date: Thu, 25 Aug 2022 13:36:08 +0900 Subject: [PATCH] [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 --- nntrainer/utils/profiler.cpp | 62 +++++++++++++------ nntrainer/utils/profiler.h | 45 +++++++++++--- test/unittest/unittest_nntrainer_profiler.cpp | 56 ++++++++--------- 3 files changed, 107 insertions(+), 56 deletions(-) diff --git a/nntrainer/utils/profiler.cpp b/nntrainer/utils/profiler.cpp index 167f8a16..98a83dc9 100644 --- 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(mem); - auto &size = std::get(mem); + auto &cur = std::get<1>(mem); + auto &total = std::get<2>(mem); auto &info = std::get(mem); auto &dur = std::get(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(item, 0, name->second, + auto data = std::make_shared(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(end - start); auto data = - std::make_shared(item, 0, name->second, duration); + std::make_shared(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(0, total_size.load(), str, - std::chrono::microseconds(0)); + auto data = std::make_shared( + 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(found->second); auto data = - std::make_shared(0, total_size.load(), str, duration); + std::make_shared(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 lock(allocates_mutex); + + auto data = std::make_shared(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 3da19e71..af808fb5 100644 --- a/nntrainer/utils/profiler.h +++ b/nntrainer/utils/profiler.h @@ -35,6 +35,8 @@ using timepoint = std::chrono::time_point; #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::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 start_time; @@ -237,9 +251,13 @@ private: unsigned int /** CNT */>> time_taken; - std::list< - std::tuple> - mem_taken; + std::list> + 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 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 f72d4005..294a84e5 100644 --- 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 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 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(); profiler = std::make_shared(); @@ -82,44 +92,39 @@ class ProfileTest : public ::testing::Test { std::shared_ptr 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(1, 0, "", std::chrono::microseconds{10}); + auto data1 = std::make_shared( + 1, 0, 0, "", std::chrono::microseconds{10}); listener->notify(PROFILE_EVENT::EVENT_TIME_START, data1); auto data2 = std::make_shared( - 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( - 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"); -- 2.34.1