From 958f3830996d210dcbe0693043185a591c3e42ac Mon Sep 17 00:00:00 2001 From: yangjundong <1047934838@qq.com> Date: Wed, 30 Oct 2024 14:54:34 +0000 Subject: [PATCH] [fix][store] Add time statistics --- src/common/tracker.cc | 4 ++++ src/common/tracker.h | 19 ++++++++++++++++--- src/handler/raft_apply_handler.cc | 6 ++++-- src/handler/raft_apply_handler_txn.cc | 7 ++++++- src/server/service_helper.h | 4 ++++ 5 files changed, 34 insertions(+), 6 deletions(-) diff --git a/src/common/tracker.cc b/src/common/tracker.cc index a0aff6f01..f4bb364f9 100644 --- a/src/common/tracker.cc +++ b/src/common/tracker.cc @@ -25,4 +25,8 @@ bvar::LatencyRecorder Tracker::raft_queue_wait_latency("dingo_tracker_raft_queue bvar::LatencyRecorder Tracker::raft_apply_latency("dingo_tracker_raft_apply"); bvar::LatencyRecorder Tracker::read_store_latency("dingo_tracker_read_store"); +bvar::LatencyRecorder Tracker::store_write_latency("dingo_tracker_store_write"); +bvar::LatencyRecorder Tracker::vector_index_write_latency("dingo_tracker_vector_index_write"); +bvar::LatencyRecorder Tracker::document_index_write_latency("dingo_tracker_document_index_write"); + } // namespace dingodb \ No newline at end of file diff --git a/src/common/tracker.h b/src/common/tracker.h index 08c0587ea..046444dba 100644 --- a/src/common/tracker.h +++ b/src/common/tracker.h @@ -98,13 +98,22 @@ class Tracker { } uint64_t RaftApplyTime() const { return metrics_.raft_apply_time_ns; } - void SetStoreWriteTime(uint64_t elapsed_time) { metrics_.store_write_time_ns = elapsed_time; } + void SetStoreWriteTime(uint64_t elapsed_time) { + metrics_.store_write_time_ns = elapsed_time; + store_write_latency << metrics_.store_write_time_ns / 1000; + } uint64_t StoreWriteTime() const { return metrics_.store_write_time_ns; } - void SetVectorIndexWriteTime(uint64_t elapsed_time) { metrics_.vector_index_write_time_ns = elapsed_time; } + void SetVectorIndexWriteTime(uint64_t elapsed_time) { + metrics_.vector_index_write_time_ns = elapsed_time; + vector_index_write_latency << metrics_.vector_index_write_time_ns / 1000; + } uint64_t VectorIndexwriteTime() const { return metrics_.vector_index_write_time_ns; } - void SetDocumentIndexWriteTime(uint64_t elapsed_time) { metrics_.document_index_write_time_ns = elapsed_time; } + void SetDocumentIndexWriteTime(uint64_t elapsed_time) { + metrics_.document_index_write_time_ns = elapsed_time; + document_index_write_latency << metrics_.document_index_write_time_ns / 1000; + } uint64_t DocumentIndexwriteTime() const { return metrics_.document_index_write_time_ns; } void SetReadStoreTime() { @@ -124,6 +133,10 @@ class Tracker { static bvar::LatencyRecorder raft_apply_latency; static bvar::LatencyRecorder read_store_latency; + static bvar::LatencyRecorder store_write_latency; + static bvar::LatencyRecorder vector_index_write_latency; + static bvar::LatencyRecorder document_index_write_latency; + private: uint64_t start_time_; uint64_t last_time_; diff --git a/src/handler/raft_apply_handler.cc b/src/handler/raft_apply_handler.cc index c6e435781..99c8dd55e 100644 --- a/src/handler/raft_apply_handler.cc +++ b/src/handler/raft_apply_handler.cc @@ -1395,12 +1395,11 @@ int DocumentAddHandler::Handle(std::shared_ptr ctx, store::RegionPtr re document_with_id.set_id(document.id()); document_with_ids.push_back(document_with_id); } - auto start_time = Helper::TimestampNs(); auto status = request.is_update() ? document_index_wrapper->Upsert(document_with_ids) : document_index_wrapper->Add(document_with_ids); if (tracker) tracker->SetDocumentIndexWriteTime(Helper::TimestampNs() - start_time); - DINGO_LOG(DEBUG) << fmt::format("[raft.apply][region({})] upsert document, count: {} cost: {}us", + DINGO_LOG(DEBUG) << fmt::format("[raft.apply][region({})] upsert document, count: {} cost: {}ns", document_index_id, document_with_ids.size(), Helper::TimestampNs() - start_time); if (status.ok()) { @@ -1494,6 +1493,9 @@ int DocumentDeleteHandler::Handle(std::shared_ptr ctx, store::RegionPtr auto start_time = Helper::TimestampNs(); auto status = document_index_wrapper->Delete(Helper::PbRepeatedToVector(request.ids())); if (tracker) tracker->SetDocumentIndexWriteTime(Helper::TimestampNs() - start_time); + DINGO_LOG(DEBUG) << fmt::format("[raft.apply][region({})] delete document, count: {} cost: {}ns", + document_index_id, request.ids().size(), + Helper::TimestampNs() - start_time); if (status.ok()) { if (region->GetStoreEngineType() == pb::common::STORE_ENG_RAFT_STORE && log_id != INT64_MAX) { document_index_wrapper->SetApplyLogId(log_id); diff --git a/src/handler/raft_apply_handler_txn.cc b/src/handler/raft_apply_handler_txn.cc index d85ae6b0c..a1ab61786 100644 --- a/src/handler/raft_apply_handler_txn.cc +++ b/src/handler/raft_apply_handler_txn.cc @@ -98,6 +98,7 @@ void TxnHandler::HandleMultiCfPutAndDeleteRequest(std::shared_ptr ctx, "[txn][region({})] HandleMultiCfPutAndDelete fail, term: {} apply_log_id: {}, error: {} request: {}.", region->Id(), term_id, log_id, status.error_str(), request.ShortDebugString()); } + auto tracker = ctx ? ctx->Tracker() : nullptr; // check if need to commit to vector index { @@ -119,6 +120,8 @@ void TxnHandler::HandleMultiCfPutAndDeleteRequest(std::shared_ptr ctx, add_ctx->SetRegionId(region->Id()); add_ctx->SetCfName(Constant::kVectorDataCF); add_ctx->SetRegionEpoch(region->Definition().epoch()); + if (tracker) add_ctx->SetTracker(tracker); + pb::raft::Request raft_request_for_vector_add; for (const auto &vector : vector_add.vectors()) { auto *new_vector = raft_request_for_vector_add.mutable_vector_add()->add_vectors(); @@ -152,7 +155,7 @@ void TxnHandler::HandleMultiCfPutAndDeleteRequest(std::shared_ptr ctx, del_ctx->SetRegionId(region->Id()); del_ctx->SetCfName(Constant::kVectorDataCF); del_ctx->SetRegionEpoch(region->Definition().epoch()); - + if (tracker) del_ctx->SetTracker(tracker); pb::raft::Request raft_request_for_vector_del; for (const auto &id : vector_del.ids()) { raft_request_for_vector_del.mutable_vector_delete()->add_ids(id); @@ -187,6 +190,7 @@ void TxnHandler::HandleMultiCfPutAndDeleteRequest(std::shared_ptr ctx, add_ctx->SetRegionId(region->Id()); add_ctx->SetCfName(Constant::kStoreDataCF); add_ctx->SetRegionEpoch(region->Definition().epoch()); + if (tracker) add_ctx->SetTracker(tracker); pb::raft::Request raft_request_for_document_add; for (const auto &document : document_add.documents()) { auto *new_document = raft_request_for_document_add.mutable_document_add()->add_documents(); @@ -221,6 +225,7 @@ void TxnHandler::HandleMultiCfPutAndDeleteRequest(std::shared_ptr ctx, del_ctx->SetRegionId(region->Id()); del_ctx->SetCfName(Constant::kStoreDataCF); del_ctx->SetRegionEpoch(region->Definition().epoch()); + if (tracker) del_ctx->SetTracker(tracker); pb::raft::Request raft_request_for_document_del; for (const auto &id : document_del.ids()) { raft_request_for_document_del.mutable_document_delete()->add_ids(id); diff --git a/src/server/service_helper.h b/src/server/service_helper.h index 2f70e041d..cc7d32da0 100644 --- a/src/server/service_helper.h +++ b/src/server/service_helper.h @@ -217,6 +217,7 @@ inline void SetPbMessageResponseInfo(google::protobuf::Message* message, Tracker << response_info_field->message_type()->full_name(); return; } + pb::common::ResponseInfo* response_info = dynamic_cast(reflection->MutableMessage(message, response_info_field)); auto* time_info = response_info->mutable_time_info(); @@ -226,6 +227,9 @@ inline void SetPbMessageResponseInfo(google::protobuf::Message* message, Tracker time_info->set_raft_commit_time_ns(tracker->RaftCommitTime()); time_info->set_raft_queue_wait_time_ns(tracker->RaftQueueWaitTime()); time_info->set_raft_apply_time_ns(tracker->RaftApplyTime()); + time_info->set_store_write_time_ns(tracker->StoreWriteTime()); + time_info->set_vector_index_write_time_ns(tracker->VectorIndexwriteTime()); + time_info->set_document_index_write_time_ns(tracker->DocumentIndexwriteTime()); } template