From fa8093139cc056445bb76b8df65f1265679c8e6e Mon Sep 17 00:00:00 2001 From: Jihoon Lee Date: Wed, 9 Dec 2020 16:23:03 +0900 Subject: [PATCH] [Profiler] Add basic profilerlistener This patch adds global profiler listener for various purpose From this patch, 1. Profiler can called globally with designated event key 2. Listener reporting suite included 3. Enum key has changed to int key to deal with unhashable key compile error in few platforms. **Self evaluation:** 1. Build test: [X]Passed [ ]Failed [ ]Skipped 2. Run test: [X]Passed [ ]Failed [ ]Skipped v2) 1. Change listener to RAII object (with forcing profiler, event designation) 2. Add unsubscribe method 3. Change event register to set to prevent notifying a listener twice 4. Change semintics to not allow adding same listener twice Signed-off-by: Jihoon Lee --- nntrainer/models/neuralnet.cpp | 6 +- nntrainer/utils/profiler.cpp | 181 +++++++++++++++++++++++--- nntrainer/utils/profiler.h | 119 ++++++++++++----- test/unittest/unittest_nntrainer_profiler.cpp | 82 ++++++++++-- 4 files changed, 321 insertions(+), 67 deletions(-) diff --git a/nntrainer/models/neuralnet.cpp b/nntrainer/models/neuralnet.cpp index 93b2435..4bc7634 100644 --- a/nntrainer/models/neuralnet.cpp +++ b/nntrainer/models/neuralnet.cpp @@ -273,11 +273,7 @@ sharedConstTensors NeuralNetwork::forwarding(sharedConstTensors input, sharedConstTensors X; if (input[0]->getDim().batch() > batch_size) throw std::logic_error("Error: mismatch in batchsize for data and model."); - - START_PROFILE(profile::NN_FORWARD); X = forwarding(input); - END_PROFILE(profile::NN_FORWARD); - X = std::static_pointer_cast(model_graph.Sorted.back().layer) ->forwarding(X, label); @@ -417,7 +413,9 @@ sharedConstTensors NeuralNetwork::inference(sharedConstTensors X) { sharedConstTensors out; try { + START_PROFILE(profile::NN_FORWARD); forwarding(X); + END_PROFILE(profile::NN_FORWARD); /** Forward loss layer without label as well */ std::static_pointer_cast(model_graph.Sorted.back().layer) ->forwarding(); diff --git a/nntrainer/utils/profiler.cpp b/nntrainer/utils/profiler.cpp index 327635b..2d9caf7 100644 --- a/nntrainer/utils/profiler.cpp +++ b/nntrainer/utils/profiler.cpp @@ -10,19 +10,134 @@ * @bug No known bugs except for NYI items * */ +#include +#include +#include #include +#include +#include #include namespace nntrainer { namespace profile { +ProfileListener::ProfileListener(Profiler *profiler_, std::vector events) : + profiler(profiler_) { + if (profiler != nullptr) { + profiler->subscribe(this, events); + } +} + +ProfileListener::~ProfileListener() noexcept { + if (profiler != nullptr) { + try { + profiler->unsubscribe(this); + } catch (...) { + ml_logw("unsubscribing profiler failed may cause undefined error"); + } + } +} + +void GenericProfileListener::onNotify(const int event, + const std::chrono::milliseconds &value) { + + time_iter = time_taken.find(event); + + if (time_iter == time_taken.end()) { + reset(event); // this sets time_iter to current, note that this is a side + // effect of reset() + } + auto &cnt_ = std::get(time_iter->second); + cnt_++; + + if (warmups >= cnt_) { + return; + } + + auto &cur_ = std::get(time_iter->second); + auto &min_ = std::get(time_iter->second); + auto &max_ = std::get(time_iter->second); + auto &sum_ = std::get(time_iter->second); + + cur_ = value; + min_ = std::min(min_, value); + max_ = std::max(max_, value); + sum_ += value; +} + +void GenericProfileListener::reset(const int event) { + time_iter = + time_taken + .insert({event, std::make_tuple(std::chrono::milliseconds{0}, + std::chrono::milliseconds::max(), + std::chrono::milliseconds::min(), + std::chrono::milliseconds{0}, int{0})}) + .first; +} + +const std::chrono::milliseconds +GenericProfileListener::result(const int event) { + auto iter = time_taken.find(event); + + if (iter == time_taken.end() || + std::get(iter->second) == 0) { + std::stringstream ss; + ss << "event has never recorded" << event_to_str(event); + throw std::invalid_argument("event has never recorded"); + } + + return std::get(iter->second); +} + +void GenericProfileListener::report(std::ostream &out) const { + const std::vector column_size = {10, 23, 23, 23}; + auto total_col_size = + std::accumulate(column_size.begin(), column_size.end(), 0); + + if (warmups != 0) { + out << "warm up: " << warmups << '\n'; + } + + /// creating header + // clang-format off + out << std::setw(column_size[0]) << "key" + << std::setw(column_size[1]) << "avg" + << std::setw(column_size[2]) << "min" + << std::setw(column_size[3]) << "max" << '\n'; + // clang-format on + + // seperator + out << std::string(total_col_size, '=') << '\n'; + + /// calculate metrics while skipping warmups + for (auto &entry : time_taken) { + auto &cnt_ = std::get(entry.second); + auto &min_ = std::get(entry.second); + auto &max_ = std::get(entry.second); + auto &sum_ = std::get(time_iter->second); + + if (warmups >= cnt_) { + out << std::left << std::setw(total_col_size) << event_to_str(entry.first) + << "less data then warmup\n"; + continue; + } + + // clang-format off + out << std::setw(column_size[0]) << event_to_str(entry.first) + << std::setw(column_size[1]) << sum_.count() / (cnt_ - warmups) + << std::setw(column_size[2]) << min_.count() + << std::setw(column_size[3]) << max_.count() << '\n'; + // clang-format on + } +} + Profiler &Profiler::Global() { static Profiler instance; return instance; } -std::string event_to_str(const EVENT event) { +std::string event_to_str(const int event) { switch (event) { case EVENT::NN_FORWARD: return "nn_forward"; @@ -31,67 +146,93 @@ std::string event_to_str(const EVENT event) { } std::stringstream ss; - ss << "undefined key - " << event; + ss << "undef(" << event << ')'; return ss.str(); } -void Profiler::start(const EVENT &event) { +void Profiler::start(const int &event) { +#ifdef DEBUG /// @todo: consider race condition auto iter = start_time.find(event); - if (iter != start_time.end()) { throw std::invalid_argument("profiler has already started"); } +#endif start_time[event] = std::chrono::steady_clock::now(); } -void Profiler::end(const EVENT &event) { +void Profiler::end(const int &event) { /// @todo: consider race condition auto end = std::chrono::steady_clock::now(); auto iter = start_time.find(event); +#ifdef DEBUG if (iter == start_time.end()) { throw std::invalid_argument("profiler hasn't started with the event"); } +#endif auto duration = std::chrono::duration_cast(end - iter->second); notify(event, duration); +#ifdef DEBUG start_time.erase(iter); +#endif } -void Profiler::notify(const EVENT &event, +void Profiler::notify(const int &event, const std::chrono::milliseconds &value) { - for (auto listener : all_event_listeners) { + std::lock_guard lk(subscription_mutex); + for (auto &listener : all_event_listeners) { listener->onNotify(event, value); } - auto items = event_listeners[event]; - for (auto listner : items) { + auto &items = event_listeners[event]; + + for (auto &listner : items) { listner->onNotify(event, value); } } void Profiler::subscribe(ProfileListener *listener, - const std::vector &events) { - + const std::vector &events) { if (listener == nullptr) { throw std::invalid_argument("listener is null!"); } - if (events.empty()) { - all_event_listeners.push_back(listener); - return; - } + { + std::lock_guard lk(subscription_mutex); + if (all_registered_listeners.count(listener) == 1) { + throw std::invalid_argument( + "listener is already registered, please unsubscribe before subscribe "); + } + + all_registered_listeners.insert(listener); - for (auto event : events) { - auto iter = event_listeners.find(event); - if (iter == event_listeners.end()) { - event_listeners[event] = std::vector{}; + if (events.empty()) { + all_event_listeners.insert(listener); + return; } - event_listeners[event].push_back(listener); + + for (auto event : events) { + auto iter = event_listeners.find(event); + if (iter == event_listeners.end()) { + event_listeners[event] = std::unordered_set{}; + } + event_listeners[event].insert(listener); + } + } +} + +void Profiler::unsubscribe(ProfileListener *listener) { + std::lock_guard lk(subscription_mutex); + all_registered_listeners.erase(listener); + all_event_listeners.erase(listener); + + for (auto &it : event_listeners) { + it.second.erase(listener); } } diff --git a/nntrainer/utils/profiler.h b/nntrainer/utils/profiler.h index 98dbfe1..955e1b5 100644 --- a/nntrainer/utils/profiler.h +++ b/nntrainer/utils/profiler.h @@ -10,18 +10,8 @@ * @bug No known bugs except for NYI items * */ - #ifndef __PROFILER_H__ #define __PROFILER_H__ - -namespace nntrainer { -namespace profile { -typedef enum { - NN_FORWARD = 0 /**< Neuralnet single inference without loss calculation */, - TEMP = 999 /**< Temporary event */ -} EVENT; -} -} // namespace nntrainer #ifndef PROFILE #define START_PROFILE(event_key) @@ -44,20 +34,29 @@ typedef enum { #endif /** PROFILE */ #include +#include #include +#include #include #include +#include #include - namespace nntrainer { namespace profile { + +typedef enum { + NN_FORWARD = 0 /**< Neuralnet single inference without loss calculation */, + TEMP = 999 /**< Temporary event */ +} EVENT; + /** * @brief get string representation of event * * @return std::string name */ -std::string event_to_str(const EVENT event); +std::string event_to_str(const int event); +class Profiler; /** * @brief Generic profile listener class to attach to a profiler, * this can be inherited to create a custom profile listener @@ -65,10 +64,19 @@ std::string event_to_str(const EVENT event); class ProfileListener { public: /** + * @brief Construct a new Profile Listener object + * + * @param profiler_ profiler that this listener is bound to. Unsubscribe will + * be called when destruction + * @param events events for this profiler to listen to + */ + ProfileListener(Profiler *profiler_, std::vector events); + + /** * @brief Destroy the Base Profile Listener object * */ - virtual ~ProfileListener() = default; + virtual ~ProfileListener() noexcept; /** * @brief A callback function to be called from a profiler @@ -76,7 +84,7 @@ public: * @param event event key to store the result * @param value time value from the profiler */ - virtual void onNotify(const EVENT event, + virtual void onNotify(const int event, const std::chrono::milliseconds &value) = 0; /** @@ -84,7 +92,7 @@ public: * * @param event event which profiler should notice */ - virtual void reset(const EVENT event) = 0; + virtual void reset(const int event) = 0; /** * @brief get the latest result of a event @@ -92,7 +100,7 @@ public: * @param event event to query the result * @return const std::chrono::milliseconds */ - virtual const std::chrono::milliseconds result(const EVENT event) = 0; + virtual const std::chrono::milliseconds result(const int event) = 0; /** * @brief report the result @@ -100,11 +108,29 @@ public: * @param out outstream object to make a report */ virtual void report(std::ostream &out) const = 0; + +private: + Profiler *profiler; }; class GenericProfileListener : public ProfileListener { public: /** + * @brief Construct a new GenericProfile Listener object + * + * @param profiler profiler that this listener is bound to. pass null if empty + * @param warmups_ ignore first @a warmups_ records when making report + */ + GenericProfileListener(Profiler *profiler, std::vector events = {}, + int warmups_ = 0) : + ProfileListener(profiler, events), + warmups(warmups_) { + for (auto &event : events) { + reset(event); + } + } + + /** * @brief Destroy the Generic Profile Listener object * */ @@ -115,25 +141,40 @@ public: * std::chrono::milliseconds &value) */ virtual void onNotify(const int event, - const std::chrono::milliseconds &value); + const std::chrono::milliseconds &value) override; /** * @copydoc ProfileListener::reset(const int event) */ - virtual void reset(const int event); + virtual void reset(const int event) override; /** * @copydoc ProfileListener::result(const int event) */ - virtual const std::chrono::milliseconds result(const int event); + virtual const std::chrono::milliseconds result(const int event) override; /** * @copydoc ProfileListener::report(std::ostream &out) */ - virtual void report(std::ostream &out) const; + virtual void report(std::ostream &out) const override; private: - std::unordered_map time_taken; + unsigned int warmups; + + static constexpr int CUR = 0; + static constexpr int MIN = 1; + static constexpr int MAX = 2; + static constexpr int SUM = 3; + static constexpr int CNT = 4; + + std::unordered_map> + time_taken; + + decltype(time_taken)::iterator time_iter; /**< iterator for the time_taken */ }; /** @@ -169,7 +210,7 @@ public: * @param key to record the profile result. Either designated key from enum * or arbitrary key can be used */ - void start(const EVENT &key); + void start(const int &key); /** * @brief end profile and notify to the listeners @@ -177,18 +218,26 @@ public: * @param key to record the profile result. Either designated key from enum * or arbitrary key can be used */ - void end(const EVENT &key); + void end(const int &key); /** - * @brief subscribe a listner to the profiler + * @brief subscribe a listener to the profiler * - * @param listener listener to register, listener must outlive lifetime of - * profiler + * @param listener listener to register, listener must call unsubscribe on + * destruction * @param events event listeners are subscribing, if empty listener subscribes * to all events + * @throw std::invalid_argument if listener is already registered */ void subscribe(ProfileListener *listener, - const std::vector &events = {}); + const std::vector &events = {}); + + /** + * @brief unsubscribe a listener from the profiler + * + * @param listener listener to unsubscribe + */ + void unsubscribe(ProfileListener *listener); private: /** @@ -197,16 +246,22 @@ private: * @param event event to notify * @param value measured value from the profiler */ - void notify(const EVENT &event, const std::chrono::milliseconds &value); + void notify(const int &event, const std::chrono::milliseconds &value); - std::vector - all_event_listeners; /**< listeners subscribed to all events */ + std::unordered_set + all_registered_listeners; /**< prevent registering listener twice */ - std::unordered_map> + std::unordered_set + all_event_listeners; /**< listeners listen to every events */ + + std::unordered_map> event_listeners; /**< listeners for an events */ - std::unordered_map> + std::unordered_map> start_time; /**< start_time of the clock */ + + std::mutex subscription_mutex; /**< protect sub/unsub routine to + gaurantee invarient */ }; } // namespace profile diff --git a/test/unittest/unittest_nntrainer_profiler.cpp b/test/unittest/unittest_nntrainer_profiler.cpp index 416b7a9..0e40da9 100644 --- a/test/unittest/unittest_nntrainer_profiler.cpp +++ b/test/unittest/unittest_nntrainer_profiler.cpp @@ -22,22 +22,24 @@ using namespace nntrainer::profile; class MockProfileListener : public ProfileListener { public: - MockProfileListener() : hit(false){}; + MockProfileListener(Profiler *profiler, std::vector events = {}) : + ProfileListener(profiler, events), + hit(false){}; ~MockProfileListener(){}; - void onNotify(const EVENT event, + void onNotify(const int event, const std::chrono::milliseconds &value) override { hit = true; } - void reset(const EVENT event) override { hit = false; } + void reset(const int event) override { hit = false; } void report(std::ostream &out) const override { out << (hit ? "hit" : "no hit"); } - const std::chrono::milliseconds result(const EVENT event) override { + const std::chrono::milliseconds result(const int event) override { return std::chrono::milliseconds(); }; @@ -45,16 +47,34 @@ private: bool hit; /**< check if onNotify has been called */ }; +TEST(GenericProfileListener, listenerBasicScenario_p) { + + GenericProfileListener listener{nullptr}; + + /// assuming library-side code is calling onNotify + listener.onNotify(EVENT::NN_FORWARD, std::chrono::milliseconds{10}); + listener.onNotify(EVENT::NN_FORWARD, std::chrono::milliseconds{100}); + listener.onNotify(EVENT::NN_FORWARD, std::chrono::milliseconds{50}); + + auto result = listener.result(EVENT::NN_FORWARD); + EXPECT_EQ(result, std::chrono::milliseconds{50}); + + std::cout << listener; +} + +TEST(GenericProfileListener, noResultButQueryResult_n) { + GenericProfileListener listener{nullptr}; + EXPECT_THROW(listener.result(EVENT::NN_FORWARD), std::invalid_argument); +} + TEST(Profiler, profilePositiveTests_p) { /// Initiate and run Profile Profiler prof; /// subscribe listener - std::unique_ptr all_listener(new MockProfileListener); - std::unique_ptr event_listener(new MockProfileListener); - - prof.subscribe(all_listener.get()); - prof.subscribe(event_listener.get(), {EVENT::NN_FORWARD}); + std::unique_ptr all_listener(new MockProfileListener{&prof}); + std::unique_ptr event_listener( + new MockProfileListener{&prof, {EVENT::NN_FORWARD}}); /// measure prof.start(EVENT::NN_FORWARD); @@ -86,32 +106,72 @@ TEST(Profiler, profilePositiveTests_p) { event_listener->report(ss); EXPECT_EQ(ss.str(), "no hit"); } + + /// unsubscribe event_listener + event_listener->reset(EVENT::NN_FORWARD); + prof.unsubscribe(event_listener.get()); + prof.start(EVENT::NN_FORWARD); + prof.end(EVENT::NN_FORWARD); + + { + std::stringstream ss; + event_listener->report(ss); + EXPECT_EQ(ss.str(), "no hit"); + } } TEST(Profiler, cannotStartTwice_n) { Profiler prof; prof.start(EVENT::NN_FORWARD); +#ifdef DEBUG EXPECT_THROW(prof.start(EVENT::NN_FORWARD), std::invalid_argument); +#endif +} + +TEST(Profiler, endThatNeverStarted_n) { + Profiler prof; +#ifdef DEBUG + EXPECT_THROW(prof.end(EVENT::NN_FORWARD), std::invalid_argument); +#endif } TEST(Profiler, cannotEndTwice_n) { Profiler prof; + prof.start(EVENT::NN_FORWARD); prof.end(EVENT::NN_FORWARD); +#ifdef DEBUG EXPECT_THROW(prof.end(EVENT::NN_FORWARD), std::invalid_argument); +#endif } TEST(Profiler, subscribeNullListener_n) { Profiler prof; - prof.subscribe(nullptr); + EXPECT_THROW(prof.subscribe(nullptr), std::invalid_argument); } TEST(Profiler, subscribeNullListener2_n) { Profiler prof; - prof.subscribe(nullptr, {EVENT::NN_FORWARD}); + EXPECT_THROW(prof.subscribe(nullptr, {EVENT::NN_FORWARD}), + std::invalid_argument); +} + +TEST(Profiler, subscribeAllTwice_n) { + Profiler prof; + std::unique_ptr all_listener(new MockProfileListener{&prof}); + + EXPECT_THROW(prof.subscribe(all_listener.get()), std::invalid_argument); +} + +TEST(Profiler, subscribePartialTwice_n) { + Profiler prof; + std::unique_ptr all_listener(new MockProfileListener{&prof}); + + EXPECT_THROW(prof.subscribe(all_listener.get(), {EVENT::NN_FORWARD}), + std::invalid_argument); } /** -- 2.7.4