From af37a14f92dddde309b66a599b3bbd30b9749967 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E7=9F=B3=E6=99=93=E4=BC=9F?= <39303645+Shixiaowei02@users.noreply.github.com> Date: Mon, 16 Dec 2019 10:21:43 +0800 Subject: [PATCH] update profiler, test=develop (#2607) * update profiler, test=develop * warm up times of profiler, test=develop --- lite/api/model_test.cc | 4 -- lite/core/profile/profiler.cc | 86 ++++++++++++++++++++--------------- lite/core/profile/profiler.h | 2 +- lite/core/profile/timer.h | 48 ++++++++++++++----- lite/core/program.cc | 2 +- lite/core/program.h | 5 ++ 6 files changed, 93 insertions(+), 54 deletions(-) diff --git a/lite/api/model_test.cc b/lite/api/model_test.cc index a04e86b7d2..cf5fa4981a 100644 --- a/lite/api/model_test.cc +++ b/lite/api/model_test.cc @@ -72,10 +72,6 @@ void Run(const std::vector>& input_shapes, const int thread_num, const int repeat, const int warmup_times = 0) { -#ifdef LITE_WITH_PROFILE - lite::profile::BasicProfiler::Global().SetWarmup( - warmup_times); -#endif lite_api::MobileConfig config; config.set_model_dir(model_dir); config.set_power_mode(power_mode); diff --git a/lite/core/profile/profiler.cc b/lite/core/profile/profiler.cc index a51b769c8f..78317f78ac 100644 --- a/lite/core/profile/profiler.cc +++ b/lite/core/profile/profiler.cc @@ -21,6 +21,13 @@ namespace paddle { namespace lite { namespace profile { +namespace { +auto op_comp = [](const OpCharacter& c1, const OpCharacter& c2) { + return (c1.target < c2.target) || (c1.op_type < c2.op_type) || + (c1.kernel_name < c2.kernel_name) || (c1.remark < c2.remark); +}; +} + int Profiler::NewTimer(const OpCharacter& ch) { StatisUnit unit; unit.character = ch; @@ -50,61 +57,66 @@ float Profiler::StopTiming(const int index, KernelContext* ctx) { return units_[index].timer->Stop(ctx); } -std::string Profiler::Summary(bool concise) { +std::string Profiler::Summary(bool concise, size_t w) { + using std::setw; + using std::left; + using std::fixed; STL::stringstream ss; - auto cout_title = [&ss](const std::string& title, const std::string& name) { - // clang-format off - ss << "===== " << title << ": " << name << " =====" << std::endl; - ss << std::setw(25) << std::left << "Operator Type" \ - << std::setw(40) << std::left << "Kernel Name" \ - << std::setw(10) << std::left << "Remark" \ - << std::setw(10) << std::left << "Avg (ms)" \ - << std::setw(10) << std::left << "Min (ms)" \ - << std::setw(10) << std::left << "Max (ms)" \ + std::string title; + // Title. + if (concise) { + ss << "Timing cycle = " << units_.front().timer->LapTimes().Size() << std::endl; - // clang-format on - }; + ss << "===== Concise Profiler Summary: " << name_ << ", Exclude " << w + << " warm-ups =====" << std::endl; + } else { + ss << "===== Detailed Profiler Summary: " << name_ << ", Exclude " << w + << " warm-ups =====" << std::endl; + } + ss << setw(25) << left << "Operator Type" + << " " << setw(40) << left << "Kernel Name" + << " " << setw(12) << left << "Remark" + << " " << setw(12) << left << "Avg (ms)" + << " " << setw(12) << left << "Min (ms)" + << " " << setw(12) << left << "Max (ms)" + << " " << setw(12) << left << "Last (ms)" << std::endl; + // Profile information. if (concise) { - auto op_comp = [](const OpCharacter& c1, const OpCharacter& c2) { - return (c1.target < c2.target) || (c1.op_type < c2.op_type) || - (c1.kernel_name < c2.kernel_name) || (c1.remark < c2.remark); - }; std::map summary(op_comp); for (auto& unit : units_) { auto ch = summary.find(unit.character); if (ch != summary.end()) { - ch->second.avg += unit.timer->LapTimes().Avg(); - ch->second.min += unit.timer->LapTimes().Min(); - ch->second.max += unit.timer->LapTimes().Max(); + ch->second.avg += unit.timer->LapTimes().Avg(w); + ch->second.min += unit.timer->LapTimes().Min(w); + ch->second.max += unit.timer->LapTimes().Max(w); } else { - TimeInfo info({unit.timer->LapTimes().Avg(), - unit.timer->LapTimes().Min(), - unit.timer->LapTimes().Max()}); + TimeInfo info({unit.timer->LapTimes().Avg(w), + unit.timer->LapTimes().Min(w), + unit.timer->LapTimes().Max(w)}); summary.insert({unit.character, info}); } } - cout_title("Concise Profiler Summary", name_); for (const auto& item : summary) { // clang-format off - ss << std::setw(25) << std::left << item.first.op_type \ - << std::setw(40) << std::left << item.first.kernel_name \ - << std::setw(10) << std::left << item.first.remark \ - << std::setw(10) << std::left << item.second.avg \ - << std::setw(10) << std::left << item.second.min \ - << std::setw(10) << std::left << item.second.max \ - << std::endl; + ss << setw(25) << left << fixed << item.first.op_type \ + << " " << setw(40) << left << fixed << item.first.kernel_name \ + << " " << setw(12) << left << fixed << item.first.remark \ + << " " << setw(12) << left << fixed << item.second.avg \ + << " " << setw(12) << left << fixed << item.second.min \ + << " " << setw(12) << left << fixed << item.second.max \ + << " " << std::endl; // clang-format on } } else { - cout_title("Detailed Profiler Summary", name_); for (auto& unit : units_) { // clang-format off - ss << std::setw(25) << std::left << unit.character.op_type \ - << std::setw(40) << std::left << unit.character.kernel_name \ - << std::setw(10) << std::left << unit.character.remark \ - << std::setw(10) << std::left << unit.timer->LapTimes().Avg() \ - << std::setw(10) << std::left << unit.timer->LapTimes().Min() \ - << std::setw(10) << std::left << unit.timer->LapTimes().Max() \ + ss << setw(25) << left << fixed << unit.character.op_type \ + << " " << setw(40) << left << fixed << unit.character.kernel_name \ + << " " << setw(12) << left << fixed << unit.character.remark \ + << " " << setw(12) << left << fixed << unit.timer->LapTimes().Avg(w) \ + << " " << setw(12) << left << fixed << unit.timer->LapTimes().Min(w) \ + << " " << setw(12) << left << fixed << unit.timer->LapTimes().Max(w) \ + << " " << setw(12) << left << fixed << unit.timer->LapTimes().Last(w) \ << std::endl; // clang-format on } diff --git a/lite/core/profile/profiler.h b/lite/core/profile/profiler.h index 0fce8167cd..4e9e9ae31c 100644 --- a/lite/core/profile/profiler.h +++ b/lite/core/profile/profiler.h @@ -47,7 +47,7 @@ class Profiler final { int NewTimer(const OpCharacter& ch); void StartTiming(const int index, KernelContext* ctx); float StopTiming(const int index, KernelContext* ctx); - std::string Summary(bool concise = true); + std::string Summary(bool concise = true, size_t warm_up = 10); private: std::string name_{std::string("N/A")}; diff --git a/lite/core/profile/timer.h b/lite/core/profile/timer.h index 1e86f0d7b9..e9bb16bd27 100644 --- a/lite/core/profile/timer.h +++ b/lite/core/profile/timer.h @@ -15,7 +15,7 @@ #pragma once #include #include // NOLINT -#include +#include #ifdef LITE_WITH_CUDA #include "lite/backends/cuda/cuda_utils.h" #endif @@ -30,20 +30,44 @@ class TimeList { public: void Clear() { laps_t_.clear(); } void Add(T t) { laps_t_.push_back(t); } - T Max() const { return *std::max_element(laps_t_.begin(), laps_t_.end()); } - T Min() const { return *std::min_element(laps_t_.begin(), laps_t_.end()); } - T Sum() const { return std::accumulate(laps_t_.begin(), laps_t_.end(), 0.0); } - size_t Size() const { return laps_t_.size(); } - T Avg() const { - if (!Size()) { + T Last(size_t offset = 0) const { + if (!Size(offset)) { return 0; } - return Sum() / Size(); + return laps_t_.back(); } - const std::list& Raw() const { return laps_t_; } + T Max(size_t offset = 0) const { + if (!Size(offset)) { + return 0; + } + return *std::max_element((laps_t_.begin() + offset), laps_t_.end()); + } + T Min(size_t offset = 0) const { + if (!Size(offset)) { + return 0; + } + return *std::min_element((laps_t_.begin() + offset), laps_t_.end()); + } + T Sum(size_t offset = 0) const { + if (!Size(offset)) { + return 0; + } + return std::accumulate((laps_t_.begin() + offset), laps_t_.end(), 0.0); + } + size_t Size(size_t offset = 0) const { + size_t size = (laps_t_.size() <= offset) ? 0 : (laps_t_.size() - offset); + return size; + } + T Avg(size_t offset = 0) const { + if (!Size(offset)) { + return 0; + } + return Sum(offset) / Size(offset); + } + const std::vector& Raw() const { return laps_t_; } private: - std::list laps_t_; + std::vector laps_t_; }; class Timer { @@ -69,8 +93,10 @@ class Timer { const TimeList& LapTimes() const { return laps_t_; } protected: - std::chrono::time_point t_start_, t_stop_; TimeList laps_t_; + + private: + std::chrono::time_point t_start_, t_stop_; }; template diff --git a/lite/core/program.cc b/lite/core/program.cc index e646fad4a9..8e4c4f4297 100644 --- a/lite/core/program.cc +++ b/lite/core/program.cc @@ -147,7 +147,7 @@ void RuntimeProgram::Run() { #endif // LITE_WITH_PROFILE } #ifdef LITE_WITH_PROFILE - LOG(INFO) << "\n" << profiler_.Summary(); + LOG(INFO) << "\n" << profiler_.Summary(false, 0); #endif // LITE_WITH_PROFILE } diff --git a/lite/core/program.h b/lite/core/program.h index 9d3f8a97bc..291252619b 100644 --- a/lite/core/program.h +++ b/lite/core/program.h @@ -141,6 +141,11 @@ class LITE_API RuntimeProgram { set_profiler(); #endif } + ~RuntimeProgram() { +#ifdef LITE_WITH_PROFILE + LOG(INFO) << "\n" << profiler_.Summary(); +#endif // LITE_WITH_PROFILE + } void Run(); -- GitLab