Add some logs and defend codes

src/storage/access/ob_index_tree_prefetcher.cpp

@@ -47,13 +47,13 @@ void ObIndexTreePrefetcher::reclaim()
 
 void ObIndexTreePrefetcher::inner_reset()
 {
-  is_rescan_ = false;
   iter_type_ = 0;
   cur_level_ = 0;
   index_tree_height_ = 0;
   max_rescan_height_ = 0;
   max_rescan_range_cnt_ = 0;
   data_version_ = 0;
+  table_scan_cnt_ = 0;
   sstable_ = nullptr;
   sstable_meta_handle_.reset();
   iter_param_ = nullptr;
@@ -99,8 +99,6 @@ int ObIndexTreePrefetcher::switch_context(
     LOG_WARN("not inited", K(ret));
   } else if (OB_FAIL(init_basic_info(iter_type, sstable, iter_param, access_ctx))) {
     LOG_WARN("Fail to init basic info", K(ret));
-  } else {
-    is_rescan_ = true;
   }
   return ret;
 }
@@ -118,6 +116,8 @@ int ObIndexTreePrefetcher::init_basic_info(
   } else if (OB_FAIL(iter_param.get_index_read_info(sstable.is_normal_cg_sstable(), index_read_info))) {
     LOG_WARN("failed to get index read info", KR(ret), K(sstable), K(iter_param));
   } else {
+    table_scan_cnt_++;
+    const bool first_scan = is_first_scan();
     iter_type_ = iter_type;
     cur_level_ = 0;
     sstable_ = &sstable;
@@ -133,9 +133,9 @@ int ObIndexTreePrefetcher::init_basic_info(
       ret = OB_INVALID_ARGUMENT;
       LOG_WARN("Unexpected null long life allocator", K(ret));
     } else if (index_scanner_.is_valid()) {
-      if (OB_ISNULL(iter_param_)) {
+      if (OB_UNLIKELY(first_scan)) {
-        ret = OB_INVALID_ARGUMENT;
+        ret = OB_ERR_UNEXPECTED;
-        LOG_WARN("invalid iter param", K(ret), KPC(iter_param_), K(lbt()));
+        LOG_WARN("Unexpected state, index_scanner_ is valid at first scan", K(ret), KPC(this), K(index_scanner_), K(iter_param), K(lbt()));
       } else {
         const ObTablet *cur_tablet = OB_ISNULL(iter_param_->tablet_handle_) ? nullptr : iter_param_->tablet_handle_->get_obj();
         index_scanner_.switch_context(sstable, cur_tablet, *datum_utils_, *access_ctx_);
@@ -390,7 +390,7 @@ int ObIndexTreePrefetcher::prefetch_block_data(
     const bool is_data)
 {
   int ret = OB_SUCCESS;
-  if (is_rescan_ && last_handle_hit(index_block_info, is_data, micro_handle)) {
+  if (is_rescan() && last_handle_hit(index_block_info, is_data, micro_handle)) {
     ++access_ctx_->table_store_stat_.block_cache_hit_cnt_;
     LOG_DEBUG("last micro block handle hits", K(is_data), K(index_block_info),
                                               K(last_micro_block_handle_), K(micro_handle));
@@ -400,7 +400,7 @@ int ObIndexTreePrefetcher::prefetch_block_data(
                          true, /* need submit io */
                          micro_handle))) {
     LOG_WARN("Fail to get micro block handle from handle mgr", K(ret));
-  } else if (is_rescan_ && is_data && micro_handle.in_block_state()) {
+  } else if (is_rescan() && is_data && micro_handle.in_block_state()) {
     last_micro_block_handle_ = micro_handle;
   }
   return ret;
@@ -517,7 +517,6 @@ int ObIndexTreeMultiPrefetcher::switch_context(
     }
   }
   if (OB_SUCC(ret)) {
-    is_rescan_ = true;
     row_states_.set_allocator(long_life_allocator_);
     level_handles_.set_allocator(long_life_allocator_);
     if (is_rowkey_sorted_ && OB_FAIL(init_for_sorted_multi_get())) {
@@ -912,6 +911,7 @@ int ObIndexTreeMultiPassPrefetcher<DATA_PREFETCH_DEPTH, INDEX_PREFETCH_DEPTH>::i
       }
     }
     if (OB_SUCC(ret)) {
+      table_scan_cnt_++;
       is_inited_ = true;
     }
   }
@@ -927,6 +927,7 @@ int ObIndexTreeMultiPassPrefetcher<DATA_PREFETCH_DEPTH, INDEX_PREFETCH_DEPTH>::s
     const void *query_range)
 {
   int ret = OB_SUCCESS;
+  const bool first_scan = is_first_scan();
   if (IS_NOT_INIT) {
     ret = OB_NOT_INIT;
     LOG_WARN("not inited", K(ret));
@@ -938,10 +939,14 @@ int ObIndexTreeMultiPassPrefetcher<DATA_PREFETCH_DEPTH, INDEX_PREFETCH_DEPTH>::s
   } else if (OB_FAIL(init_basic_info(iter_type, sstable, iter_param, access_ctx, query_range))) {
     LOG_WARN("Fail to init basic info", K(ret), K(access_ctx));
   } else {
-    is_rescan_ = true;
+    table_scan_cnt_++;
     for (int64_t level = 0; OB_SUCC(ret) && level < index_tree_height_; level++) {
       if (tree_handles_[level].index_scanner_.is_valid()) {
-        if (OB_ISNULL(iter_param_)) {
+        if (OB_UNLIKELY(first_scan)) {
+          ret = OB_ERR_UNEXPECTED;
+          LOG_WARN("Unexpected state, index_scanner_ is valid at first scan", K(ret), K(level), KPC(this),
+              K(tree_handles_[level].index_scanner_), KPC(iter_param_), K(lbt()));
+        } else if (OB_ISNULL(iter_param_)) {
           ret = OB_INVALID_ARGUMENT;
           LOG_WARN("invalid iter param", K(ret), KPC(iter_param_), K(lbt()));
         } else {

src/storage/access/ob_index_tree_prefetcher.h

@@ -123,13 +123,13 @@ class ObIndexTreePrefetcher
 public:
   ObIndexTreePrefetcher() :
       is_inited_(false),
-      is_rescan_(false),
       iter_type_(0),
       cur_level_(0),
       index_tree_height_(0),
       max_rescan_height_(0),
       max_rescan_range_cnt_(0),
       data_version_(0),
+      table_scan_cnt_(0),
       sstable_(nullptr),
       sstable_meta_handle_(),
       index_block_(),
@@ -162,8 +162,9 @@ public:
   int lookup_in_index_tree(ObSSTableReadHandle &read_handle, const bool force_prefetch);
   OB_INLINE bool is_valid() { return is_inited_; }
   ObMicroBlockDataHandle &get_last_data_handle() { return last_micro_block_handle_; }
-  VIRTUAL_TO_STRING_KV(K_(is_rescan), K_(iter_type), K_(cur_level), K_(index_tree_height),
+  VIRTUAL_TO_STRING_KV(K_(is_inited), K_(iter_type), K_(cur_level), K_(index_tree_height),
-      K_(max_rescan_height), K_(max_rescan_range_cnt), K_(data_version), K_(index_scanner));
+      K_(max_rescan_height), K_(max_rescan_range_cnt), K_(data_version), K_(table_scan_cnt), K_(index_scanner),
+      KPC_(sstable), KPC_(iter_param), K_(last_micro_block_handle));
 protected:
   void inner_reset();
   int init_index_scanner(ObIndexBlockRowScanner &index_scanner);
@@ -181,24 +182,25 @@ protected:
       ObSSTable &sstable,
       const ObTableIterParam &iter_param,
       ObTableAccessContext &access_ctx);
+  OB_INLINE bool is_first_scan() const { return nullptr == sstable_; }
+  OB_INLINE bool is_rescan() const { return 1 < table_scan_cnt_; }
 private:
   ObMicroBlockDataHandle &get_read_handle(const int64_t level)
   {
     return micro_handles_[level % DEFAULT_GET_MICRO_DATA_HANDLE_CNT];
   }
   bool last_handle_hit(const ObMicroIndexInfo &block_info, const bool is_data, ObMicroBlockDataHandle &micro_handle);
-
 protected:
   static const int64_t MAX_RESCAN_HOLD_LIMIT = 64;
   static const int16_t MAX_INDEX_TREE_HEIGHT = 16;
   bool is_inited_;
-  bool is_rescan_;
   int16_t iter_type_;
   int16_t cur_level_;
   int16_t index_tree_height_;
   int16_t max_rescan_height_;
   int64_t max_rescan_range_cnt_;
   int64_t data_version_;
+  int64_t table_scan_cnt_;
   ObSSTable *sstable_;
   ObSSTableMetaHandle sstable_meta_handle_;
   ObMicroBlockData index_block_;
@@ -348,7 +350,7 @@ public:
   { return ext_read_handles_[fetch_rowkey_idx_ % MAX_MULTIGET_MICRO_DATA_HANDLE_CNT]; }
   OB_INLINE ObMicroBlockDataHandle &current_micro_handle()
   { return *ext_read_handles_[fetch_rowkey_idx_ % MAX_MULTIGET_MICRO_DATA_HANDLE_CNT].micro_handle_; }
-  INHERIT_TO_STRING_KV("ObIndexTreePrefetcher", ObIndexTreePrefetcher, K_(index_tree_height),
+  INHERIT_TO_STRING_KV("ObIndexTreePrefetcher", ObIndexTreePrefetcher, K_(index_tree_height), K_(is_rowkey_sorted),
       K_(fetch_rowkey_idx), K_(prefetch_rowkey_idx), K_(prefetched_rowkey_cnt), K_(max_handle_prefetching_cnt));
   bool is_rowkey_sorted_;
   int64_t fetch_rowkey_idx_;

src/storage/access/ob_multiple_get_merge.cpp

@@ -199,7 +199,7 @@ int ObMultipleGetMerge::inner_get_next_row(ObDatumRow &row)
               ret = OB_SUCCESS;
             }
           } else {
-            STORAGE_LOG(WARN, "Iterator get next row failed", K(i), K(ret));
+            STORAGE_LOG(WARN, "Iterator get next row failed", K(i), K(ret), K(tables_));
           }
         } else if (OB_ISNULL(tmp_row)) {
           ret = OB_ERR_UNEXPECTED;

src/storage/access/ob_multiple_merge.cpp

@@ -583,7 +583,7 @@ int ObMultipleMerge::get_next_normal_rows(int64_t &count, int64_t capacity)
             scan_state_ = ScanState::BATCH;
             continue;
           } else if (OB_ITER_END != ret) {
-            LOG_WARN("Fail to inner get next row, ", K(ret), KP(this));
+            LOG_WARN("Fail to inner get next row, ", K(ret), K(tables_), KP(this));
           }
         } else if (need_read_lob_columns(unprojected_row_)) {
           if (OB_FAIL(handle_lob_before_fuse_row())) {

src/storage/access/ob_sstable_row_multi_getter.cpp

@@ -166,7 +166,7 @@ int ObSSTableRowMultiGetter::fetch_row(ObSSTableReadHandle &read_handle, const b
               read_handle,
               store_row,
               macro_block_reader_))) {
-    LOG_WARN("Fail to get row", K(ret));
+    LOG_WARN("Fail to get row", K(ret), K(prefetcher_));
   }
   return ret;
 }

src/storage/access/ob_sstable_row_scanner.cpp

@@ -793,7 +793,6 @@ int ObSSTableRowScanner<PrefetchType>::prepare_micro_scanner_for_column_store(Ob
     } else {
       prefetcher_.cur_micro_data_fetch_idx_ = read_handle.micro_begin_idx_;
       cur_range_idx_ = read_handle.range_idx_;
-    }
       blocksstable::ObMicroIndexInfo &micro_info = co_prefetcher->current_micro_info();
       ObMicroBlockDataHandle &micro_handle = co_prefetcher->current_micro_handle();
       ObMicroBlockData block_data;
@@ -806,6 +805,7 @@ int ObSSTableRowScanner<PrefetchType>::prepare_micro_scanner_for_column_store(Ob
                   micro_info.is_right_border()))) {
         LOG_WARN("Failed to open micro_scanner", K(ret), K(micro_info), K(micro_handle), KPC(this));
       }
+    }
   } else {
     // micro_scanner_ is already prepared.
   }

