From 1650212a91d4583d4974ebd327806861901e0b68 Mon Sep 17 00:00:00 2001
From: sangoly <sangoly@aliyun.com>
Date: Wed, 6 Nov 2019 13:31:19 +0800
Subject: [PATCH] [profile] fix profile count bug & exclude warmup profile
 monitor test=develop (#2374)

---
 lite/api/model_test.cc              |  7 +++++++
 lite/core/kernel.h                  |  4 +++-
 lite/core/profile/basic_profiler.cc | 13 +++++++++++--
 lite/core/profile/basic_profiler.h  | 28 +++++++++++++++++++++-------
 4 files changed, 42 insertions(+), 10 deletions(-)

diff --git a/lite/api/model_test.cc b/lite/api/model_test.cc
index 14fecaad3a..1358267000 100644
--- a/lite/api/model_test.cc
+++ b/lite/api/model_test.cc
@@ -24,6 +24,9 @@
 #include "lite/tests/utils/timer.h"
 #include "lite/utils/cp_logging.h"
 #include "lite/utils/string.h"
+#ifdef LITE_WITH_PROFILE
+#include "lite/core/profile/basic_profiler.h"
+#endif  // LITE_WITH_PROFILE
 
 using paddle::lite::Timer;
 
@@ -69,6 +72,10 @@ void Run(const std::vector<std::vector<int64_t>>& input_shapes,
          const int thread_num,
          const int repeat,
          const int warmup_times = 0) {
+#ifdef LITE_WITH_PROFILE
+  lite::profile::BasicProfiler<lite::profile::BasicTimer>::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/kernel.h b/lite/core/kernel.h
index 176f6c69ac..05d7a6b333 100644
--- a/lite/core/kernel.h
+++ b/lite/core/kernel.h
@@ -84,9 +84,11 @@ class KernelBase {
 #ifdef LITE_WITH_PROFILE
     if (profile_id_ >= 0) {
       profile::ProfileBlock x(profile_id_, "kernel");
+      Run();
     }
-#endif
+#else
     Run();
+#endif
   }
 
   void SetContext(std::unique_ptr<KernelContext>&& ctx) {
diff --git a/lite/core/profile/basic_profiler.cc b/lite/core/profile/basic_profiler.cc
index b1e8ddf011..a947bfa295 100644
--- a/lite/core/profile/basic_profiler.cc
+++ b/lite/core/profile/basic_profiler.cc
@@ -91,12 +91,21 @@ const TimerInfo& BasicTimer::GetTimerInfo(const std::string& key) const {
   return iter->second;
 }
 
-void BasicTimer::Log(TimerInfo* timer_info, uint32_t timespan) {
+void BasicTimer::SetWarmup(int warmup_times) {
+  CHECK_GE(warmup_times, 0) << "warmup times must >= 0";
+  warmup_ = warmup_times;
+}
+
+void BasicTimer::Log(TimerInfo* timer_info, uint64_t timespan) {
+  if (warmup_ > 0) {
+    --warmup_;
+    return;
+  }
   CHECK(timer_info);
+  timer_info->count_++;
   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() {
diff --git a/lite/core/profile/basic_profiler.h b/lite/core/profile/basic_profiler.h
index 7981b2b8c3..660650655e 100644
--- a/lite/core/profile/basic_profiler.h
+++ b/lite/core/profile/basic_profiler.h
@@ -37,11 +37,11 @@ namespace lite {
 namespace profile {
 
 struct TimerInfo {
-  uint64_t total_{};
-  uint64_t count_{};
-  uint32_t max_{std::numeric_limits<uint32_t>::min()};
-  uint32_t min_{std::numeric_limits<uint32_t>::max()};
-  uint64_t timer_{};
+  uint64_t total_{0};
+  uint64_t count_{0};
+  uint64_t max_{std::numeric_limits<uint64_t>::min()};
+  uint64_t min_{std::numeric_limits<uint64_t>::max()};
+  uint64_t timer_{0};
 
   double ave() const { return total_ * 1. / count_; }
   double max() const { return max_; }
@@ -56,7 +56,7 @@ class TimerBase {
  public:
   void Start(const std::string& key) { self()->Start(key); }
   void Stop(const std::string& key) { self()->Stop(key); }
-  void Log(TimerInfo* timer_info, uint32_t x) {
+  void Log(TimerInfo* timer_info, uint64_t x) {
     return self()->Log(timer_info, x);
   }
   std::string basic_repr() const { return const_self()->basic_repr(); }
@@ -75,6 +75,7 @@ class TimerBase {
 
 class BasicTimer : TimerBase<BasicTimer> {
   int id_{-1};
+  int warmup_{0};
   std::string key_;
   std::map<std::string, TimerInfo> timer_infos_;
   std::map<std::string, std::string> custom_infos_;
@@ -100,7 +101,7 @@ class BasicTimer : TimerBase<BasicTimer> {
   void Start(const std::string& timer_key);
   void Stop(const std::string& timer_key);
 
-  void Log(TimerInfo* timer_info, uint32_t timespan);
+  void Log(TimerInfo* timer_info, uint64_t timespan);
 
   void SetCustomInfo(const std::string& key, const std::string& value);
   std::string GetCustomInfo(const std::string& key) const;
@@ -112,6 +113,8 @@ class BasicTimer : TimerBase<BasicTimer> {
 
   // BasicRecord(const BasicRecord &) = delete;
   void operator=(const BasicTimer&) = delete;
+
+  void SetWarmup(int warmup_times);
 };
 
 /*
@@ -132,6 +135,7 @@ class BasicProfiler {
     records_.emplace_back();
     records_.back().SetId(records_.size() - 1);
     records_.back().SetKey(key);
+    records_.back().SetWarmup(warmup_);
     return records_.back();
   }
 
@@ -158,11 +162,21 @@ class BasicProfiler {
   std::string summary_repr_header() const;
   std::string summary_repr() const;
 
+  void SetWarmup(int warmup_times) {
+    CHECK_GE(warmup_times, 0) << "warmup times must >= 0";
+    // Instruction and kernel share the common BasicTimer instance, so the
+    // warmup count
+    // will be decrease twice when instruction execute once
+    // TODO(sangoly): fix the ugly code.
+    warmup_ = warmup_times * 2;
+  }
+
   ~BasicProfiler();
 
  private:
   std::string name_;
   std::vector<record_t> records_;
+  int warmup_{0};
 };
 
 struct ProfileBlock {
-- 
GitLab