use TimeRecorder instead of chrono (#1989)

Signed-off-by: Tracy199 <houkx@vip.sina.com>
This commit is contained in:
Tracy199 2020-04-20 09:29:11 +08:00 committed by GitHub
parent 008f24a7c2
commit c50de3de9a
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

View File

@ -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<double> 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<int> 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<double> 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<segment::DeletedDocs>();
auto time2 = std::chrono::high_resolution_clock::now();
std::chrono::duration<double> 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<double> 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<double>::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<double> 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<double> 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<double> 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<double> diff7 = end_total - time7;
LOG_ENGINE_DEBUG_ << "Update deletes to meta in collection " << collection_id_ << " in " << diff7.count() << " s";
std::chrono::duration<double> 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);