Add log to help debug replay in memtable

This commit is contained in:
obdev
2023-01-12 08:08:15 +00:00
committed by ob-robot
parent 0ee1285b06
commit 8ffeb21dc9
2 changed files with 14 additions and 0 deletions

View File

@ -107,6 +107,7 @@ int ObIMvccCtx::register_row_replay_cb(
int ret = OB_SUCCESS; int ret = OB_SUCCESS;
const bool is_replay = true; const bool is_replay = true;
ObMvccRowCallback *cb = NULL; ObMvccRowCallback *cb = NULL;
common::ObTimeGuard timeguard("ObIMvccCtx::register_row_replay_cb", 5 * 1000);
if (OB_ISNULL(key) || OB_ISNULL(value) || OB_ISNULL(node) if (OB_ISNULL(key) || OB_ISNULL(value) || OB_ISNULL(node)
|| data_size <= 0 || OB_ISNULL(memtable)) { || data_size <= 0 || OB_ISNULL(memtable)) {
ret = OB_INVALID_ARGUMENT; ret = OB_INVALID_ARGUMENT;
@ -114,6 +115,7 @@ int ObIMvccCtx::register_row_replay_cb(
} else if (OB_ISNULL(cb = alloc_row_callback(*this, *value, memtable))) { } else if (OB_ISNULL(cb = alloc_row_callback(*this, *value, memtable))) {
ret = OB_ALLOCATE_MEMORY_FAILED; ret = OB_ALLOCATE_MEMORY_FAILED;
TRANS_LOG(WARN, "alloc row callback failed", K(ret)); TRANS_LOG(WARN, "alloc row callback failed", K(ret));
} else if (FALSE_IT(timeguard.click("alloc_row_callback"))) {
} else { } else {
cb->set(key, cb->set(key,
node, node,
@ -125,6 +127,7 @@ int ObIMvccCtx::register_row_replay_cb(
ObRowLatchGuard guard(value->latch_); ObRowLatchGuard guard(value->latch_);
cb->link_trans_node(); cb->link_trans_node();
} }
timeguard.click("link_trans_node");
cb->set_scn(scn); cb->set_scn(scn);
if (OB_FAIL(append_callback(cb))) { if (OB_FAIL(append_callback(cb))) {
@ -134,9 +137,11 @@ int ObIMvccCtx::register_row_replay_cb(
} }
TRANS_LOG(WARN, "append callback failed", K(ret)); TRANS_LOG(WARN, "append callback failed", K(ret));
} }
timeguard.click("append_callback");
if (OB_FAIL(ret)) { if (OB_FAIL(ret)) {
callback_free(cb); callback_free(cb);
timeguard.click("callback_free");
TRANS_LOG(WARN, "append callback failed", K(ret)); TRANS_LOG(WARN, "append callback failed", K(ret));
} }
} }

View File

@ -1078,6 +1078,7 @@ int ObMemtable::replay_row(ObStoreCtx &ctx,
ObPartTransCtx *part_ctx = static_cast<ObPartTransCtx *>(mt_ctx->get_trans_ctx()); ObPartTransCtx *part_ctx = static_cast<ObPartTransCtx *>(mt_ctx->get_trans_ctx());
const SCN scn = mt_ctx->get_redo_scn(); const SCN scn = mt_ctx->get_redo_scn();
const int64_t log_id = mt_ctx->get_redo_log_id(); const int64_t log_id = mt_ctx->get_redo_log_id();
common::ObTimeGuard timeguard("ObMemtable::replay_row", 5 * 1000);
if (OB_FAIL(mmi->get_mutator_row().copy(table_id, rowkey, table_version, row, if (OB_FAIL(mmi->get_mutator_row().copy(table_id, rowkey, table_version, row,
old_row, dml_flag, modify_count, acc_checksum, version, old_row, dml_flag, modify_count, acc_checksum, version,
@ -1085,9 +1086,11 @@ int ObMemtable::replay_row(ObStoreCtx &ctx,
if (OB_ITER_END != ret) { if (OB_ITER_END != ret) {
TRANS_LOG(WARN, "get next row error", K(ret)); TRANS_LOG(WARN, "get next row error", K(ret));
} }
} else if (FALSE_IT(timeguard.click("mutator_row copy"))) {
} else if (OB_FAIL(check_standby_cluster_schema_condition_(ctx, table_id, table_version))) { } else if (OB_FAIL(check_standby_cluster_schema_condition_(ctx, table_id, table_version))) {
TRANS_LOG(WARN, "failed to check standby_cluster_schema_condition", K(ret), K(table_id), TRANS_LOG(WARN, "failed to check standby_cluster_schema_condition", K(ret), K(table_id),
K(table_version)); K(table_version));
} else if (FALSE_IT(timeguard.click("check_standby_cluster_schema_condition"))) {
} else if (OB_UNLIKELY(dml_flag == blocksstable::ObDmlFlag::DF_NOT_EXIST)) { } else if (OB_UNLIKELY(dml_flag == blocksstable::ObDmlFlag::DF_NOT_EXIST)) {
ret = OB_ERR_UNEXPECTED; ret = OB_ERR_UNEXPECTED;
TRANS_LOG(ERROR, "Unexpected not exist trans node", K(ret), K(dml_flag), K(rowkey)); TRANS_LOG(ERROR, "Unexpected not exist trans node", K(ret), K(dml_flag), K(rowkey));
@ -1107,6 +1110,7 @@ int ObMemtable::replay_row(ObStoreCtx &ctx,
TRANS_LOG(WARN, "mtk encode fail", "ret", ret); TRANS_LOG(WARN, "mtk encode fail", "ret", ret);
} else if (OB_FAIL(mvcc_replay_(ctx, &mtk, arg))) { } else if (OB_FAIL(mvcc_replay_(ctx, &mtk, arg))) {
TRANS_LOG(WARN, "mvcc replay failed", K(ret), K(ctx), K(arg)); TRANS_LOG(WARN, "mvcc replay failed", K(ret), K(ctx), K(arg));
} else if (FALSE_IT(timeguard.click("mvcc_replay_"))) {
} }
if (OB_SUCCESS != ret) { if (OB_SUCCESS != ret) {
@ -2495,6 +2499,7 @@ int ObMemtable::mvcc_replay_(storage::ObStoreCtx &ctx,
bool is_new_add = false; bool is_new_add = false;
ObIMemtableCtx *mem_ctx = ctx.mvcc_acc_ctx_.get_mem_ctx(); ObIMemtableCtx *mem_ctx = ctx.mvcc_acc_ctx_.get_mem_ctx();
ObMvccReplayResult res; ObMvccReplayResult res;
common::ObTimeGuard timeguard("ObMemtable::mvcc_replay_", 5 * 1000);
if (OB_FAIL(mvcc_engine_.create_kv(key, if (OB_FAIL(mvcc_engine_.create_kv(key,
&stored_key, &stored_key,
@ -2502,14 +2507,17 @@ int ObMemtable::mvcc_replay_(storage::ObStoreCtx &ctx,
getter, getter,
is_new_add))) { is_new_add))) {
TRANS_LOG(WARN, "prepare kv before lock fail", K(ret)); TRANS_LOG(WARN, "prepare kv before lock fail", K(ret));
} else if (FALSE_IT(timeguard.click("mvcc_engine_.create_kv"))) {
} else if (OB_FAIL(mvcc_engine_.mvcc_replay(*mem_ctx, } else if (OB_FAIL(mvcc_engine_.mvcc_replay(*mem_ctx,
&stored_key, &stored_key,
*value, *value,
arg, arg,
res))) { res))) {
TRANS_LOG(WARN, "mvcc replay fail", K(ret)); TRANS_LOG(WARN, "mvcc replay fail", K(ret));
} else if (FALSE_IT(timeguard.click("mvcc_engine_.mvcc_replay"))) {
} else if (OB_FAIL(mvcc_engine_.ensure_kv(&stored_key, value))) { } else if (OB_FAIL(mvcc_engine_.ensure_kv(&stored_key, value))) {
TRANS_LOG(WARN, "prepare kv after lock fail", K(ret)); TRANS_LOG(WARN, "prepare kv after lock fail", K(ret));
} else if (FALSE_IT(timeguard.click("mvcc_engine_.ensure_kv"))) {
} else if (OB_FAIL(mem_ctx->register_row_replay_cb(&stored_key, } else if (OB_FAIL(mem_ctx->register_row_replay_cb(&stored_key,
value, value,
res.tx_node_, res.tx_node_,
@ -2518,6 +2526,7 @@ int ObMemtable::mvcc_replay_(storage::ObStoreCtx &ctx,
arg.seq_no_, arg.seq_no_,
arg.scn_))) { arg.scn_))) {
TRANS_LOG(WARN, "register_row_replay_cb fail", K(ret)); TRANS_LOG(WARN, "register_row_replay_cb fail", K(ret));
} else if (FALSE_IT(timeguard.click("register_row_replay_cb"))) {
} }
return ret; return ret;