diff --git a/core/src/db/insert/MemTable.cpp b/core/src/db/insert/MemTable.cpp index d572ef967e..d1d498e8d1 100644 --- a/core/src/db/insert/MemTable.cpp +++ b/core/src/db/insert/MemTable.cpp @@ -22,6 +22,7 @@ #include "knowhere/index/vector_index/VecIndex.h" #include "segment/SegmentReader.h" #include "utils/Log.h" +#include "utils/TimeRecorder.h" namespace milvus { namespace engine { @@ -126,7 +127,7 @@ MemTable::GetTableFileCount() { Status MemTable::Serialize(uint64_t wal_lsn, bool apply_delete) { - auto start = std::chrono::high_resolution_clock::now(); + TimeRecorder recorder("MemTable::Serialize collection " + collection_id_); if (!doc_ids_to_delete_.empty() && apply_delete) { auto status = ApplyDeletes(); @@ -157,9 +158,7 @@ MemTable::Serialize(uint64_t wal_lsn, bool apply_delete) { return Status(DB_ERROR, err_msg); } - auto end = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff = end - start; - LOG_ENGINE_DEBUG_ << "Finished flushing for collection " << collection_id_ << " in " << diff.count() << " s"; + recorder.RecordSection("Finished flushing"); return Status::OK(); } @@ -203,9 +202,7 @@ MemTable::ApplyDeletes() { LOG_ENGINE_DEBUG_ << "Applying " << doc_ids_to_delete_.size() << " deletes in collection: " << collection_id_; - auto start_total = std::chrono::high_resolution_clock::now(); - - // auto start = std::chrono::high_resolution_clock::now(); + TimeRecorder recorder("MemTable::ApplyDeletes for collection " + collection_id_); std::vector file_types{meta::SegmentSchema::FILE_TYPE::RAW, meta::SegmentSchema::FILE_TYPE::TO_INDEX, meta::SegmentSchema::FILE_TYPE::BACKUP}; @@ -246,10 +243,7 @@ MemTable::ApplyDeletes() { OngoingFileChecker::GetInstance().MarkOngoingFiles(files_to_check); - auto time0 = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff0 = time0 - start_total; - LOG_ENGINE_DEBUG_ << "Found " << ids_to_check_map.size() << " segment to apply deletes in " << diff0.count() - << " s"; + recorder.RecordSection("Found " + std::to_string(ids_to_check_map.size()) + " segment to apply deletes"); meta::SegmentsSchema table_files_to_update; @@ -257,7 +251,7 @@ MemTable::ApplyDeletes() { auto& table_file = table_files[kv.first]; LOG_ENGINE_DEBUG_ << "Applying deletes in segment: " << table_file.segment_id_; - auto time1 = std::chrono::high_resolution_clock::now(); + TimeRecorder rec("handle segment " + table_file.segment_id_); std::string segment_dir; utils::GetParentPath(table_file.location_, segment_dir); @@ -300,15 +294,11 @@ MemTable::ApplyDeletes() { segment::DeletedDocsPtr deleted_docs = std::make_shared(); - auto time2 = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff1 = time2 - time1; - LOG_ENGINE_DEBUG_ << "Loading uids and deleted docs took " << diff1.count() << " s"; + rec.RecordSection("Loading uids and deleted docs"); std::sort(ids_to_check.begin(), ids_to_check.end()); - auto time3 = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff2 = time3 - time2; - LOG_ENGINE_DEBUG_ << "Sorting " << ids_to_check.size() << " ids took " << diff2.count() << " s"; + rec.RecordSection("Sorting " + std::to_string(ids_to_check.size()) + " ids"); size_t delete_count = 0; auto find_diff = std::chrono::duration::zero(); @@ -348,14 +338,12 @@ MemTable::ApplyDeletes() { << find_diff.count() << " s in total"; LOG_ENGINE_DEBUG_ << "Setting deleted docs and bloom filter took " << set_diff.count() << " s in total"; - auto time4 = std::chrono::high_resolution_clock::now(); + rec.RecordSection("Find uids and set deleted docs and bloom filter"); for (auto i = 0; i < indexes.size(); ++i) { indexes[i]->SetBlacklist(blacklists[i]); } - // start = std::chrono::high_resolution_clock::now(); - segment::Segment tmp_segment; segment::SegmentWriter segment_writer(segment_dir); status = segment_writer.WriteDeletedDocs(deleted_docs); @@ -363,22 +351,14 @@ MemTable::ApplyDeletes() { break; } - auto time5 = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff4 = time5 - time4; - LOG_ENGINE_DEBUG_ << "Appended " << deleted_docs->GetSize() - << " offsets to deleted docs in segment: " << table_file.segment_id_ << " in " - << diff4.count() << " s"; - - // start = std::chrono::high_resolution_clock::now(); + rec.RecordSection("Appended " + std::to_string(deleted_docs->GetSize()) + " offsets to deleted docs"); status = segment_writer.WriteBloomFilter(id_bloom_filter_ptr); if (!status.ok()) { break; } - auto time6 = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff5 = time6 - time5; - LOG_ENGINE_DEBUG_ << "Updated bloom filter in segment: " << table_file.segment_id_ << " in " << diff5.count() - << " s"; + + rec.RecordSection("Updated bloom filter"); // Update collection file row count for (auto& file : segment_files) { @@ -388,14 +368,10 @@ MemTable::ApplyDeletes() { table_files_to_update.emplace_back(file); } } - auto time7 = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff6 = time7 - time6; - diff6 = time6 - time5; - LOG_ENGINE_DEBUG_ << "Update collection file row count in vector of segment: " << table_file.segment_id_ - << " in " << diff6.count() << " s"; + rec.RecordSection("Update collection file row count in vector"); } - auto time7 = std::chrono::high_resolution_clock::now(); + recorder.RecordSection("Finished " + std::to_string(ids_to_check_map.size()) + " segment to apply deletes"); status = meta_->UpdateCollectionFilesRowCount(table_files_to_update); @@ -407,11 +383,8 @@ MemTable::ApplyDeletes() { doc_ids_to_delete_.clear(); - auto end_total = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff7 = end_total - time7; - LOG_ENGINE_DEBUG_ << "Update deletes to meta in collection " << collection_id_ << " in " << diff7.count() << " s"; - std::chrono::duration diff_total = end_total - start_total; - LOG_ENGINE_DEBUG_ << "Finished deletes in collection " << collection_id_ << " in " << diff_total.count() << " s"; + recorder.RecordSection("Update deletes to meta"); + recorder.ElapseFromBegin("Finished deletes"); OngoingFileChecker::GetInstance().UnmarkOngoingFiles(files_to_check);