[fix][store] Add time statistics

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

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_;

src/handler/raft_apply_handler.cc

@@ -1395,12 +1395,11 @@ int DocumentAddHandler::Handle(std::shared_ptr<Context> 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<Context> 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);

src/handler/raft_apply_handler_txn.cc

@@ -98,6 +98,7 @@ void TxnHandler::HandleMultiCfPutAndDeleteRequest(std::shared_ptr<Context> 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<Context> 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<Context> 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<Context> 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<Context> 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);

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<pb::common::ResponseInfo*>(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 <typename T, typename U, bool need_region>