Skip to content

Commit

Permalink
[improve](cloud-mow) modify some log (#47347)
Browse files Browse the repository at this point in the history
  • Loading branch information
mymeiyi authored Jan 24, 2025
1 parent 1298c14 commit 386e745
Show file tree
Hide file tree
Showing 7 changed files with 56 additions and 29 deletions.
17 changes: 14 additions & 3 deletions be/src/cloud/cloud_tablet.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -860,16 +860,21 @@ Status CloudTablet::calc_delete_bitmap_for_compaction(
}

// 2. calc delete bitmap for incremental data
int64_t t1 = MonotonicMicros();
RETURN_IF_ERROR(_engine.meta_mgr().get_delete_bitmap_update_lock(
*this, COMPACTION_DELETE_BITMAP_LOCK_ID, initiator));
int64_t t2 = MonotonicMicros();
RETURN_IF_ERROR(_engine.meta_mgr().sync_tablet_rowsets(this));
int64_t t3 = MonotonicMicros();

calc_compaction_output_rowset_delete_bitmap(
input_rowsets, rowid_conversion, version.second, UINT64_MAX, missed_rows.get(),
location_map.get(), tablet_meta()->delete_bitmap(), output_rowset_delete_bitmap.get());
int64_t t4 = MonotonicMicros();
if (location_map) {
RETURN_IF_ERROR(check_rowid_conversion(output_rowset, *location_map));
}
int64_t t5 = MonotonicMicros();
if (missed_rows) {
DCHECK_EQ(missed_rows->size(), missed_rows_size);
if (missed_rows->size() != missed_rows_size) {
Expand All @@ -879,9 +884,15 @@ Status CloudTablet::calc_delete_bitmap_for_compaction(
}

// 3. store delete bitmap
RETURN_IF_ERROR(_engine.meta_mgr().update_delete_bitmap(*this, -1, initiator,
output_rowset_delete_bitmap.get()));
return Status::OK();
auto st = _engine.meta_mgr().update_delete_bitmap(*this, -1, initiator,
output_rowset_delete_bitmap.get());
int64_t t6 = MonotonicMicros();
LOG(INFO) << "calc_delete_bitmap_for_compaction, tablet_id=" << tablet_id()
<< ", get lock cost " << (t2 - t1) << " us, sync rowsets cost " << (t3 - t2)
<< " us, calc delete bitmap cost " << (t4 - t3) << " us, check rowid conversion cost "
<< (t5 - t4) << " us, store delete bitmap cost " << (t6 - t5)
<< " us, st=" << st.to_string();
return st;
}

Status CloudTablet::sync_meta() {
Expand Down
21 changes: 13 additions & 8 deletions cloud/src/meta-service/meta_service.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -1870,7 +1870,8 @@ void MetaServiceImpl::update_delete_bitmap(google::protobuf::RpcController* cont
txn->put(pending_key, pending_val);
fdb_txn_size = fdb_txn_size + pending_key.size() + pending_val.size();
LOG(INFO) << "xxx update delete bitmap put pending_key=" << hex(pending_key)
<< " lock_id=" << request->lock_id() << " value_size: " << pending_val.size();
<< " lock_id=" << request->lock_id() << " initiator=" << request->initiator()
<< " value_size: " << pending_val.size();
} else if (request->lock_id() == -3) {
// delete existing key
for (size_t i = 0; i < request->rowset_ids_size(); ++i) {
Expand Down Expand Up @@ -1899,15 +1900,16 @@ void MetaServiceImpl::update_delete_bitmap(google::protobuf::RpcController* cont
if (txn->approximate_bytes() + key.size() * 3 + val.size() > config::max_txn_commit_byte) {
LOG(INFO) << "fdb txn size more than " << config::max_txn_commit_byte
<< ", current size: " << txn->approximate_bytes()
<< " lock_id=" << request->lock_id() << ", need to commit";
<< " lock_id=" << request->lock_id() << " initiator=" << request->initiator()
<< ", need to commit";
err = txn->commit();
total_txn_put_keys += txn->num_put_keys();
total_txn_put_bytes += txn->put_bytes();
total_txn_size += txn->approximate_bytes();
if (err != TxnErrorCode::TXN_OK) {
code = cast_as<ErrCategory::COMMIT>(err);
ss << "failed to update delete bitmap, err=" << err << " tablet_id=" << tablet_id
<< " lock_id=" << request->lock_id()
<< " lock_id=" << request->lock_id() << " initiator=" << request->initiator()
<< " delete_bitmap_key=" << current_key_count
<< " delete_bitmap_value=" << current_value_count
<< " put_size=" << txn->put_bytes() << " num_put_keys=" << txn->num_put_keys()
Expand Down Expand Up @@ -1940,8 +1942,8 @@ void MetaServiceImpl::update_delete_bitmap(google::protobuf::RpcController* cont
total_key_count++;
total_value_count += val.size();
VLOG_DEBUG << "xxx update delete bitmap put delete_bitmap_key=" << hex(key)
<< " lock_id=" << request->lock_id() << " key_size: " << key.size()
<< " value_size: " << val.size();
<< " lock_id=" << request->lock_id() << " initiator=" << request->initiator()
<< " key_size: " << key.size() << " value_size: " << val.size();
}
err = txn->commit();
total_txn_put_keys += txn->num_put_keys();
Expand All @@ -1950,13 +1952,15 @@ void MetaServiceImpl::update_delete_bitmap(google::protobuf::RpcController* cont
if (err != TxnErrorCode::TXN_OK) {
code = cast_as<ErrCategory::COMMIT>(err);
ss << "failed to update delete bitmap, err=" << err << " tablet_id=" << tablet_id
<< " lock_id=" << request->lock_id() << " delete_bitmap_key=" << current_key_count
<< " lock_id=" << request->lock_id() << " initiator=" << request->initiator()
<< " delete_bitmap_key=" << current_key_count
<< " delete_bitmap_value=" << current_value_count << " put_size=" << txn->put_bytes()
<< " num_put_keys=" << txn->num_put_keys() << " txn_size=" << txn->approximate_bytes();
msg = ss.str();
return;
}
LOG(INFO) << "update_delete_bitmap tablet_id=" << tablet_id << " lock_id=" << request->lock_id()
<< " initiator=" << request->initiator()
<< " rowset_num=" << request->rowset_ids_size()
<< " total_key_count=" << total_key_count
<< " total_value_count=" << total_value_count << " unlock=" << unlock
Expand Down Expand Up @@ -2230,8 +2234,9 @@ void MetaServiceImpl::get_delete_bitmap_update_lock(google::protobuf::RpcControl
return;
}
txn->put(lock_key, lock_val);
LOG(INFO) << "xxx put lock_key=" << hex(lock_key) << " lock_id=" << request->lock_id()
<< " initiators_size: " << lock_info.initiators_size();
LOG(INFO) << "xxx put lock_key=" << hex(lock_key) << " table_id=" << table_id
<< " lock_id=" << request->lock_id() << " initiator=" << request->initiator()
<< " initiators_size=" << lock_info.initiators_size();

err = txn->commit();
if (err != TxnErrorCode::TXN_OK) {
Expand Down
11 changes: 9 additions & 2 deletions cloud/src/meta-service/meta_service_helper.h
Original file line number Diff line number Diff line change
Expand Up @@ -60,8 +60,8 @@ void begin_rpc(std::string_view func_name, brpc::Controller* ctrl, const Request
LOG(INFO) << "begin " << func_name << " from " << ctrl->remote_side();
} else if constexpr (std::is_same_v<Request, UpdateDeleteBitmapRequest>) {
LOG(INFO) << "begin " << func_name << " from " << ctrl->remote_side()
<< " tablet_id=" << req->tablet_id() << " lock_id=" << req->lock_id()
<< " initiator=" << req->initiator()
<< " table_id=" << req->table_id() << " tablet_id=" << req->tablet_id()
<< " lock_id=" << req->lock_id() << " initiator=" << req->initiator()
<< " delete_bitmap_size=" << req->segment_delete_bitmaps_size();
} else if constexpr (std::is_same_v<Request, GetDeleteBitmapRequest>) {
LOG(INFO) << "begin " << func_name << " from " << ctrl->remote_side()
Expand All @@ -77,6 +77,11 @@ void begin_rpc(std::string_view func_name, brpc::Controller* ctrl, const Request
} else if constexpr (std::is_same_v<Request, RemoveDeleteBitmapRequest>) {
LOG(INFO) << "begin " << func_name << " from " << ctrl->remote_side()
<< " tablet_id=" << req->tablet_id() << " rowset_size=" << req->rowset_ids_size();
} else if constexpr (std::is_same_v<Request, GetDeleteBitmapUpdateLockRequest>) {
LOG(INFO) << "begin " << func_name << " from " << ctrl->remote_side()
<< " table_id=" << req->table_id() << " lock_id=" << req->lock_id()
<< " initiator=" << req->initiator() << " expiration=" << req->expiration()
<< " require_compaction_stats=" << req->require_compaction_stats();
} else {
LOG(INFO) << "begin " << func_name << " from " << ctrl->remote_side()
<< " request=" << req->ShortDebugString();
Expand Down Expand Up @@ -124,6 +129,8 @@ void finish_rpc(std::string_view func_name, brpc::Controller* ctrl, Response* re
res->clear_cumulative_compaction_cnts();
res->clear_cumulative_points();
}
LOG(INFO) << "finish " << func_name << " from " << ctrl->remote_side()
<< " status=" << res->status().ShortDebugString();
} else if constexpr (std::is_same_v<Response, GetObjStoreInfoResponse> ||
std::is_same_v<Response, GetStageResponse>) {
std::string debug_string = res->DebugString();
Expand Down
16 changes: 10 additions & 6 deletions cloud/src/meta-service/meta_service_job.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -474,7 +474,8 @@ static bool check_and_remove_delete_bitmap_update_lock(MetaServiceCode& code, st
return false;
}
if (lock_info.lock_id() != lock_id) {
msg = "lock id not match";
ss << "lock id not match, locked by lock_id=" << lock_info.lock_id();
msg = ss.str();
code = MetaServiceCode::LOCK_EXPIRED;
return false;
}
Expand All @@ -488,13 +489,14 @@ static bool check_and_remove_delete_bitmap_update_lock(MetaServiceCode& code, st
}
}
if (!found) {
msg = "lock initiator not exist";
ss << "lock initiator " << lock_initiator << " not exist";
msg = ss.str();
code = MetaServiceCode::LOCK_EXPIRED;
return false;
}
if (initiators->empty()) {
INSTANCE_LOG(INFO) << "remove delete bitmap lock, table_id=" << table_id
<< " key=" << hex(lock_key);
<< " lock_id=" << lock_id << " key=" << hex(lock_key);
txn->remove(lock_key);
return true;
}
Expand All @@ -505,7 +507,8 @@ static bool check_and_remove_delete_bitmap_update_lock(MetaServiceCode& code, st
return false;
}
INSTANCE_LOG(INFO) << "remove delete bitmap lock initiator, table_id=" << table_id
<< ", key=" << hex(lock_key) << ", initiator=" << lock_initiator
<< ", key=" << hex(lock_key) << " lock_id=" << lock_id
<< " initiator=" << lock_initiator
<< " initiators_size=" << lock_info.initiators_size();
txn->put(lock_key, lock_val);
return true;
Expand Down Expand Up @@ -547,7 +550,7 @@ static void remove_delete_bitmap_update_lock(std::unique_ptr<Transaction>& txn,
}
if (initiators->empty()) {
INSTANCE_LOG(INFO) << "remove delete bitmap lock, table_id=" << table_id
<< " key=" << hex(lock_key);
<< " lock_id=" << lock_id << " key=" << hex(lock_key);
txn->remove(lock_key);
return;
}
Expand All @@ -558,7 +561,8 @@ static void remove_delete_bitmap_update_lock(std::unique_ptr<Transaction>& txn,
return;
}
INSTANCE_LOG(INFO) << "remove delete bitmap lock initiator, table_id=" << table_id
<< ", key=" << hex(lock_key) << ", initiator=" << lock_initiator
<< ", key=" << hex(lock_key) << " lock_id=" << lock_id
<< " initiator=" << lock_initiator
<< " initiators_size=" << lock_info.initiators_size();
txn->put(lock_key, lock_val);
}
Expand Down
7 changes: 4 additions & 3 deletions cloud/src/meta-service/meta_service_txn.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -949,7 +949,7 @@ void process_mow_when_commit_txn(
// by another transaction and successfully committed.
if (!lock_values[i].has_value()) {
ss << "get delete bitmap update lock info, lock is expired"
<< " table_id=" << table_id << " key=" << hex(lock_keys[i]);
<< " table_id=" << table_id << " key=" << hex(lock_keys[i]) << " txn_id=" << txn_id;
code = MetaServiceCode::LOCK_EXPIRED;
msg = ss.str();
LOG(WARNING) << msg << " txn_id=" << txn_id;
Expand All @@ -964,13 +964,14 @@ void process_mow_when_commit_txn(
return;
}
if (lock_info.lock_id() != request->txn_id()) {
msg = "lock is expired";
ss << "lock is expired, locked by lock_id=" << lock_info.lock_id();
msg = ss.str();
code = MetaServiceCode::LOCK_EXPIRED;
return;
}
txn->remove(lock_keys[i]);
LOG(INFO) << "xxx remove delete bitmap lock, lock_key=" << hex(lock_keys[i])
<< " txn_id=" << txn_id;
<< " table_id=" << table_id << " txn_id=" << txn_id;

for (auto tablet_id : table_id_tablet_ids[table_id]) {
std::string pending_key = meta_pending_delete_bitmap_key({instance_id, tablet_id});
Expand Down
2 changes: 1 addition & 1 deletion cloud/test/meta_service_job_test.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -1783,7 +1783,7 @@ TEST(MetaServiceJobTest, SchemaChangeJobWithMoWTest) {
finish_schema_change_job(meta_service.get(), tablet_id, new_tablet_id, "job1", "be1",
output_rowsets, res);
ASSERT_EQ(res.status().code(), MetaServiceCode::LOCK_EXPIRED);
ASSERT_NE(res.status().msg().find("lock initiator not exist"), std::string::npos);
ASSERT_NE(res.status().msg().find("lock initiator 12345 not exist"), std::string::npos);
remove_delete_bitmap_lock(meta_service.get(), table_id);
res.Clear();

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -351,7 +351,8 @@ public void commitTransaction(long dbId, List<Table> tableList, long transaction
throws UserException {
List<OlapTable> mowTableList = getMowTableList(tableList, tabletCommitInfos);
try {
LOG.info("try to commit transaction, transactionId: {}", transactionId);
LOG.info("try to commit transaction, transactionId: {}, tableIds: {}", transactionId,
tableList.stream().map(Table::getId).collect(Collectors.toList()));
Map<Long, List<TCalcDeleteBitmapPartitionInfo>> backendToPartitionInfos = null;
if (!mowTableList.isEmpty()) {
DeleteBitmapUpdateLockContext lockContext = new DeleteBitmapUpdateLockContext();
Expand Down Expand Up @@ -941,11 +942,9 @@ private void getDeleteBitmapUpdateLock(long transactionId, List<OlapTable> mowTa
totalRetryTime += retryTime;
}
stopWatch.stop();
if (totalRetryTime > 0 || stopWatch.getTime() > 20) {
LOG.info("get delete bitmap lock successfully. txns: {}. totalRetryTime: {}. "
+ "partitionSize: {}. time cost: {} ms.", transactionId, totalRetryTime,
lockContext.getTableToPartitions().size(), stopWatch.getTime());
}
LOG.info("get delete bitmap lock successfully. txnId: {}. totalRetryTime: {}. "
+ "tableSize: {}. cost: {} ms.", transactionId, totalRetryTime,
lockContext.getTableToPartitions().size(), stopWatch.getTime());
}

private void removeDeleteBitmapUpdateLock(List<OlapTable> tableList, long transactionId) {
Expand Down

0 comments on commit 386e745

Please sign in to comment.