#1921 use TimeRecorder instead of chrono (#1922)

Signed-off-by: yudong.cai <yudong.cai@zilliz.com>
This commit is contained in:
Cai Yudong 2020-04-13 18:42:31 +08:00 committed by GitHub
parent f8a28699b4
commit a63d832772
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 22 additions and 52 deletions

View File

@ -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

View File

@ -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<double> 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<double> 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<double> 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();

View File

@ -18,12 +18,12 @@
#include "segment/Vectors.h"
#include <algorithm>
#include <chrono>
#include <iostream>
#include <utility>
#include <vector>
#include "utils/Log.h"
#include "utils/TimeRecorder.h"
namespace milvus {
namespace segment {
@ -61,21 +61,15 @@ Vectors::Erase(std::vector<int32_t>& 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<double> 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<int32_t>& 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<uint8_t>&