#274 logger the time cost during preloading data

CHANGELOG.md

@@ -50,6 +50,7 @@ Please mark all change in change log and use the ticket from JIRA.
 - \#255 - Add ivfsq8 test report detailed version
 - \#260 - C++ SDK README
 - \#266 - Rpc request source code refactor
+- \#274 - Logger the time cost during preloading data
 - \#275 - Rename C++ SDK IndexType
 - \#284 - Change C++ SDK to shared library
 - \#306 - Use int64 for all config integer

core/src/db/DBImpl.cpp

@@ -182,7 +182,7 @@ DBImpl::PreloadTable(const std::string& table_id) {
         return SHUTDOWN_ERROR;
     }
 
-    // get all table files from parent table
+    // step 1: get all table files from parent table
     meta::DatesT dates;
     std::vector<size_t> ids;
     meta::TableFilesSchema files_array;
@@ -191,7 +191,7 @@ DBImpl::PreloadTable(const std::string& table_id) {
         return status;
     }
 
-    // get files from partition tables
+    // step 2: get files from partition tables
     std::vector<meta::TableSchema> partiton_array;
     status = meta_ptr_->ShowPartitions(table_id, partiton_array);
     for (auto& schema : partiton_array) {
@@ -203,6 +203,10 @@ DBImpl::PreloadTable(const std::string& table_id) {
     int64_t cache_usage = cache::CpuCacheMgr::GetInstance()->CacheUsage();
     int64_t available_size = cache_total - cache_usage;
 
+    // step 3: load file one by one
+    ENGINE_LOG_DEBUG << "Begin pre-load table:" + table_id + ", totally " << files_array.size()
+                     << " files need to be pre-loaded";
+    TimeRecorderAuto rc("Pre-load table:" + table_id);
     for (auto& file : files_array) {
         ExecutionEnginePtr engine = EngineFactory::Build(file.dimension_, file.location_, (EngineType)file.engine_type_,
                                                          (MetricType)file.metric_type_, file.nlist_);
@@ -213,10 +217,12 @@ DBImpl::PreloadTable(const std::string& table_id) {
 
         size += engine->PhysicalSize();
         if (size > available_size) {
+            ENGINE_LOG_DEBUG << "Pre-load canceled since cache almost full";
             return Status(SERVER_CACHE_FULL, "Cache is full");
         } else {
             try {
-                // step 1: load index
+                std::string msg = "Pre-loaded file: " + file.file_id_ + " size: " + std::to_string(file.file_size_);
+                TimeRecorderAuto rc_1(msg);
                 engine->Load(true);
             } catch (std::exception& ex) {
                 std::string msg = "Pre-load table encounter exception: " + std::string(ex.what());

core/src/utils/TimeRecorder.cpp

@@ -96,4 +96,11 @@ TimeRecorder::ElapseFromBegin(const std::string& msg) {
     return span;
 }
 
+TimeRecorderAuto::TimeRecorderAuto(const std::string& header, int64_t log_level) : TimeRecorder(header, log_level) {
+}
+
+TimeRecorderAuto::~TimeRecorderAuto() {
+    ElapseFromBegin("totally cost");
+}
+
 }  // namespace milvus

core/src/utils/TimeRecorder.h

@@ -28,7 +28,7 @@ class TimeRecorder {
  public:
     explicit TimeRecorder(const std::string& header, int64_t log_level = 1);
 
-    ~TimeRecorder();  // trace = 0, debug = 1, info = 2, warn = 3, error = 4, critical = 5
+    virtual ~TimeRecorder();  // trace = 0, debug = 1, info = 2, warn = 3, error = 4, critical = 5
 
     double
     RecordSection(const std::string& msg);
@@ -50,4 +50,11 @@ class TimeRecorder {
     int64_t log_level_;
 };
 
+class TimeRecorderAuto : public TimeRecorder {
+ public:
+    explicit TimeRecorderAuto(const std::string& header, int64_t log_level = 1);
+
+    ~TimeRecorderAuto();
+};
+
 }  // namespace milvus