src/storage/access/ob_table_scan_iterator.cpp

@@ -190,6 +190,9 @@ int ObTableScanIterator::prepare_cached_iter_node()
 void ObTableScanIterator::try_release_cached_iter_node(const ObQRIterType rescan_iter_type)
 {
   if (nullptr != cached_iter_node_ && current_iter_type_ != rescan_iter_type) {
+    STORAGE_LOG(INFO, "iter type is changed in rescan", KPC(cached_iter_node_),
+      K(current_iter_type_), K(rescan_iter_type), KP(cached_iter_),
+      KP(single_merge_), KP(get_merge_), KP(scan_merge_), KP(multi_scan_merge_));
     main_table_param_.diable_use_global_iter_pool();
     main_table_ctx_.reset_cached_iter_node();
     MTL(ObGlobalIteratorPool*)->release(cached_iter_node_);
@@ -280,7 +283,7 @@ int ObTableScanIterator::rescan(ObTableScanParam &scan_param)
       STORAGE_LOG(WARN, "Failed to get query iter type", K(ret));
     } else if (FALSE_IT(try_release_cached_iter_node(rescan_iter_type))) {
     } else if (OB_FAIL(open_iter())) {
-      STORAGE_LOG(WARN, "fail to open iter", K(ret));
+      STORAGE_LOG(WARN, "fail to open iter", K(ret), KPC(cached_iter_node_));
     } else {
       STORAGE_LOG(DEBUG, "Success to rescan ObTableScanIterator", K(scan_param.key_ranges_));
     }
@@ -317,7 +320,7 @@ int ObTableScanIterator::init(ObTableScanParam &scan_param, const ObTabletHandle
     } else if (OB_FAIL(prepare_table_context())) {
       STORAGE_LOG(WARN, "Fail to prepare table ctx, ", K(ret));
     } else if (OB_FAIL(open_iter())) {
-      STORAGE_LOG(WARN, "fail to open iter", K(ret), K(*this));
+      STORAGE_LOG(WARN, "fail to open iter", K(ret), KPC(cached_iter_node_), K(*this));
     } else {
       is_inited_ = true;
     }
@@ -356,7 +359,7 @@ int ObTableScanIterator::switch_param(ObTableScanParam &scan_param, const ObTabl
     } else if (OB_FAIL(switch_param_for_iter())) {
       STORAGE_LOG(WARN, "Failed to switch param for iter", K(ret), K(*this));
     } else if (OB_FAIL(open_iter())) {
-      STORAGE_LOG(WARN, "fail to open iter", K(ret), K(*this));
+      STORAGE_LOG(WARN, "fail to open iter", K(ret), KPC(cached_iter_node_), K(*this));
     } else {
       is_inited_ = true;
     }
@@ -635,7 +638,7 @@ int ObTableScanIterator::get_next_row(blocksstable::ObDatumRow *&row)
       if (OB_ITER_END != ret) {
         STORAGE_LOG(WARN, "Fail to get next row, ", K(ret), KPC_(scan_param), K_(main_table_param),
             KP(single_merge_), KP(get_merge_), KP(scan_merge_), KP(multi_scan_merge_),
-            KP(skip_scan_merge_));
+            KP(skip_scan_merge_), KPC(cached_iter_node_));
       }
     }
   }
@@ -669,7 +672,7 @@ int ObTableScanIterator::get_next_rows(int64_t &count, int64_t capacity)
       if (OB_ITER_END != ret) {
         STORAGE_LOG(WARN, "Fail to get next row, ", K(ret), K(*scan_param_), K_(main_table_param),
             KP(single_merge_), KP(get_merge_), KP(scan_merge_), KP(multi_scan_merge_),
-            KP(skip_scan_merge_));
+            KP(skip_scan_merge_), KPC(cached_iter_node_));
       }
     }
   }

src/storage/blocksstable/index_block/ob_index_block_row_struct.h

@@ -530,7 +530,8 @@ public:
   }
   TO_STRING_KV(KP_(query_range), KPC_(row_header), KPC_(minor_meta_info), KPC_(endkey),
       KP_(agg_row_buf), K_(agg_buf_size), K_(flag), K_(range_idx), K_(parent_macro_id),
-      K_(nested_offset), K_(cs_row_range), K_(skipping_filter_results));
+      K_(nested_offset), K_(rowkey_begin_idx), K_(rowkey_end_idx), K_(cs_row_range),
+      K_(skipping_filter_results));
 
 public:
   const ObIndexBlockRowHeader *row_header_;