refine log (#3991)

* refine log
Signed-off-by: Ngroot <yihua.mo@zilliz.com>

* refine log
Signed-off-by: Ngroot <yihua.mo@zilliz.com>

core/src/db/DBImpl.cpp

@@ -349,7 +349,7 @@ Status
 DBImpl::CreateIndex(const std::shared_ptr<server::Context>& context, const std::string& collection_name,
                     const std::string& field_name, const CollectionIndex& index) {
     CHECK_AVAILABLE
-
+    SetThreadName("create_index");
     LOG_ENGINE_DEBUG_ << "Create index for collection: " << collection_name << " field: " << field_name;
 
     // step 1: wait merge file thread finished to avoid duplicate data bug
@@ -586,7 +586,7 @@ DBImpl::Insert(const std::string& collection_name, const std::string& partition_
 
         std::set<int64_t> collection_ids;
         if (mem_mgr_->RequireFlush(collection_ids)) {
-            LOG_ENGINE_DEBUG_ << LogOut("[%s][%ld] ", "insert", 0) << "Insert buffer size exceeds limit. Force flush";
+            LOG_ENGINE_DEBUG_ << "Insert buffer size exceeds limit. Force flush";
             InternalFlush();
         }
     }
@@ -625,7 +625,7 @@ DBImpl::DeleteEntityByID(const std::string& collection_name, const engine::IDNum
     snapshot::ScopedSnapshotT ss;
     auto status = snapshot::Snapshots::GetInstance().GetSnapshot(ss, collection_name);
     if (!status.ok()) {
-        LOG_WAL_ERROR_ << LogOut("[%s][%ld] ", "delete", 0) << "Get snapshot fail: " << status.message();
+        LOG_ENGINE_DEBUG_ << "Failed to get snapshot: " << status.message();
         return status;
     }
 
@@ -637,8 +637,7 @@ DBImpl::DeleteEntityByID(const std::string& collection_name, const engine::IDNum
     std::set<int64_t> collection_ids;
     if (mem_mgr_->RequireFlush(collection_ids)) {
         if (collection_ids.find(ss->GetCollectionId()) != collection_ids.end()) {
-            LOG_ENGINE_DEBUG_ << LogOut("[%s][%ld] ", "delete", 0)
-                              << "Delete count in buffer exceeds limit. Force flush";
+            LOG_ENGINE_DEBUG_ << "Delete count in buffer exceeds limit. Force flush";
             InternalFlush(collection_name);
         }
     }
@@ -649,8 +648,8 @@ DBImpl::DeleteEntityByID(const std::string& collection_name, const engine::IDNum
 Status
 DBImpl::Query(const server::ContextPtr& context, const query::QueryPtr& query_ptr, engine::QueryResultPtr& result) {
     CHECK_AVAILABLE
-
-    TimeRecorder rc("DBImpl::Query");
+    SetThreadName("query");
+    TimeRecorderAuto rc("DBImpl::Query");
 
     if (!query_ptr->root) {
         return Status{DB_ERROR, "BinaryQuery is null"};
@@ -662,7 +661,7 @@ DBImpl::Query(const server::ContextPtr& context, const query::QueryPtr& query_pt
     SnapshotVisitor ss_visitor(ss);
     snapshot::IDS_TYPE segment_ids;
     STATUS_CHECK(ss_visitor.SegmentsToSearch(query_ptr->partitions, segment_ids));
-    LOG_ENGINE_DEBUG_ << LogOut("Engine query begin, segment count: %ld", segment_ids.size());
+    rc.RecordSection("segments to search: " + std::to_string(segment_ids.size()));
 
     scheduler::SearchJobPtr job = std::make_shared<scheduler::SearchJob>(nullptr, ss, options_, query_ptr, segment_ids);
 
@@ -685,12 +684,14 @@ DBImpl::Query(const server::ContextPtr& context, const query::QueryPtr& query_pt
     if (job->query_result()) {
         result = job->query_result();
     }
+    rc.RecordSection("execute query");
 
     // step 4: get entities by result ids
     std::vector<bool> valid_row;
     if (!query_ptr->field_names.empty()) {
         STATUS_CHECK(GetEntityByID(query_ptr->collection_id, result->result_ids_, query_ptr->field_names, valid_row,
                                    result->data_chunk_));
+        rc.RecordSection("get entities");
     }
 
     // step 5: filter entities by field names
@@ -708,8 +709,6 @@ DBImpl::Query(const server::ContextPtr& context, const query::QueryPtr& query_pt
     //        filter_attrs.emplace_back(attrs_data);
     //    }
 
-    rc.ElapseFromBegin("Engine query totally cost");
-
     // tracer.Context()->GetTraceContext()->GetSpan()->Finish();
 
     return Status::OK();
@@ -885,7 +884,7 @@ DBImpl::InternalFlush(const std::string& collection_name, bool merge) {
         snapshot::ScopedSnapshotT ss;
         status = snapshot::Snapshots::GetInstance().GetSnapshot(ss, collection_name);
         if (!status.ok()) {
-            LOG_WAL_ERROR_ << LogOut("[%s][%ld] ", "flush", 0) << "Get snapshot fail: " << status.message();
+            LOG_WAL_ERROR_ << "Failed to get snapshot: " << status.message();
             return;
         }
 

core/src/db/insert/MemSegment.cpp

@@ -298,7 +298,11 @@ MemSegment::PutChunksToWriter(const segment::SegmentWriterPtr& writer) {
 
         // copy data to writer
         writer->AddChunk(chunk);
+
+        // free memory immediately since the data has been added into writer
+        action.insert_data_ = nullptr;
     }
+    actions_.clear();
 
     return Status::OK();
 }

core/src/scheduler/JobMgr.cpp

@@ -21,6 +21,7 @@
 #include "scheduler/selector/Optimizer.h"
 #include "scheduler/task/Task.h"
 #include "scheduler/tasklabel/SpecResLabel.h"
+#include "utils/TimeRecorder.h"
 
 namespace milvus {
 namespace scheduler {
@@ -73,14 +74,18 @@ JobMgr::worker_function() {
         //            search_job->GetResultDistances().resize(search_job->nq(), std::numeric_limits<float>::max());
         //        }
 
+        TimeRecorder rc("JobMgr");
         auto tasks = build_task(job);
+        rc.RecordSection("build_tasks");
         for (auto& task : tasks) {
             OptimizerInst::GetInstance()->Run(task);
         }
+        rc.RecordSection("optimize");
 
         for (auto& task : tasks) {
             calculate_path(res_mgr_, task);
         }
+        rc.RecordSection("calculate path");
 
         // disk resources NEVER be empty.
         if (auto disk = res_mgr_->GetDiskResources()[0].lock()) {

core/src/scheduler/selector/FaissIVFPass.cpp

@@ -58,7 +58,7 @@ FaissIVFPass::Run(const TaskPtr& task) {
         LOG_SERVER_DEBUG_ << LogOut("FaissIVFPass: gpu disable, specify cpu to search!");
         res_ptr = ResMgrInst::GetInstance()->GetResource("cpu");
     } else if (search_task->nq() < threshold_) {
-        LOG_SERVER_DEBUG_ << LogOut("FaissIVFPass: nq < gpu_search_threshold, specify cpu to search! ");
+        LOG_SERVER_DEBUG_ << LogOut("FaissIVFPass: nq < gpu_search_threshold, specify cpu to search!");
         res_ptr = ResMgrInst::GetInstance()->GetResource("cpu");
     } else if (search_task->topk() > server::GPU_QUERY_MAX_TOPK) {
         LOG_SERVER_DEBUG_ << LogOut("FaissIVFPass: topk > gpu_max_topk_threshold, specify cpu to search!");

core/src/server/delivery/request/CountEntitiesReq.cpp

@@ -46,8 +46,6 @@ CountEntitiesReq::OnExecute() {
         }
 
         STATUS_CHECK(DBWrapper::DB()->CountEntities(collection_name_, row_count_));
-
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/CreateCollectionReq.cpp

@@ -115,8 +115,6 @@ CreateCollectionReq::OnExecute() {
             }
             return status;
         }
-
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/CreateIndexReq.cpp

@@ -45,7 +45,7 @@ CreateIndexReq::Create(const ContextPtr& context, const std::string& collection_
 Status
 CreateIndexReq::OnExecute() {
     try {
-        std::string hdr = "CreateIndexReq(collection=" + collection_name_ + ")";
+        std::string hdr = "CreateIndexReq(collection=" + collection_name_ + +" field=" + field_name_ + ")";
         TimeRecorderAuto rc(hdr);
 
         // step 1: check arguments
@@ -127,7 +127,6 @@ CreateIndexReq::OnExecute() {
         }
 
         STATUS_CHECK(DBWrapper::DB()->CreateIndex(context_, collection_name_, field_name_, index));
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/CreatePartitionReq.cpp

@@ -40,7 +40,7 @@ CreatePartitionReq::Create(const ContextPtr& context, const std::string& collect
 Status
 CreatePartitionReq::OnExecute() {
     try {
-        std::string hdr = "CreatePartitionReq(collection=" + collection_name_ + ", partition_tag=" + tag_ + ")";
+        std::string hdr = "CreatePartitionReq(collection=" + collection_name_ + ", partition=" + tag_ + ")";
         TimeRecorderAuto rc(hdr);
 
         // step 1: check arguments
@@ -77,7 +77,6 @@ CreatePartitionReq::OnExecute() {
         fiu_do_on("CreatePartitionReq.OnExecute.create_partition_fail",
                   status = Status(milvus::SERVER_UNEXPECTED_ERROR, ""));
         fiu_do_on("CreatePartitionRequest.OnExecute.throw_std_exception", throw std::exception());
-        rc.ElapseFromBegin("done");
         return status;
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());

core/src/server/delivery/request/DeleteEntityByIDReq.cpp

@@ -44,7 +44,7 @@ DeleteEntityByIDReq::Create(const ContextPtr& context, const std::string& collec
 Status
 DeleteEntityByIDReq::OnExecute() {
     try {
-        TimeRecorderAuto rc("DeleteEntityByIDReq");
+        TimeRecorderAuto rc("DeleteEntityByIDReq(collection=" + collection_name_ + ")");
 
         bool exist = false;
         STATUS_CHECK(DBWrapper::DB()->HasCollection(collection_name_, exist));
@@ -53,7 +53,6 @@ DeleteEntityByIDReq::OnExecute() {
         }
 
         STATUS_CHECK(DBWrapper::DB()->DeleteEntityByID(collection_name_, entity_ids_));
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/DescribeIndexReq.cpp

@@ -46,7 +46,7 @@ DescribeIndexReq::Create(const std::shared_ptr<milvus::server::Context>& context
 Status
 DescribeIndexReq::OnExecute() {
     try {
-        std::string hdr = "DescribeIndexReq(collection=" + collection_name_ + ")";
+        std::string hdr = "DescribeIndexReq(collection=" + collection_name_ + " field=" + field_name_ + ")";
         TimeRecorderAuto rc(hdr);
 
         // step 1: check arguments

core/src/server/delivery/request/DropCollectionReq.cpp

@@ -31,7 +31,7 @@ Status
 DropCollectionReq::OnExecute() {
     try {
         std::string hdr = "DropCollectionReq(collection=" + collection_name_ + ")";
-        TimeRecorder rc(hdr);
+        TimeRecorderAuto rc(hdr);
 
         STATUS_CHECK(ValidateCollectionName(collection_name_));
 
@@ -42,8 +42,6 @@ DropCollectionReq::OnExecute() {
         }
 
         STATUS_CHECK(DBWrapper::DB()->DropCollection(collection_name_));
-
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/DropIndexReq.cpp

@@ -41,7 +41,7 @@ Status
 DropIndexReq::OnExecute() {
     try {
         fiu_do_on("DropIndexReq.OnExecute.throw_std_exception", throw std::exception());
-        std::string hdr = "DropIndexReq(collection=" + collection_name_ + ")";
+        std::string hdr = "DropIndexReq(collection=" + collection_name_ + " filed=" + field_name_ + ")";
         TimeRecorderAuto rc(hdr);
 
         bool exist = false;
@@ -56,7 +56,6 @@ DropIndexReq::OnExecute() {
         if (!status.ok()) {
             return status;
         }
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/DropPartitionReq.cpp

@@ -35,7 +35,7 @@ DropPartitionReq::Create(const ContextPtr& context, const std::string& collectio
 Status
 DropPartitionReq::OnExecute() {
     try {
-        std::string hdr = "DropPartitionReq(collection=" + collection_name_ + ", partition_tag=" + tag_ + ")";
+        std::string hdr = "DropPartitionReq(collection=" + collection_name_ + ", partition=" + tag_ + ")";
         TimeRecorderAuto rc(hdr);
 
         /* check partition tag */

core/src/server/delivery/request/GetCollectionInfoReq.cpp

@@ -77,8 +77,6 @@ GetCollectionInfoReq::OnExecute() {
 
             collection_schema_.fields_.insert(std::make_pair(field_name, field_schema));
         }
-
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/GetCollectionStatsReq.cpp

@@ -54,7 +54,6 @@ GetCollectionStatsReq::OnExecute() {
         milvus::json json_stats;
         STATUS_CHECK(DBWrapper::DB()->GetCollectionStats(collection_name_, json_stats));
         collection_stats_ = json_stats.dump();
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/GetEntityByIDReq.cpp

@@ -107,7 +107,6 @@ GetEntityByIDReq::OnExecute() {
         // step 2: get vector data, now only support get one id
         STATUS_CHECK(
             DBWrapper::DB()->GetEntityByID(collection_name_, id_array_, field_names_, valid_row_, data_chunk_));
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/HasCollectionReq.cpp

@@ -37,8 +37,6 @@ HasCollectionReq::OnExecute() {
 
         STATUS_CHECK(ValidateCollectionName(collection_name_));
         STATUS_CHECK(DBWrapper::DB()->HasCollection(collection_name_, exist_));
-
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/HasPartitionReq.cpp

@@ -39,7 +39,7 @@ HasPartitionReq::Create(const ContextPtr& context, const std::string& collection
 Status
 HasPartitionReq::OnExecute() {
     try {
-        std::string hdr = "HasPartitionReq(collection=" + collection_name_ + " tag=" + partition_tag_ + ")";
+        std::string hdr = "HasPartitionReq(collection=" + collection_name_ + " partition=" + partition_tag_ + ")";
         TimeRecorderAuto rc(hdr);
 
         has_partition_ = false;
@@ -54,7 +54,6 @@ HasPartitionReq::OnExecute() {
         }
 
         STATUS_CHECK(DBWrapper::DB()->HasPartition(collection_name_, partition_tag_, has_partition_));
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/InsertReq.cpp

@@ -78,10 +78,10 @@ InsertReq::Create(const ContextPtr& context, const std::string& collection_name,
 
 Status
 InsertReq::OnExecute() {
-    LOG_SERVER_INFO_ << LogOut("[%s][%ld] ", "insert", 0) << "Execute InsertReq.";
     try {
-        std::string hdr = "InsertReq(collection=" + collection_name_ + ", partition_name=" + partition_name_ + ")";
-        TimeRecorder rc(hdr);
+        std::string hdr = "InsertReq(collection=" + collection_name_ + ", partition=" + partition_name_ + ")";
+        LOG_SERVER_DEBUG_ << hdr << " begin";
+        TimeRecorderAuto rc(hdr);
 
         if (insert_param_.row_count_ == 0 || insert_param_.fields_data_.empty()) {
             return Status{SERVER_INVALID_ARGUMENT, "The field is empty, make sure you have entered entities"};
@@ -121,8 +121,6 @@ InsertReq::OnExecute() {
         int64_t num = iter->second->data_.size() / sizeof(int64_t);
         insert_param_.id_returned_.resize(num);
         memcpy(insert_param_.id_returned_.data(), iter->second->data_.data(), iter->second->data_.size());
-
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/ListCollectionsReq.cpp

@@ -38,7 +38,6 @@ ListCollectionsReq::OnExecute() {
     if (!status.ok()) {
         return status;
     }
-    rc.ElapseFromBegin("done");
     return Status::OK();
 }
 

core/src/server/delivery/request/ListIDInSegmentReq.cpp

@@ -57,7 +57,6 @@ ListIDInSegmentReq::OnExecute() {
         // step 2: get vector data, now only support get one id
         ids_.clear();
         STATUS_CHECK(DBWrapper::DB()->ListIDInSegment(collection_name_, segment_id_, ids_));
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/ListPartitionsReq.cpp

@@ -47,7 +47,6 @@ ListPartitionsReq::OnExecute() {
 
     /* get partitions */
     STATUS_CHECK(DBWrapper::DB()->ListPartitions(collection_name_, partition_list_));
-    rc.ElapseFromBegin("done");
 
     return Status::OK();
 }

core/src/server/delivery/request/LoadCollectionReq.cpp

@@ -63,8 +63,6 @@ LoadCollectionReq::OnExecute() {
         if (!status.ok()) {
             return status;
         }
-
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }

core/src/server/delivery/request/SearchReq.cpp

@@ -50,8 +50,9 @@ Status
 SearchReq::OnExecute() {
     try {
         fiu_do_on("SearchReq.OnExecute.throw_std_exception", throw std::exception());
-        std::string hdr = "SearchReq(table=" + query_ptr_->collection_id;
-        TimeRecorder rc(hdr);
+        std::string hdr = "SearchReq(collection=" + query_ptr_->collection_id + ")";
+        LOG_SERVER_DEBUG_ << hdr << " begin";
+        TimeRecorderAuto rc(hdr);
 
         STATUS_CHECK(ValidateCollectionName(query_ptr_->collection_id));
         //        STATUS_CHECK(ValidatePartitionTags(query_ptr_->partitions));
@@ -161,7 +162,6 @@ SearchReq::OnExecute() {
 
         // step 8: print time cost percent
         rc.RecordSection("construct result and send");
-        rc.ElapseFromBegin("done");
     } catch (std::exception& ex) {
         return Status(SERVER_UNEXPECTED_ERROR, ex.what());
     }