Add more info logging (#31)

Summary:
Adding some more info log logging to track blob file live cycle.

Test Plan:
Existing test.
Signed-off-by: Yi Wu <yiwu@pingcap.com>

src/blob_gc_job.cc

 #include "blob_gc_job.h"
 
+#ifndef __STDC_FORMAT_MACROS
+#define __STDC_FORMAT_MACROS
+#endif
+
+#include <inttypes.h>
+
 namespace rocksdb {
 namespace titandb {
 
@@ -306,6 +312,9 @@ Status BlobGCJob::DoRunGC() {
       if (!s.ok()) {
         break;
       }
+      ROCKS_LOG_INFO(db_options_.info_log,
+                     "Titan new GC output file %" PRIu64 ".",
+                     blob_file_handle->GetNumber());
       blob_file_builder = std::unique_ptr<BlobFileBuilder>(
           new BlobFileBuilder(db_options_, blob_gc_->titan_cf_options(),
                               blob_file_handle->GetFile()));
@@ -420,7 +429,20 @@ Status BlobGCJob::Finish() {
   {
     mutex_->Unlock();
     s = InstallOutputBlobFiles();
-    if (s.ok()) s = RewriteValidKeyToLSM();
+    if (s.ok()) {
+      s = RewriteValidKeyToLSM();
+      if (!s.ok()) {
+        ROCKS_LOG_ERROR(db_options_.info_log,
+                        "[%s] GC job failed to rewrite keys to LSM: %s",
+                        blob_gc_->column_family_handle()->GetName().c_str(),
+                        s.ToString().c_str());
+      }
+    } else {
+      ROCKS_LOG_ERROR(db_options_.info_log,
+                      "[%s] GC job failed to install output blob files: %s",
+                      blob_gc_->column_family_handle()->GetName().c_str(),
+                      s.ToString().c_str());
+    }
     mutex_->Lock();
   }
 
@@ -466,8 +488,19 @@ Status BlobGCJob::InstallOutputBlobFiles() {
         blob_gc_->column_family_handle()->GetID(), files);
   } else {
     std::vector<unique_ptr<BlobFileHandle>> handles;
-    for (auto& builder : this->blob_file_builders_)
+    std::string to_delete_files;
+    for (auto& builder : this->blob_file_builders_) {
+      if (!to_delete_files.empty()) {
+        to_delete_files.append(" ");
+      }
+      to_delete_files.append(std::to_string(builder.first->GetNumber()));
       handles.emplace_back(std::move(builder.first));
+    }
+    ROCKS_LOG_BUFFER(
+        log_buffer_,
+        "[%s] InstallOutputBlobFiles failed. Delete GC output files: %s",
+        blob_gc_->column_family_handle()->GetName().c_str(),
+        to_delete_files.c_str());
     this->blob_file_manager_->BatchDeleteFiles(handles);
   }
   return s;

src/db_impl.cc

@@ -703,6 +703,9 @@ void TitanDBImpl::OnFlushCompleted(const FlushJobInfo& flush_job_info) {
       if (!file) {
         continue;
       }
+      ROCKS_LOG_INFO(db_options_.info_log,
+                     "OnFlushCompleted[%d]: output blob file %" PRIu64 ".",
+                     flush_job_info.job_id, file->file_number());
       file->FileStateTransit(BlobFileMeta::FileEvent::kFlushCompleted);
     }
   }
@@ -792,6 +795,10 @@ void TitanDBImpl::OnCompactionCompleted(
         assert(false);
         return;
       }
+      ROCKS_LOG_INFO(
+          db_options_.info_log,
+          "OnCompactionCompleted[%d]: compaction output blob file %" PRIu64 ".",
+          compaction_job_info.job_id, file->file_number());
       file->FileStateTransit(BlobFileMeta::FileEvent::kCompactionCompleted);
     }
 

src/table_builder.cc

 #include "table_builder.h"
 
+#ifndef __STDC_FORMAT_MACROS
+#define __STDC_FORMAT_MACROS
+#endif
+
+#include <inttypes.h>
+
 namespace rocksdb {
 namespace titandb {
 
@@ -68,6 +74,9 @@ void TitanTableBuilder::AddBlob(const Slice& key, const Slice& value,
   if (!blob_builder_) {
     status_ = blob_manager_->NewFile(&blob_handle_);
     if (!ok()) return;
+    ROCKS_LOG_INFO(db_options_.info_log,
+                   "Titan table builder created new blob file %" PRIu64 ".",
+                   blob_handle_->GetNumber());
     blob_builder_.reset(
         new BlobFileBuilder(db_options_, cf_options_, blob_handle_->GetFile()));
   }
@@ -105,21 +114,37 @@ Status TitanTableBuilder::Finish() {
   if (blob_builder_) {
     blob_builder_->Finish();
     if (ok()) {
+      ROCKS_LOG_INFO(db_options_.info_log,
+                     "Titan table builder finish output file %" PRIu64 ".",
+                     blob_handle_->GetNumber());
       std::shared_ptr<BlobFileMeta> file = std::make_shared<BlobFileMeta>(
           blob_handle_->GetNumber(), blob_handle_->GetFile()->GetFileSize());
       file->FileStateTransit(BlobFileMeta::FileEvent::kFlushOrCompactionOutput);
       status_ =
           blob_manager_->FinishFile(cf_id_, file, std::move(blob_handle_));
     } else {
+      ROCKS_LOG_WARN(
+          db_options_.info_log,
+          "Titan table builder finish failed. Delete output file %" PRIu64 ".",
+          blob_handle_->GetNumber());
       status_ = blob_manager_->DeleteFile(std::move(blob_handle_));
     }
   }
+  if (!status_.ok()) {
+    ROCKS_LOG_ERROR(db_options_.info_log,
+                    "Titan table builder failed on finish: %s",
+                    status_.ToString().c_str());
+  }
   return status();
 }
 
 void TitanTableBuilder::Abandon() {
   base_builder_->Abandon();
   if (blob_builder_) {
+    ROCKS_LOG_INFO(db_options_.info_log,
+                   "Titan table builder abandoned. Delete output file %" PRIu64
+                   ".",
+                   blob_handle_->GetNumber());
     blob_builder_->Abandon();
     status_ = blob_manager_->DeleteFile(std::move(blob_handle_));
   }

src/version_set.cc

@@ -88,6 +88,8 @@ Status VersionSet::Recover() {
     s = collector.GetNextFileNumber(&next_file_number);
     if (!s.ok()) return s;
     next_file_number_.store(next_file_number);
+    ROCKS_LOG_INFO(db_options_.info_log,
+                   "Next blob file number is %" PRIu64 ".", next_file_number);
   }
 
   auto new_manifest_file_number = NewFileNumber();
@@ -98,6 +100,19 @@ Status VersionSet::Recover() {
   std::set<uint64_t> alive_files;
   alive_files.insert(new_manifest_file_number);
   for (const auto& bs : column_families_) {
+    std::string files_str;
+    for (const auto& f : bs.second->files_) {
+      if (!files_str.empty()) {
+        files_str.append(", ");
+      }
+      files_str.append(std::to_string(f.first));
+      if (f.second->is_obsolete()) {
+        files_str.append("(obsolete)");
+      }
+    }
+    ROCKS_LOG_INFO(db_options_.info_log,
+                   "Blob files for CF %" PRIu32 " found: %s", bs.first,
+                   files_str.c_str());
     // delete obsoleted files at reopen
     // all the obsolete files's obsolete sequence are 0
     bs.second->GetObsoleteFiles(nullptr, kMaxSequenceNumber);
@@ -115,7 +130,8 @@ Status VersionSet::Recover() {
     if (file_type != FileType::kBlobFile &&
         file_type != FileType::kDescriptorFile)
       continue;
-
+    ROCKS_LOG_INFO(db_options_.info_log,
+                   "Titan recovery delete obsolete file %s.", f.c_str());
     env_->DeleteFile(dirname_ + "/" + f);
   }