diff --git a/lite/core/profile/basic_profiler.cc b/lite/core/profile/basic_profiler.cc index 5f2ffad78740237b0a2311fc8e6e3a127418c157..b1e8ddf011a7bdedc0e7434860711ac0185fb2e0 100644 --- a/lite/core/profile/basic_profiler.cc +++ b/lite/core/profile/basic_profiler.cc @@ -13,6 +13,8 @@ // limitations under the License. #include "lite/core/profile/basic_profiler.h" +#include +#include DEFINE_string(time_profile_file, "time_profile.txt", @@ -22,15 +24,181 @@ DEFINE_string(time_profile_summary_file, "time_profile_summary.txt", "Lite time profile summary information dump file"); +DEFINE_string(time_profile_unit, + "ms", + "Unit of time in profile infomation, ms or us"); + namespace paddle { namespace lite { namespace profile { +static std::string GetTimeUnit() { + auto time_unit = FLAGS_time_profile_unit; + if (time_unit != "ms" && time_unit != "us") { + LOG(FATAL) << "Profile time unit only support ms or us now"; + } + return time_unit; +} + const int BasicTimer::data_w = 10; const int BasicTimer::name_w = 15; +void BasicTimer::Start(const std::string& timer_key) { + TimerInfo& timer_info = timer_infos_[timer_key]; + timer_info.timer_ = static_cast( + std::chrono::duration_cast( + std::chrono::system_clock::now().time_since_epoch()) + .count()); +} + +void BasicTimer::Stop(const std::string& timer_key) { + if (timer_infos_.find(timer_key) == timer_infos_.end()) { + LOG(FATAL) << "Error: Can't found timer key [" << timer_key << "] for " + << key_; + } + TimerInfo& timer_info = timer_infos_[timer_key]; + auto duration = static_cast< + uint64_t>( // timer unit: microsecond, 1second = 1e6 microsecond + std::chrono::duration_cast( + std::chrono::system_clock::now().time_since_epoch()) + .count() - + timer_info.timer_); + Log(&timer_info, duration); +} + +void BasicTimer::SetCustomInfo(const std::string& key, + const std::string& value) { + if (custom_infos_.find(key) != custom_infos_.end()) { + LOG(FATAL) << "Error: Custom Info for key [" << key + << "] can't be overwritten"; + } + custom_infos_[key] = value; +} + +std::string BasicTimer::GetCustomInfo(const std::string& key) const { + auto iter = custom_infos_.find(key); + if (iter == custom_infos_.end()) { + LOG(FATAL) << "Error: Custom Info for key [" << key << "] can't be found"; + } + return iter->second; +} + +const TimerInfo& BasicTimer::GetTimerInfo(const std::string& key) const { + auto iter = timer_infos_.find(key); + if (iter == timer_infos_.end()) { + LOG(FATAL) << "Error: Timer Info for key [" << key << "] can't be found"; + } + return iter->second; +} + +void BasicTimer::Log(TimerInfo* timer_info, uint32_t timespan) { + CHECK(timer_info); + timer_info->total_ += timespan; + timer_info->max_ = std::max(timer_info->max_, timespan); + timer_info->min_ = std::min(timer_info->min_, timespan); + timer_info->count_++; +} + +std::string BasicTimer::basic_repr_header() { + auto time_unit = GetTimeUnit(); + STL::stringstream ss; + // clang-format off + ss << "op" << "\t" + << "kernel" << "\t" + << "k_average(" << time_unit << ")\t" + << "k_min(" << time_unit << ")\t" + << "k_max(" << time_unit << ")\t" + << "i_average(" << time_unit << ")\t" + << "i_min(" << time_unit << ")\t" + << "i_max(" << time_unit << ")\t" + << "count" << "\t" + << "op_info"; + // clang-format on + return ss.str(); +} + +std::string BasicTimer::basic_repr() const { + auto& kernel_timer_info = GetTimerInfo("kernel"); + auto& inst_timer_info = GetTimerInfo("instruction"); + float time_unit_factor = 1.; + if (GetTimeUnit() == "ms") { + time_unit_factor = 1000.; + } + STL::stringstream ss; + // clang-format off + ss << GetCustomInfo("op_type") << "\t" + << key() << "\t" + << kernel_timer_info.ave() / time_unit_factor << "\t" + << kernel_timer_info.min() / time_unit_factor << "\t" + << kernel_timer_info.max() / time_unit_factor << "\t" + << inst_timer_info.ave() / time_unit_factor << "\t" + << inst_timer_info.min() / time_unit_factor << "\t" + << inst_timer_info.max() / time_unit_factor << "\t" + << inst_timer_info.count() << "\t" + << GetCustomInfo("op_info"); + // clang-format on + return ss.str(); +} + template class BasicProfiler; +template +std::string BasicProfiler::summary_repr_header() const { + auto time_unit = GetTimeUnit(); + STL::stringstream ss; + // clang-format off + ss << "op" << "\t" + << "average(" << time_unit << ")\t" + << "min(" << time_unit << ")\t" + << "max(" << time_unit << ")\t" + << "op_time(" << time_unit << ")\t" + << "total_time(" << time_unit << ")\t" + << "precent" << "\t" + << "count"; + // clang-format on + return ss.str(); +} + +template +std::string BasicProfiler::summary_repr() const { + std::map op_summary; + uint64_t total{0}; + + for (const auto& rcd : records_) { + // We use kernel run time here + auto kernel_timer = rcd.GetTimerInfo("kernel"); + auto op_type = rcd.GetCustomInfo("op_type"); + auto& op_timer = op_summary[op_type]; + + total += kernel_timer.total_; + op_timer.total_ += kernel_timer.total_; + op_timer.max_ = std::max(kernel_timer.max_, op_timer.max_); + op_timer.min_ = std::min(kernel_timer.min_, op_timer.min_); + op_timer.count_ += kernel_timer.count_; + } + + float time_unit_factor = 1.; + if (GetTimeUnit() == "ms") { + time_unit_factor = 1000.; + } + STL::stringstream ss; + for (auto& iter : op_summary) { + auto& op_timer = iter.second; + // clang-format off + ss << iter.first << "\t" + << op_timer.ave() / time_unit_factor << "\t" + << op_timer.min() / time_unit_factor << "\t" + << op_timer.max() / time_unit_factor << "\t" + << op_timer.total() / time_unit_factor << "\t" + << total / time_unit_factor << "\t" + << (op_timer.total() * 1. / total * 100) << "%\t" + << op_timer.count() << "\t" + << "\n"; + // clang-format on + } + return ss.str(); +} + template BasicProfiler::~BasicProfiler() { LOG(INFO) << "Basic Profile dumps:"; diff --git a/lite/core/profile/basic_profiler.h b/lite/core/profile/basic_profiler.h index 3ae6e1f15967c18ebe03883994129d64863806a6..7981b2b8c3c6f11ddc12bed8f60baa60c16d032b 100644 --- a/lite/core/profile/basic_profiler.h +++ b/lite/core/profile/basic_profiler.h @@ -88,103 +88,27 @@ class BasicTimer : TimerBase { BasicTimer(int id, const std::string& key) : id_(id), key_(key) {} void SetId(int id) { id_ = id; } - void SetKey(const std::string& key) { key_ = key; } - void Start(const std::string& timer_key) { - TimerInfo& timer_info = timer_infos_[timer_key]; - timer_info.timer_ = static_cast( - std::chrono::duration_cast( - std::chrono::system_clock::now().time_since_epoch()) - .count()); - } - void Stop(const std::string& timer_key) { - if (timer_infos_.find(timer_key) == timer_infos_.end()) { - LOG(FATAL) << "Error: Can't found timer key [" << timer_key << "] for " - << key_; - } - TimerInfo& timer_info = timer_infos_[timer_key]; - auto duration = static_cast< - uint64_t>( // timer unit: microsecond, 1second = 1e6 microsecond - std::chrono::duration_cast( - std::chrono::system_clock::now().time_since_epoch()) - .count() - - timer_info.timer_); - Log(&timer_info, duration); - } - - void SetCustomInfo(const std::string& key, const std::string& value) { - if (custom_infos_.find(key) != custom_infos_.end()) { - LOG(FATAL) << "Error: Custom Info for key [" << key - << "] can't be overwritten"; - } - custom_infos_[key] = value; - } - std::string GetCustomInfo(const std::string& key) const { - auto iter = custom_infos_.find(key); - if (iter == custom_infos_.end()) { - LOG(FATAL) << "Error: Custom Info for key [" << key << "] can't be found"; - } - return iter->second; + int id() const { + CHECK_GE(id_, 0) << "id is not inited"; + return id_; } - const TimerInfo& GetTimerInfo(const std::string& key) const { - auto iter = timer_infos_.find(key); - if (iter == timer_infos_.end()) { - LOG(FATAL) << "Error: Timer Info for key [" << key << "] can't be found"; - } - return iter->second; - } + void SetKey(const std::string& key) { key_ = key; } + const std::string& key() const { return key_; } - void Log(TimerInfo* timer_info, uint32_t timespan) { - CHECK(timer_info); - timer_info->total_ += timespan; - timer_info->max_ = std::max(timer_info->max_, timespan); - timer_info->min_ = std::min(timer_info->min_, timespan); - timer_info->count_++; - } + void Start(const std::string& timer_key); + void Stop(const std::string& timer_key); - static std::string basic_repr_header() { - STL::stringstream ss; - // clang-format off - ss << "op" << "\t" - << "kernel" << "\t" - << "k_average" << "\t" - << "k_min" << "\t" - << "k_max" << "\t" - << "i_average" << "\t" - << "i_min" << "\t" - << "i_max" << "\t" - << "count" << "\t" - << "op_info"; - // clang-format on - return ss.str(); - } + void Log(TimerInfo* timer_info, uint32_t timespan); - std::string basic_repr() const { - auto& kernel_timer_info = GetTimerInfo("kernel"); - auto& inst_timer_info = GetTimerInfo("instruction"); - STL::stringstream ss; - // clang-format off - ss << GetCustomInfo("op_type") << "\t" - << key() << "\t" - << kernel_timer_info.ave() << "\t" - << kernel_timer_info.min() << "\t" - << kernel_timer_info.max() << "\t" - << inst_timer_info.ave() << "\t" - << inst_timer_info.min() << "\t" - << inst_timer_info.max() << "\t" - << inst_timer_info.count() << "\t" - << GetCustomInfo("op_info"); - // clang-format on - return ss.str(); - } + void SetCustomInfo(const std::string& key, const std::string& value); + std::string GetCustomInfo(const std::string& key) const; - const std::string& key() const { return key_; } + const TimerInfo& GetTimerInfo(const std::string& key) const; - int id() const { - CHECK_GE(id_, 0) << "id is not inited"; - return id_; - } + static std::string basic_repr_header(); + std::string basic_repr() const; // BasicRecord(const BasicRecord &) = delete; void operator=(const BasicTimer&) = delete; @@ -231,55 +155,8 @@ class BasicProfiler { return ss.str(); } - std::string summary_repr_header() const { - STL::stringstream ss; - // clang-format off - ss << "op" << "\t" - << "average" << "\t" - << "min" << "\t" - << "max" << "\t" - << "op_time" << "\t" - << "total_time" << "\t" - << "precent" << "\t" - << "count"; - // clang-format on - return ss.str(); - } - - std::string summary_repr() const { - std::map op_summary; - uint64_t total{0}; - - for (const auto& rcd : records_) { - // We use kernel run time here - auto kernel_timer = rcd.GetTimerInfo("kernel"); - auto op_type = rcd.GetCustomInfo("op_type"); - auto& op_timer = op_summary[op_type]; - - total += kernel_timer.total_; - op_timer.total_ += kernel_timer.total_; - op_timer.max_ = std::max(kernel_timer.max_, op_timer.max_); - op_timer.min_ = std::min(kernel_timer.min_, op_timer.min_); - op_timer.count_ += kernel_timer.count_; - } - - STL::stringstream ss; - for (auto& iter : op_summary) { - auto& op_timer = iter.second; - // clang-format off - ss << iter.first << "\t" - << op_timer.ave() << "\t" - << op_timer.min() << "\t" - << op_timer.max() << "\t" - << op_timer.total() << "\t" - << total << "\t" - << (op_timer.total() * 1. / total * 100) << "%\t" - << op_timer.count() << "\t" - << "\n"; - // clang-format on - } - return ss.str(); - } + std::string summary_repr_header() const; + std::string summary_repr() const; ~BasicProfiler();