From ddb72b85c97ee751b9775383b3d5e17001cc02dd Mon Sep 17 00:00:00 2001 From: obdev Date: Thu, 27 Jun 2024 04:28:04 +0000 Subject: [PATCH] add iterator_info stat for hot cache --- .../logservice/test_ob_simple_log_cache.cpp | 4 +- src/logservice/palf/log_cache.cpp | 4 + src/logservice/palf/log_iterator_info.h | 77 +++++++++++++------ src/logservice/palf/log_reader.cpp | 21 +++++ 4 files changed, 82 insertions(+), 24 deletions(-) diff --git a/mittest/logservice/test_ob_simple_log_cache.cpp b/mittest/logservice/test_ob_simple_log_cache.cpp index 5de0dd44e..9559da16a 100644 --- a/mittest/logservice/test_ob_simple_log_cache.cpp +++ b/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_); } diff --git a/src/logservice/palf/log_cache.cpp b/src/logservice/palf/log_cache.cpp index 005fcba4e..009c88def 100644 --- a/src/logservice/palf/log_cache.cpp +++ b/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)); diff --git a/src/logservice/palf/log_iterator_info.h b/src/logservice/palf/log_iterator_info.h index 8e28ee3bd..44596fa37 100644 --- a/src/logservice/palf/log_iterator_info.h +++ b/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), - cache_read_size_(0), read_io_cnt_(0), read_io_size_(0), - read_disk_cost_ts_(0) {} + : allow_filling_cache_(allow_filling_cache), hot_cache_stat_(), cold_cache_stat_(), + read_io_cnt_(0), read_io_size_(0), read_disk_cost_ts_(0) {} ~LogIteratorInfo() { reset(); } void reset() { allow_filling_cache_ = false; - hit_cnt_ = 0; - miss_cnt_ = 0; - cache_read_size_ = 0; + hot_cache_stat_.reset(); + cold_cache_stat_.reset(); 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_miss_cnt() { miss_cnt_++; } - void inc_cache_read_size(int64_t cache_read_size) { cache_read_size_ += cache_read_size; } + void inc_hit_cnt(const bool is_cold_cache = true) { + if (is_cold_cache) { + 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_), - K(cache_read_size_), K(read_io_cnt_), K(read_io_size_), - K(read_disk_cost_ts_), "hit rate", get_hit_ratio(), K(start_lsn_)); + TO_STRING_KV(K_(allow_filling_cache), K_(hot_cache_stat), K_(cold_cache_stat), + K_(read_io_cnt), K_(read_io_size), K_(read_disk_cost_ts), 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_; - int64_t miss_cnt_; - int64_t cache_read_size_; + IteratorCacheStat hot_cache_stat_; + IteratorCacheStat cold_cache_stat_; int64_t read_io_cnt_; int64_t read_io_size_; int64_t read_disk_cost_ts_; - int64_t thread_id_; LSN start_lsn_; }; } diff --git a/src/logservice/palf/log_reader.cpp b/src/logservice/palf/log_reader.cpp index 5caa714b7..860bc1087 100644 --- a/src/logservice/palf/log_reader.cpp +++ b/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)) {