add iterator_info stat for hot cache

mittest/logservice/test_ob_simple_log_cache.cpp

@@ -245,7 +245,7 @@ TEST_F(TestObSimpleLogCache, DISABLED_fill_cache_when_slide)
     PALF_LOG(INFO, "start to read log");
     EXPECT_EQ(OB_ITER_END, read_log(leader, iterator));
     // all hit cache, no read disk
-    EXPECT_EQ(0, iterator.io_ctx_.iterator_info_.miss_cnt_);
+    EXPECT_EQ(0, iterator.io_ctx_.iterator_info_.cold_cache_stat_.miss_cnt_);
   }
 
   {
@@ -269,7 +269,7 @@ TEST_F(TestObSimpleLogCache, DISABLED_fill_cache_when_slide)
 
     EXPECT_EQ(OB_ITER_END, read_log(leader, read_lsn, iterator));
     // miss, have to read disk at lease once
-    EXPECT_LT(0, iterator.io_ctx_.iterator_info_.miss_cnt_);
+    EXPECT_LT(0, iterator.io_ctx_.iterator_info_.cold_cache_stat_.miss_cnt_);
   }
 
 

src/logservice/palf/log_cache.cpp

@@ -956,6 +956,7 @@ int LogCache::read(const int64_t flashback_version,
                    LogIteratorInfo *iterator_info)
 {
   int ret = OB_SUCCESS;
+  const bool is_cold_cache = false;
   if (IS_NOT_INIT) {
     ret = OB_NOT_INIT;
     PALF_LOG(ERROR, "LogCache is not inited!", K(ret));
@@ -964,6 +965,9 @@ int LogCache::read(const int64_t flashback_version,
     PALF_LOG(WARN, "Invalid argument!!!", K(ret), K(lsn), K(in_read_size), K(read_buf));
   } else if (OB_SUCC(read_hot_cache_(lsn, in_read_size, read_buf.buf_, out_read_size))) {
     // read data from hot_cache successfully
+    iterator_info->inc_hit_cnt(is_cold_cache);
+    iterator_info->inc_cache_read_size(out_read_size, is_cold_cache);
+  } else if (FALSE_IT(iterator_info->inc_miss_cnt(is_cold_cache))) {
   } else if (OB_FAIL(read_cold_cache_(flashback_version, lsn, in_read_size,
                                       read_buf, out_read_size, iterator_info))) {
     PALF_LOG(WARN, "fail to read from cold cache", K(ret), K(lsn), K(in_read_size), K(read_buf), K(out_read_size));

src/logservice/palf/log_iterator_info.h

@@ -22,20 +22,18 @@ class LogIteratorInfo
 {
 public:
   LogIteratorInfo()
-      : allow_filling_cache_(true), hit_cnt_(0), miss_cnt_(0), cache_read_size_(0),
+      : allow_filling_cache_(true), hot_cache_stat_(), cold_cache_stat_(),
         read_io_cnt_(0), read_io_size_(0), read_disk_cost_ts_(0) {}
   LogIteratorInfo(bool allow_filling_cache)
-      : allow_filling_cache_(allow_filling_cache), hit_cnt_(0), miss_cnt_(0),
+      : allow_filling_cache_(allow_filling_cache), hot_cache_stat_(), cold_cache_stat_(),
-        cache_read_size_(0), read_io_cnt_(0), read_io_size_(0),
+        read_io_cnt_(0), read_io_size_(0), read_disk_cost_ts_(0) {}
-        read_disk_cost_ts_(0) {}
   ~LogIteratorInfo() {
     reset();
   }
   void reset() {
     allow_filling_cache_ = false;
-    hit_cnt_ = 0;
+    hot_cache_stat_.reset();
-    miss_cnt_ = 0;
+    cold_cache_stat_.reset();
-    cache_read_size_ = 0;
     read_io_cnt_ = 0;
     read_io_size_ = 0;
     read_disk_cost_ts_ = 0;
@@ -46,31 +44,66 @@ public:
   void set_allow_filling_cache(const bool allow_filling_cache) {
     allow_filling_cache_ = allow_filling_cache;
   }
-  void inc_hit_cnt() { hit_cnt_++; }
+  void inc_hit_cnt(const bool is_cold_cache = true) {
-  void inc_miss_cnt() { miss_cnt_++; }
+    if (is_cold_cache) {
-  void inc_cache_read_size(int64_t cache_read_size) { cache_read_size_ += cache_read_size; }
+      cold_cache_stat_.inc_hit_cnt();
+    } else {
+      hot_cache_stat_.inc_hit_cnt();
+    }
+  }
+  void inc_miss_cnt(const bool is_cold_cache = true) {
+    if (is_cold_cache) {
+      cold_cache_stat_.inc_miss_cnt();
+    } else {
+      hot_cache_stat_.inc_miss_cnt();
+    }
+  }
+  void inc_cache_read_size(int64_t cache_read_size, const bool is_cold_cache = true) {
+    if (is_cold_cache) {
+      cold_cache_stat_.inc_cache_read_size(cache_read_size);
+    } else {
+      hot_cache_stat_.inc_cache_read_size(cache_read_size);
+    }
+  }
   void inc_read_io_cnt() { read_io_cnt_++; }
   void inc_read_io_size(int64_t read_io_size) { read_io_size_ += read_io_size; }
   void inc_read_disk_cost_ts(int64_t read_disk_cost_ts) { read_disk_cost_ts_ += read_disk_cost_ts; }
-  double get_hit_ratio() const
-  {
-    int64_t total_cnt = (hit_cnt_ + miss_cnt_ == 0) ? 1 : hit_cnt_ + miss_cnt_;
-    return hit_cnt_ * 1.0 /total_cnt;
-  }
   void set_start_lsn(const LSN &start_lsn) { start_lsn_ = start_lsn; }
-  TO_STRING_KV(K(allow_filling_cache_), K(hit_cnt_), K(miss_cnt_),
+  TO_STRING_KV(K_(allow_filling_cache), K_(hot_cache_stat), K_(cold_cache_stat),
-               K(cache_read_size_), K(read_io_cnt_), K(read_io_size_),
+               K_(read_io_cnt), K_(read_io_size), K_(read_disk_cost_ts), K_(start_lsn));
-               K(read_disk_cost_ts_), "hit rate", get_hit_ratio(), K(start_lsn_));
 
+private:
+  class IteratorCacheStat
+  {
+  public:
+    IteratorCacheStat() : hit_cnt_(0), miss_cnt_(0), cache_read_size_(0) {}
+    ~IteratorCacheStat() { reset(); }
+    void reset() {
+      hit_cnt_ = 0;
+      miss_cnt_ = 0;
+      cache_read_size_ = 0;
+    }
+    void inc_hit_cnt() { hit_cnt_++; }
+    void inc_miss_cnt() { miss_cnt_++; }
+    void inc_cache_read_size(int64_t cache_read_size) { cache_read_size_ += cache_read_size; }
+    double get_hit_ratio() const
+    {
+      int64_t total_cnt = (hit_cnt_ + miss_cnt_ == 0) ? 1 : hit_cnt_ + miss_cnt_;
+      return hit_cnt_ * 1.0 /total_cnt;
+    }
+    TO_STRING_KV(K_(hit_cnt), K_(miss_cnt), K_(cache_read_size), "hit_ratio", get_hit_ratio());
+  private:
+    int64_t hit_cnt_;
+    int64_t miss_cnt_;
+    int64_t cache_read_size_;
+  };
 private:
   bool allow_filling_cache_;
-  int64_t hit_cnt_;
+  IteratorCacheStat hot_cache_stat_;
-  int64_t miss_cnt_;
+  IteratorCacheStat cold_cache_stat_;
-  int64_t cache_read_size_;
   int64_t read_io_cnt_;
   int64_t read_io_size_;
   int64_t read_disk_cost_ts_;
-  int64_t thread_id_;
   LSN start_lsn_;
 };
 }

src/logservice/palf/log_reader.cpp

@@ -18,6 +18,7 @@
 #include "log_define.h"                   // LOG_READ_FLAG
 #include "log_define.h"                   // LOG_DIO_ALIGN_SIZE...
 #include "log_reader_utils.h"             // ReadBuf
+#include "lib/stat/ob_session_stat.h"     // Session
 
 namespace oceanbase
 {
@@ -87,6 +88,7 @@ int LogReader::pread(const block_id_t block_id,
     ret = convert_sys_errno();
     PALF_LOG(WARN, "LogReader open block failed", K(ret), K(errno), K(block_path), K(read_io_fd));
   } else {
+    const int64_t start_ts = ObTimeUtility::fast_current_time();
     int64_t remained_read_size = in_read_size;
     int64_t remained_read_buf_len = read_buf.buf_len_;
     int64_t step = MAX_LOG_BUFFER_SIZE;
@@ -108,6 +110,25 @@ int LogReader::pread(const block_id_t block_id,
             K(remained_read_size), K(block_path));
       }
     }
+
+    if (OB_SUCC(ret)) {
+      const int64_t cost_ts = ObTimeUtility::fast_current_time() - start_ts;
+      iterator_info->inc_read_disk_cost_ts(cost_ts);
+      EVENT_TENANT_INC(ObStatEventIds::PALF_READ_IO_COUNT_FROM_DISK, MTL_ID());
+      EVENT_ADD(ObStatEventIds::PALF_READ_SIZE_FROM_DISK, out_read_size);
+      EVENT_ADD(ObStatEventIds::PALF_READ_TIME_FROM_DISK, cost_ts);
+      ATOMIC_INC(&accum_read_io_count_);
+      ATOMIC_AAF(&accum_read_log_size_, out_read_size);
+      ATOMIC_AAF(&accum_read_cost_ts_, cost_ts);
+      if (palf_reach_time_interval(PALF_IO_STAT_PRINT_INTERVAL_US, last_accum_read_statistic_time_)) {
+        const int64_t avg_pread_cost = accum_read_cost_ts_ / accum_read_io_count_;
+        PALF_LOG(INFO, "[PALF STAT READ LOG INFO FROM DISK]", K_(accum_read_io_count),
+                 K_(accum_read_log_size), K(avg_pread_cost));
+        ATOMIC_STORE(&accum_read_io_count_, 0);
+        ATOMIC_STORE(&accum_read_log_size_, 0);
+        ATOMIC_STORE(&accum_read_cost_ts_, 0);
+      }
+    }
   }
 
   if (-1 != read_io_fd && -1 == ::close(read_io_fd)) {