From 8fa0c1de8cf4f2442ff72df092dfd8c283f6bf11 Mon Sep 17 00:00:00 2001 From: Handora Date: Tue, 17 Dec 2024 02:45:07 +0000 Subject: [PATCH] [ENHANCE] add debug info on mvcc row --- src/storage/memtable/mvcc/ob_mvcc_define.h | 11 ++++ src/storage/memtable/mvcc/ob_mvcc_row.cpp | 18 +++++++ src/storage/memtable/mvcc/ob_mvcc_row.h | 46 ++++++++++++++++- src/storage/memtable/ob_memtable.cpp | 58 ++++++++++++++++++---- src/storage/memtable/ob_memtable.h | 3 ++ 5 files changed, 126 insertions(+), 10 deletions(-) diff --git a/src/storage/memtable/mvcc/ob_mvcc_define.h b/src/storage/memtable/mvcc/ob_mvcc_define.h index a42e83bc3..63cac0dc2 100644 --- a/src/storage/memtable/mvcc/ob_mvcc_define.h +++ b/src/storage/memtable/mvcc/ob_mvcc_define.h @@ -187,6 +187,17 @@ public: } }; +// used only for debug during mvcc_write +struct ObMvccWriteDebugInfo { + ObMvccWriteDebugInfo() + : memtable_iterate_cnt_(0), + sstable_iterate_cnt_(0) {} + + int64_t memtable_iterate_cnt_; + int64_t sstable_iterate_cnt_; + // TODO(handora.qc): add more debug info if necessary + // int64_t exist_table_bitmap_; +}; } // namespace memtable } // namespace oceanbase diff --git a/src/storage/memtable/mvcc/ob_mvcc_row.cpp b/src/storage/memtable/mvcc/ob_mvcc_row.cpp index ed45e0191..6c62a655c 100644 --- a/src/storage/memtable/mvcc/ob_mvcc_row.cpp +++ b/src/storage/memtable/mvcc/ob_mvcc_row.cpp @@ -285,6 +285,11 @@ void ObMvccRow::reset() last_compact_cnt_ = 0; max_modify_scn_.set_invalid(); min_modify_scn_.set_invalid(); + +#ifdef ENABLE_DEBUG_LOG + lower_lock_scanned_ts_ = 0; + lower_lock_scanned_info_.raw_value_ = 0; +#endif } int64_t ObMvccRow::to_string(char *buf, const int64_t buf_len) const @@ -323,6 +328,19 @@ int64_t ObMvccRow::to_string(char *buf, const int64_t buf_len) const common::databuff_printf(buf, buf_len, pos, max_modify_scn_); common::databuff_printf(buf, buf_len, pos, " min_modify_scn="); common::databuff_printf(buf, buf_len, pos, min_modify_scn_); + +#ifdef ENABLE_DEBUG_LOG + common::databuff_printf(buf, buf_len, pos, + " lower_lock_ts=%ld " + "lower_lock_mem_cnt=%hd " + "lower_lock_sst_cnt=%hd " + "lower_lock_tx_id=%d", + lower_lock_scanned_ts_, + lower_lock_scanned_info_.lower_lock_scanned_memtable_cnt_, + lower_lock_scanned_info_.lower_lock_scanned_sstable_cnt_, + lower_lock_scanned_info_.lower_lock_scanned_tx_id_); +#endif + common::databuff_printf(buf, buf_len, pos, "}"); return pos; } diff --git a/src/storage/memtable/mvcc/ob_mvcc_row.h b/src/storage/memtable/mvcc/ob_mvcc_row.h index b751cea0b..fe76f8652 100644 --- a/src/storage/memtable/mvcc/ob_mvcc_row.h +++ b/src/storage/memtable/mvcc/ob_mvcc_row.h @@ -280,9 +280,27 @@ struct ObMvccRow ObMvccTransNode *latest_compact_node_; ObMvccRowIndex *index_; + // for row lock 4377 problem debug +#ifdef ENABLE_DEBUG_LOG + int64_t lower_lock_scanned_ts_; + union { + int64_t raw_value_; + struct { + int32_t lower_lock_scanned_tx_id_ : 32; + int16_t lower_lock_scanned_memtable_cnt_ : 16; + int16_t lower_lock_scanned_sstable_cnt_ : 16; + }; + } lower_lock_scanned_info_; +#endif + + ObMvccRow() { +#ifdef ENABLE_DEBUG_LOG + STATIC_ASSERT(sizeof(ObMvccRow) <= 136, "Size of ObMvccRow Overflow."); +#else STATIC_ASSERT(sizeof(ObMvccRow) <= 120, "Size of ObMvccRow Overflow."); +#endif reset(); } void reset(); @@ -406,9 +424,35 @@ struct ObMvccRow { return ATOMIC_LOAD(&flag_) & F_LOWER_LOCK_SCANED; } - OB_INLINE void set_lower_lock_scaned() + OB_INLINE void set_lower_lock_scaned(const transaction::ObTransID &lower_lock_tx_id, + const int64_t lower_lock_mem_cnt, + const int64_t lower_lock_sst_cnt) { +#ifdef ENABLE_DEBUG_LOG + while (true) { + const uint8_t old = ATOMIC_LOAD(&(flag_)); + if (old & F_LOWER_LOCK_SCANED) { + break; + } else { + const uint8_t tmp = (old | (F_LOWER_LOCK_SCANED)); + if (ATOMIC_BCAS(&(flag_), old, tmp)) { + lower_lock_scanned_ts_ = ObTimeUtility::current_time(); + lower_lock_scanned_info_.lower_lock_scanned_tx_id_ = + static_cast(lower_lock_tx_id.get_id()); + lower_lock_scanned_info_.lower_lock_scanned_memtable_cnt_ = + static_cast(lower_lock_mem_cnt); + lower_lock_scanned_info_.lower_lock_scanned_sstable_cnt_ = + static_cast(lower_lock_sst_cnt); + break; + } + } + } +#else + UNUSED(lower_lock_tx_id); + UNUSED(lower_lock_mem_cnt); + UNUSED(lower_lock_sst_cnt); ATOMIC_ADD_TAG(F_LOWER_LOCK_SCANED); +#endif } // ===================== ObMvccRow Helper Function ===================== int64_t to_string(char *buf, const int64_t buf_len) const; diff --git a/src/storage/memtable/ob_memtable.cpp b/src/storage/memtable/ob_memtable.cpp index 2ff62218e..c5c702205 100644 --- a/src/storage/memtable/ob_memtable.cpp +++ b/src/storage/memtable/ob_memtable.cpp @@ -1321,15 +1321,27 @@ int ObMemtable::lock_row_on_frozen_stores_( } else { ObRowState row_state; common::ObSEArray iter_tables; + ObMvccWriteDebugInfo debug_info; if (OB_FAIL(get_all_tables_(ctx, iter_tables))) { TRANS_LOG(WARN, "get all tables from table iter failed", KR(ret)); - } else if (OB_FAIL(internal_lock_row_on_frozen_stores_( - check_exist, key, param, iter_tables, context, res, row_state))) { + } else if (OB_FAIL(internal_lock_row_on_frozen_stores_(check_exist, + key, + param, + iter_tables, + context, + debug_info, + res, + row_state))) { TRANS_LOG(WARN, "internal lock row failed", KR(ret)); } else { lock_state.trans_version_ = MAX(lock_state.trans_version_, row_state.get_max_trans_version()); - if (OB_FAIL(lock_row_on_frozen_stores_on_success(lock_state.is_locked_, arg.data_->dml_flag_, - lock_state.trans_version_, context, value, res))) { + if (OB_FAIL(lock_row_on_frozen_stores_on_success(lock_state.is_locked_, + arg.data_->dml_flag_, + lock_state.trans_version_, + context, + debug_info, + value, + res))) { if (OB_UNLIKELY(OB_TRANSACTION_SET_VIOLATION != ret)) { TRANS_LOG(WARN, "Failed to call on success callback after lock row on frozen stores", K(ret)); } @@ -1367,6 +1379,7 @@ int ObMemtable::internal_lock_row_on_frozen_stores_(const bool check_exist, const storage::ObTableIterParam ¶m, const ObIArray &iter_tables, storage::ObTableAccessContext &context, + ObMvccWriteDebugInfo &debug_info, ObMvccWriteResult &res, ObRowState &row_state) @@ -1394,6 +1407,8 @@ int ObMemtable::internal_lock_row_on_frozen_stores_(const bool check_exist, // FIXME(handora.qc): two active memtable in transfer if (OB_FAIL(mvcc_engine.check_row_locked(ctx.mvcc_acc_ctx_, key, tmp_lock_state, row_state))) { TRANS_LOG(WARN, "mvcc engine check row lock fail", K(ret), K(lock_state), K(tmp_lock_state)); + } else { + debug_info.memtable_iterate_cnt_++; } } else if (iter_tables.at(i)->is_sstable()) { blocksstable::ObDatumRowkeyHelper rowkey_converter; @@ -1412,6 +1427,8 @@ int ObMemtable::internal_lock_row_on_frozen_stores_(const bool check_exist, K(lock_state), K(tmp_lock_state), K(row_state)); + } else { + debug_info.sstable_iterate_cnt_++; } TRANS_LOG(DEBUG, "sstable check row lock debug", @@ -1440,6 +1457,8 @@ int ObMemtable::internal_lock_row_on_frozen_stores_(const bool check_exist, K(lock_state), K(tmp_lock_state), K(row_state)); + } else { + debug_info.sstable_iterate_cnt_++; } TRANS_LOG(DEBUG, "direct load memtable check row lock debug", @@ -1489,6 +1508,7 @@ int ObMemtable::lock_row_on_frozen_stores_on_success( const blocksstable::ObDmlFlag writer_dml_flag, const share::SCN &max_trans_version, storage::ObTableAccessContext &context, + ObMvccWriteDebugInfo &debug_info, ObMvccRow *value, ObMvccWriteResult &res) { @@ -1507,7 +1527,9 @@ int ObMemtable::lock_row_on_frozen_stores_on_success( ret = OB_TRANSACTION_SET_VIOLATION; TRANS_LOG(WARN, "TRANS_SET_VIOLATION", K(ret), K(max_trans_version), "ctx", ctx); } - value->set_lower_lock_scaned(); + value->set_lower_lock_scaned(my_tx_id, + debug_info.memtable_iterate_cnt_, + debug_info.sstable_iterate_cnt_); TRANS_LOG(DEBUG, "lower lock check finish", K(*value)); } else { // There is the lock on frozen stores by my self @@ -1616,12 +1638,18 @@ int ObMemtable::lock_rows_on_frozen_stores_( // so there is no need to check transaction conflict again. } else { common::ObSEArray iter_tables; + ObMvccWriteDebugInfo debug_info; if (OB_FAIL(get_all_tables_(ctx, iter_tables))) { TRANS_LOG(WARN, "get all tables from table iter failed", KR(ret)); } else { share::SCN max_trans_version = SCN::min_scn(); - if (OB_FAIL(internal_lock_rows_on_frozen_stores_(check_exist, iter_tables, param, context, - max_trans_version, rows_info))) { + if (OB_FAIL(internal_lock_rows_on_frozen_stores_(check_exist, + iter_tables, + param, + context, + debug_info, + max_trans_version, + rows_info))) { TRANS_LOG(WARN, "Failed to lock rows on frozen stores", K(ret), K(check_exist), K(iter_tables)); } else if (!rows_info.have_conflict()) { for (int64_t i = 0; OB_SUCC(ret) && i < mvcc_rows.count(); ++i) { @@ -1634,8 +1662,11 @@ int ObMemtable::lock_rows_on_frozen_stores_( row_lock_state.trans_version_ = MAX(row_lock_state.trans_version_, max_trans_version); if (OB_FAIL(lock_row_on_frozen_stores_on_success(row_lock_state.is_locked_, blocksstable::ObDmlFlag::DF_INSERT, - row_lock_state.trans_version_, context, - mvcc_row, write_result))) { + row_lock_state.trans_version_, + context, + debug_info, + mvcc_row, + write_result))) { TRANS_LOG(WARN, "Failed to lock rows on frozen stores", K(ret), K(check_exist), K(iter_tables)); // The upper layer determines whether to call lock_row_on_frozen_stores_on_failure based on whether rows_info has a conflict. // Therefore, here we convert the error code to success and store the error code in rows_info. @@ -1657,6 +1688,7 @@ int ObMemtable::internal_lock_rows_on_frozen_stores_( const ObIArray &iter_tables, const storage::ObTableIterParam ¶m, storage::ObTableAccessContext &context, + ObMvccWriteDebugInfo &debug_info, share::SCN &max_trans_version, ObRowsInfo &rows_info) { @@ -1668,6 +1700,8 @@ int ObMemtable::internal_lock_rows_on_frozen_stores_( if (OB_FAIL(memtable->check_rows_locked(check_exist, param, context, rows_info))) { TRANS_LOG(WARN, "Failed to check rows locked and duplication in memtable", K(ret), K(i), K(iter_tables)); + } else { + debug_info.memtable_iterate_cnt_++; } } else if (i_table->is_sstable()) { ObSSTable *sstable = static_cast(i_table); @@ -1678,6 +1712,8 @@ int ObMemtable::internal_lock_rows_on_frozen_stores_( context, rows_info))) { TRANS_LOG(WARN, "Failed to check rows locked for sstable", K(ret), K(i), K(iter_tables)); + } else { + debug_info.sstable_iterate_cnt_++; } } else { if (OB_FAIL(sstable->check_rows_locked(check_exist, @@ -1685,6 +1721,8 @@ int ObMemtable::internal_lock_rows_on_frozen_stores_( max_trans_version, rows_info))) { TRANS_LOG(WARN, "Failed to check rows locked for sstable", K(ret), K(i), K(iter_tables)); + } else { + debug_info.sstable_iterate_cnt_++; } } } else if (i_table->is_direct_load_memtable()) { @@ -1696,6 +1734,8 @@ int ObMemtable::internal_lock_rows_on_frozen_stores_( } else { ret = OB_SUCCESS; } + } else { + debug_info.sstable_iterate_cnt_++; } } else { ret = OB_ERR_UNEXPECTED; diff --git a/src/storage/memtable/ob_memtable.h b/src/storage/memtable/ob_memtable.h index 32b3dd492..a920c1cc5 100644 --- a/src/storage/memtable/ob_memtable.h +++ b/src/storage/memtable/ob_memtable.h @@ -501,6 +501,7 @@ private: const blocksstable::ObDmlFlag writer_dml_flag, const share::SCN &max_trans_version, storage::ObTableAccessContext &context, + ObMvccWriteDebugInfo &debug_info, ObMvccRow *value, ObMvccWriteResult &res); @@ -524,6 +525,7 @@ private: const storage::ObTableIterParam ¶m, const ObIArray &iter_tables, storage::ObTableAccessContext &context, + ObMvccWriteDebugInfo &debug_info, ObMvccWriteResult &res, ObRowState &row_state); @@ -532,6 +534,7 @@ private: const ObIArray &iter_tables, const storage::ObTableIterParam ¶m, storage::ObTableAccessContext &context, + ObMvccWriteDebugInfo &debug_info, share::SCN &max_trans_version, ObRowsInfo &rows_info);