diff --git a/CHANGELOG.md b/CHANGELOG.md index f297472314..7b9a7a16b7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -29,6 +29,7 @@ Please mark all change in change log and use the issue from GitHub - \#1885 Optimize knowhere unittest - \#1886 Refactor log on search and insert request - \#1897 Heap pop and push can be realized by heap_swap_top +- \#1921 Use TimeRecorder instead of chrono ## Task diff --git a/core/src/segment/SegmentWriter.cpp b/core/src/segment/SegmentWriter.cpp index 859d42799c..2c650d4a19 100644 --- a/core/src/segment/SegmentWriter.cpp +++ b/core/src/segment/SegmentWriter.cpp @@ -27,6 +27,7 @@ #include "storage/disk/DiskIOWriter.h" #include "storage/disk/DiskOperation.h" #include "utils/Log.h" +#include "utils/TimeRecorder.h" namespace milvus { namespace segment { @@ -57,7 +58,7 @@ SegmentWriter::SetVectorIndex(const milvus::knowhere::VecIndexPtr& index) { Status SegmentWriter::Serialize() { - auto start = std::chrono::high_resolution_clock::now(); + TimeRecorder recorder("SegmentWriter::Serialize"); auto status = WriteBloomFilter(); if (!status.ok()) { @@ -65,31 +66,20 @@ SegmentWriter::Serialize() { return status; } - auto end = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff = end - start; - ENGINE_LOG_DEBUG << "Writing bloom filter took " << diff.count() << " s in total"; + recorder.RecordSection("Writing bloom filter done"); - start = std::chrono::high_resolution_clock::now(); - - ENGINE_LOG_DEBUG << "Write vectors"; status = WriteVectors(); if (!status.ok()) { ENGINE_LOG_ERROR << "Write vectors fail: " << status.message(); return status; } - end = std::chrono::high_resolution_clock::now(); - diff = end - start; - ENGINE_LOG_DEBUG << "Writing vectors and uids took " << diff.count() << " s in total"; - - start = std::chrono::high_resolution_clock::now(); + recorder.RecordSection("Writing vectors and uids done"); // Write an empty deleted doc status = WriteDeletedDocs(); - end = std::chrono::high_resolution_clock::now(); - diff = end - start; - ENGINE_LOG_DEBUG << "Writing deleted docs took " << diff.count() << " s"; + recorder.RecordSection("Writing deleted docs done"); return status; } @@ -128,32 +118,22 @@ SegmentWriter::WriteBloomFilter() { try { fs_ptr_->operation_ptr_->CreateDirectory(); - auto start = std::chrono::high_resolution_clock::now(); + TimeRecorder recorder("SegmentWriter::WriteBloomFilter"); default_codec.GetIdBloomFilterFormat()->create(fs_ptr_, segment_ptr_->id_bloom_filter_ptr_); - auto end = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff = end - start; - ENGINE_LOG_DEBUG << "Initializing bloom filter took " << diff.count() << " s"; - - start = std::chrono::high_resolution_clock::now(); + recorder.RecordSection("Initializing bloom filter"); auto& uids = segment_ptr_->vectors_ptr_->GetUids(); for (auto& uid : uids) { segment_ptr_->id_bloom_filter_ptr_->Add(uid); } - end = std::chrono::high_resolution_clock::now(); - diff = end - start; - ENGINE_LOG_DEBUG << "Adding " << uids.size() << " ids to bloom filter took " << diff.count() << " s"; - - start = std::chrono::high_resolution_clock::now(); + recorder.RecordSection("Adding " + std::to_string(uids.size()) + " ids to bloom filter"); default_codec.GetIdBloomFilterFormat()->write(fs_ptr_, segment_ptr_->id_bloom_filter_ptr_); - end = std::chrono::high_resolution_clock::now(); - diff = end - start; - ENGINE_LOG_DEBUG << "Writing bloom filter took " << diff.count() << " s"; + recorder.RecordSection("Writing bloom filter"); } catch (std::exception& e) { std::string err_msg = "Failed to write vectors: " + std::string(e.what()); ENGINE_LOG_ERROR << err_msg; @@ -225,7 +205,7 @@ SegmentWriter::Merge(const std::string& dir_to_merge, const std::string& name) { ENGINE_LOG_DEBUG << "Merging from " << dir_to_merge << " to " << fs_ptr_->operation_ptr_->GetDirectory(); - auto start = std::chrono::high_resolution_clock::now(); + TimeRecorder recorder("SegmentWriter::Merge"); SegmentReader segment_reader_to_merge(dir_to_merge); bool in_cache; @@ -242,9 +222,7 @@ SegmentWriter::Merge(const std::string& dir_to_merge, const std::string& name) { segment_reader_to_merge.GetSegment(segment_to_merge); auto& uids = segment_to_merge->vectors_ptr_->GetUids(); - auto end = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff = end - start; - ENGINE_LOG_DEBUG << "Loading segment took " << diff.count() << " s"; + recorder.RecordSection("Loading segment"); if (segment_to_merge->deleted_docs_ptr_ != nullptr) { auto offsets_to_delete = segment_to_merge->deleted_docs_ptr_->GetDeletedDocs(); @@ -253,14 +231,12 @@ SegmentWriter::Merge(const std::string& dir_to_merge, const std::string& name) { segment_to_merge->vectors_ptr_->Erase(offsets_to_delete); } - start = std::chrono::high_resolution_clock::now(); + recorder.RecordSection("erase"); AddVectors(name, segment_to_merge->vectors_ptr_->GetData(), segment_to_merge->vectors_ptr_->GetUids()); - end = std::chrono::high_resolution_clock::now(); - diff = end - start; - ENGINE_LOG_DEBUG << "Adding " << segment_to_merge->vectors_ptr_->GetCount() << " vectors and uids took " - << diff.count() << " s"; + auto rows = segment_to_merge->vectors_ptr_->GetCount(); + recorder.RecordSection("Adding " + std::to_string(rows) + " vectors and uids"); ENGINE_LOG_DEBUG << "Merging completed from " << dir_to_merge << " to " << fs_ptr_->operation_ptr_->GetDirectory(); diff --git a/core/src/segment/Vectors.cpp b/core/src/segment/Vectors.cpp index 04c68d5186..67b6ec4c31 100644 --- a/core/src/segment/Vectors.cpp +++ b/core/src/segment/Vectors.cpp @@ -18,12 +18,12 @@ #include "segment/Vectors.h" #include -#include #include #include #include #include "utils/Log.h" +#include "utils/TimeRecorder.h" namespace milvus { namespace segment { @@ -61,21 +61,15 @@ Vectors::Erase(std::vector& offsets) { } // Sort and remove duplicates - auto start = std::chrono::high_resolution_clock::now(); + TimeRecorder recorder("Vectors::Erase"); std::sort(offsets.begin(), offsets.end()); - auto end = std::chrono::high_resolution_clock::now(); - std::chrono::duration diff = end - start; - ENGINE_LOG_DEBUG << "Sorting " << offsets.size() << " offsets to delete took " << diff.count() << " s"; - - start = std::chrono::high_resolution_clock::now(); + recorder.RecordSection("Sorting " + std::to_string(offsets.size()) + " offsets to delete"); offsets.erase(std::unique(offsets.begin(), offsets.end()), offsets.end()); - end = std::chrono::high_resolution_clock::now(); - diff = end - start; - ENGINE_LOG_DEBUG << "Deduplicating " << offsets.size() << " offsets to delete took " << diff.count() << " s"; + recorder.RecordSection("Deduplicating " + std::to_string(offsets.size()) + " offsets to delete"); // Reconstruct raw vectors and uids ENGINE_LOG_DEBUG << "Begin erasing..."; @@ -114,10 +108,9 @@ Vectors::Erase(std::vector& offsets) { data_.swap(new_data); uids_.swap(new_uids); - end = std::chrono::high_resolution_clock::now(); - diff = end - start; - ENGINE_LOG_DEBUG << "Erasing " << offsets.size() << " vectors out of " << loop_size << " vectors took " - << diff.count() << " s"; + std::string msg = + "Erasing " + std::to_string(offsets.size()) + " vectors out of " + std::to_string(loop_size) + " vectors"; + recorder.RecordSection(msg); } const std::vector&