Periodically flush info log out of application buffer (facebook#7488)

Summary: This PR schedules a background thread (shared across all DB instances) to flush info log every ten seconds. This improves debuggability in case of RocksDB hanging since it ensures the log messages leading up to the hang will eventually become visible in the log. The bulk of this PR is moving monitoring/stats_dump_scheduler* to db/periodic_work_scheduler* and making the corresponding name changes since now the scheduler handles info log flushing, not just stats dumping. Pull Request resolved: facebook#7488 Reviewed By: riversand963 Differential Revision: D24065165 Pulled By: ajkr fbshipit-source-id: 339c47a0ff43b79fdbd055fbd9fefbb6f9d8d3b5
tianxiaogu · Oct 2, 2020 · 1e00909 · 1e00909
1 parent 94fc676
commit 1e00909
Show file tree

Hide file tree

Showing 14 changed files with 209 additions and 174 deletions.
diff --git a/CMakeLists.txt b/CMakeLists.txt
@@ -621,6 +621,7 @@ set(SOURCES
         db/merge_helper.cc
         db/merge_operator.cc
         db/output_validator.cc
+        db/periodic_work_scheduler.cc
         db/range_del_aggregator.cc
         db/range_tombstone_fragmenter.cc
         db/repair.cc
@@ -678,7 +679,6 @@ set(SOURCES
         monitoring/perf_level.cc
         monitoring/persistent_stats_history.cc
         monitoring/statistics.cc
-        monitoring/stats_dump_scheduler.cc
         monitoring/thread_status_impl.cc
         monitoring/thread_status_updater.cc
         monitoring/thread_status_util.cc
@@ -1103,6 +1103,7 @@ if(WITH_TESTS)
         db/merge_test.cc
         db/options_file_test.cc
         db/perf_context_test.cc
+        db/periodic_work_scheduler_test.cc
         db/plain_table_db_test.cc
         db/prefix_test.cc
         db/range_del_aggregator_test.cc
@@ -1134,7 +1135,6 @@ if(WITH_TESTS)
         monitoring/histogram_test.cc
         monitoring/iostats_context_test.cc
         monitoring/statistics_test.cc
-        monitoring/stats_dump_scheduler_test.cc
         monitoring/stats_history_test.cc
         options/configurable_test.cc
         options/options_settable_test.cc

diff --git a/Makefile b/Makefile
@@ -1904,7 +1904,7 @@ blob_file_garbage_test: $(OBJ_DIR)/db/blob/blob_file_garbage_test.o $(TEST_LIBRA
 timer_test: $(OBJ_DIR)/util/timer_test.o $(TEST_LIBRARY) $(LIBRARY)
 	$(AM_LINK)
 
-stats_dump_scheduler_test: $(OBJ_DIR)/monitoring/stats_dump_scheduler_test.o $(TEST_LIBRARY) $(LIBRARY)
+periodic_work_scheduler_test: $(OBJ_DIR)/db/periodic_work_scheduler_test.o $(TEST_LIBRARY) $(LIBRARY)
 	$(AM_LINK)
 
 testutil_test: $(OBJ_DIR)/test_util/testutil_test.o $(TEST_LIBRARY) $(LIBRARY)

diff --git a/TARGETS b/TARGETS
@@ -185,6 +185,7 @@ cpp_library(
         "db/merge_helper.cc",
         "db/merge_operator.cc",
         "db/output_validator.cc",
+        "db/periodic_work_scheduler.cc",
         "db/range_del_aggregator.cc",
         "db/range_tombstone_fragmenter.cc",
         "db/repair.cc",
@@ -245,7 +246,6 @@ cpp_library(
         "monitoring/perf_level.cc",
         "monitoring/persistent_stats_history.cc",
         "monitoring/statistics.cc",
-        "monitoring/stats_dump_scheduler.cc",
         "monitoring/thread_status_impl.cc",
         "monitoring/thread_status_updater.cc",
         "monitoring/thread_status_updater_debug.cc",
@@ -472,6 +472,7 @@ cpp_library(
         "db/merge_helper.cc",
         "db/merge_operator.cc",
         "db/output_validator.cc",
+        "db/periodic_work_scheduler.cc",
         "db/range_del_aggregator.cc",
         "db/range_tombstone_fragmenter.cc",
         "db/repair.cc",
@@ -532,7 +533,6 @@ cpp_library(
         "monitoring/perf_level.cc",
         "monitoring/persistent_stats_history.cc",
         "monitoring/statistics.cc",
-        "monitoring/stats_dump_scheduler.cc",
         "monitoring/thread_status_impl.cc",
         "monitoring/thread_status_updater.cc",
         "monitoring/thread_status_updater_debug.cc",
@@ -1681,6 +1681,13 @@ ROCKS_TESTS = [
         [],
         [],
     ],
+    [
+        "periodic_work_scheduler_test",
+        "db/periodic_work_scheduler_test.cc",
+        "serial",
+        [],
+        [],
+    ],
     [
         "persistent_cache_test",
         "utilities/persistent_cache/persistent_cache_test.cc",
@@ -1814,13 +1821,6 @@ ROCKS_TESTS = [
         [],
         [],
     ],
-    [
-        "stats_dump_scheduler_test",
-        "monitoring/stats_dump_scheduler_test.cc",
-        "serial",
-        [],
-        [],
-    ],
     [
         "stats_history_test",
         "monitoring/stats_history_test.cc",

diff --git a/db/compacted_db_impl.cc b/db/compacted_db_impl.cc
@@ -156,7 +156,7 @@ Status CompactedDBImpl::Open(const Options& options,
   std::unique_ptr<CompactedDBImpl> db(new CompactedDBImpl(db_options, dbname));
   Status s = db->Init(options);
   if (s.ok()) {
-    db->StartStatsDumpScheduler();
+    db->StartPeriodicWorkScheduler();
     ROCKS_LOG_INFO(db->immutable_db_options_.info_log,
                    "Opened the db as fully compacted mode");
     LogFlush(db->immutable_db_options_.info_log);

diff --git a/db/db_impl/db_impl.cc b/db/db_impl/db_impl.cc
@@ -44,6 +44,7 @@
 #include "db/memtable_list.h"
 #include "db/merge_context.h"
 #include "db/merge_helper.h"
+#include "db/periodic_work_scheduler.h"
 #include "db/range_tombstone_fragmenter.h"
 #include "db/table_cache.h"
 #include "db/table_properties_collector.h"
@@ -65,7 +66,6 @@
 #include "monitoring/iostats_context_imp.h"
 #include "monitoring/perf_context_imp.h"
 #include "monitoring/persistent_stats_history.h"
-#include "monitoring/stats_dump_scheduler.h"
 #include "monitoring/thread_status_updater.h"
 #include "monitoring/thread_status_util.h"
 #include "options/cf_options.h"
@@ -207,7 +207,7 @@ DBImpl::DBImpl(const DBOptions& options, const std::string& dbname,
       refitting_level_(false),
       opened_successfully_(false),
 #ifndef ROCKSDB_LITE
-      stats_dump_scheduler_(nullptr),
+      periodic_work_scheduler_(nullptr),
 #endif  // ROCKSDB_LITE
       two_write_queues_(options.two_write_queues),
       manual_wal_flush_(options.manual_wal_flush),
@@ -446,8 +446,8 @@ void DBImpl::CancelAllBackgroundWork(bool wait) {
                  "Shutdown: canceling all background work");
 
 #ifndef ROCKSDB_LITE
-  if (stats_dump_scheduler_ != nullptr) {
-    stats_dump_scheduler_->Unregister(this);
+  if (periodic_work_scheduler_ != nullptr) {
+    periodic_work_scheduler_->Unregister(this);
   }
 #endif  // !ROCKSDB_LITE
 
@@ -685,18 +685,18 @@ void DBImpl::PrintStatistics() {
   }
 }
 
-void DBImpl::StartStatsDumpScheduler() {
+void DBImpl::StartPeriodicWorkScheduler() {
 #ifndef ROCKSDB_LITE
   {
     InstrumentedMutexLock l(&mutex_);
-    stats_dump_scheduler_ = StatsDumpScheduler::Default();
-    TEST_SYNC_POINT_CALLBACK("DBImpl::StartStatsDumpScheduler:Init",
-                             &stats_dump_scheduler_);
+    periodic_work_scheduler_ = PeriodicWorkScheduler::Default();
+    TEST_SYNC_POINT_CALLBACK("DBImpl::StartPeriodicWorkScheduler:Init",
+                             &periodic_work_scheduler_);
   }
 
-  stats_dump_scheduler_->Register(this,
-                                  mutable_db_options_.stats_dump_period_sec,
-                                  mutable_db_options_.stats_persist_period_sec);
+  periodic_work_scheduler_->Register(
+      this, mutable_db_options_.stats_dump_period_sec,
+      mutable_db_options_.stats_persist_period_sec);
 #endif  // !ROCKSDB_LITE
 }
 
@@ -907,6 +907,14 @@ void DBImpl::DumpStats() {
   PrintStatistics();
 }
 
+void DBImpl::FlushInfoLog() {
+  if (shutdown_initiated_) {
+    return;
+  }
+  TEST_SYNC_POINT("DBImpl::FlushInfoLog:StartRunning");
+  LogFlush(immutable_db_options_.info_log);
+}
+
 Status DBImpl::TablesRangeTombstoneSummary(ColumnFamilyHandle* column_family,
                                            int max_entries_to_print,
                                            std::string* out_str) {
@@ -1082,19 +1090,12 @@ Status DBImpl::SetDBOptions(
               mutable_db_options_.stats_dump_period_sec ||
           new_options.stats_persist_period_sec !=
               mutable_db_options_.stats_persist_period_sec) {
-        if (stats_dump_scheduler_) {
-          mutex_.Unlock();
-          stats_dump_scheduler_->Unregister(this);
-          mutex_.Lock();
-        }
-        if (new_options.stats_dump_period_sec > 0 ||
-            new_options.stats_persist_period_sec > 0) {
-          mutex_.Unlock();
-          stats_dump_scheduler_->Register(this,
-                                          new_options.stats_dump_period_sec,
-                                          new_options.stats_persist_period_sec);
-          mutex_.Lock();
-        }
+        mutex_.Unlock();
+        periodic_work_scheduler_->Unregister(this);
+        periodic_work_scheduler_->Register(
+            this, new_options.stats_dump_period_sec,
+            new_options.stats_persist_period_sec);
+        mutex_.Lock();
       }
       write_controller_.set_max_delayed_write_rate(
           new_options.delayed_write_rate);

diff --git a/db/db_impl/db_impl.h b/db/db_impl/db_impl.h
@@ -70,9 +70,9 @@ class ArenaWrappedDBIter;
 class InMemoryStatsHistoryIterator;
 class MemTable;
 class PersistentStatsHistoryIterator;
-class StatsDumpScheduler;
+class PeriodicWorkScheduler;
 #ifndef NDEBUG
-class StatsDumpTestScheduler;
+class PeriodicWorkTestScheduler;
 #endif  // !NDEBUG
 class TableCache;
 class TaskLimiterToken;
@@ -1002,7 +1002,7 @@ class DBImpl : public DB {
   }
 
 #ifndef ROCKSDB_LITE
-  StatsDumpTestScheduler* TEST_GetStatsDumpScheduler() const;
+  PeriodicWorkTestScheduler* TEST_GetPeriodicWorkScheduler() const;
 #endif  // !ROCKSDB_LITE
 
 #endif  // NDEBUG
@@ -1013,6 +1013,9 @@ class DBImpl : public DB {
   // dump rocksdb.stats to LOG
   void DumpStats();
 
+  // flush LOG out of application buffer
+  void FlushInfoLog();
+
  protected:
   const std::string dbname_;
   std::string db_id_;
@@ -1652,7 +1655,7 @@ class DBImpl : public DB {
                               LogBuffer* log_buffer);
 
   // Schedule background tasks
-  void StartStatsDumpScheduler();
+  void StartPeriodicWorkScheduler();
 
   void PrintStatistics();
 
@@ -2111,10 +2114,11 @@ class DBImpl : public DB {
   std::unique_ptr<PreReleaseCallback> recoverable_state_pre_release_callback_;
 
 #ifndef ROCKSDB_LITE
-  // Scheduler to run DumpStats() and PersistStats(). Currently, it always use
-  // a global instance from StatsDumpScheduler::Default(). Only in unittest, it
-  // can be overrided by StatsDumpTestSchduler.
-  StatsDumpScheduler* stats_dump_scheduler_;
+  // Scheduler to run DumpStats(), PersistStats(), and FlushInfoLog().
+  // Currently, it always use a global instance from
+  // PeriodicWorkScheduler::Default(). Only in unittest, it can be overrided by
+  // PeriodicWorkTestScheduler.
+  PeriodicWorkScheduler* periodic_work_scheduler_;
 #endif
 
   // When set, we use a separate queue for writes that don't write to memtable.

diff --git a/db/db_impl/db_impl_debug.cc b/db/db_impl/db_impl_debug.cc
@@ -12,7 +12,7 @@
 #include "db/column_family.h"
 #include "db/db_impl/db_impl.h"
 #include "db/error_handler.h"
-#include "monitoring/stats_dump_scheduler.h"
+#include "db/periodic_work_scheduler.h"
 #include "monitoring/thread_status_updater.h"
 #include "util/cast_util.h"
 
@@ -274,14 +274,14 @@ size_t DBImpl::TEST_GetWalPreallocateBlockSize(
 
 #ifndef ROCKSDB_LITE
 void DBImpl::TEST_WaitForStatsDumpRun(std::function<void()> callback) const {
-  if (stats_dump_scheduler_ != nullptr) {
-    static_cast<StatsDumpTestScheduler*>(stats_dump_scheduler_)
+  if (periodic_work_scheduler_ != nullptr) {
+    static_cast<PeriodicWorkTestScheduler*>(periodic_work_scheduler_)
         ->TEST_WaitForRun(callback);
   }
 }
 
-StatsDumpTestScheduler* DBImpl::TEST_GetStatsDumpScheduler() const {
-  return static_cast<StatsDumpTestScheduler*>(stats_dump_scheduler_);
+PeriodicWorkTestScheduler* DBImpl::TEST_GetPeriodicWorkScheduler() const {
+  return static_cast<PeriodicWorkTestScheduler*>(periodic_work_scheduler_);
 }
 #endif  // !ROCKSDB_LITE
 

diff --git a/db/db_impl/db_impl_open.cc b/db/db_impl/db_impl_open.cc
@@ -11,12 +11,12 @@
 #include "db/builder.h"
 #include "db/db_impl/db_impl.h"
 #include "db/error_handler.h"
+#include "db/periodic_work_scheduler.h"
 #include "env/composite_env_wrapper.h"
 #include "file/read_write_util.h"
 #include "file/sst_file_manager_impl.h"
 #include "file/writable_file_writer.h"
 #include "monitoring/persistent_stats_history.h"
-#include "monitoring/stats_dump_scheduler.h"
 #include "options/options_helper.h"
 #include "rocksdb/table.h"
 #include "rocksdb/wal_filter.h"
@@ -1763,7 +1763,7 @@ Status DBImpl::Open(const DBOptions& db_options, const std::string& dbname,
                    persist_options_status.ToString().c_str());
   }
   if (s.ok()) {
-    impl->StartStatsDumpScheduler();
+    impl->StartPeriodicWorkScheduler();
   } else {
     for (auto* h : *handles) {
       delete h;