From 2677bd5967b385d3bf09123b2e400e9448e87dc4 Mon Sep 17 00:00:00 2001 From: Akanksha Mahajan Date: Fri, 5 Jun 2020 09:41:03 -0700 Subject: [PATCH] Add logs and stats in DeleteScheduler (#6927) Summary: Add logs and stats for files marked as trash and files deleted immediately in DeleteScheduler Pull Request resolved: https://github.com/facebook/rocksdb/pull/6927 Test Plan: make check -j64 Reviewed By: riversand963 Differential Revision: D21869068 Pulled By: akankshamahajan15 fbshipit-source-id: e9f673c4fa8049ce648b23c75d742f2f9c6c57a1 --- db/db_impl/db_impl_open.cc | 6 +++ db/db_sst_test.cc | 10 +++++ file/delete_scheduler.cc | 41 +++++++++++++++---- file/delete_scheduler.h | 5 +++ file/delete_scheduler_test.cc | 25 ++++++++++- file/sst_file_manager_impl.h | 6 +++ include/rocksdb/sst_file_manager.h | 4 ++ include/rocksdb/statistics.h | 6 +++ java/rocksjni/portal.h | 15 +++++-- .../src/main/java/org/rocksdb/TickerType.java | 10 +++++ monitoring/statistics.cc | 2 + 11 files changed, 119 insertions(+), 11 deletions(-) diff --git a/db/db_impl/db_impl_open.cc b/db/db_impl/db_impl_open.cc index 8d0675493..9daad0601 100644 --- a/db/db_impl/db_impl_open.cc +++ b/db/db_impl/db_impl_open.cc @@ -1569,6 +1569,12 @@ Status DBImpl::Open(const DBOptions& db_options, const std::string& dbname, auto sfm = static_cast( impl->immutable_db_options_.sst_file_manager.get()); if (s.ok() && sfm) { + // Set Statistics ptr for SstFileManager to dump the stats of + // DeleteScheduler. + sfm->SetStatisticsPtr(impl->immutable_db_options_.statistics); + ROCKS_LOG_INFO(impl->immutable_db_options_.info_log, + "SstFileManager instance %p", sfm); + // Notify SstFileManager about all sst files that already exist in // db_paths[0] and cf_paths[0] when the DB is opened. diff --git a/db/db_sst_test.cc b/db/db_sst_test.cc index 01a6880c4..687d3b852 100644 --- a/db/db_sst_test.cc +++ b/db/db_sst_test.cc @@ -376,6 +376,7 @@ TEST_F(DBSSTTest, RateLimitedDelete) { env_->SetTimeElapseOnlySleep(&options); options.disable_auto_compactions = true; options.env = env_; + options.statistics = CreateDBStatistics(); int64_t rate_bytes_per_sec = 1024 * 10; // 10 Kbs / Sec Status s; @@ -425,6 +426,9 @@ TEST_F(DBSSTTest, RateLimitedDelete) { } ASSERT_GT(time_spent_deleting, expected_penlty * 0.9); ASSERT_LT(time_spent_deleting, expected_penlty * 1.1); + ASSERT_EQ(4, options.statistics->getAndResetTickerCount(FILES_MARKED_TRASH)); + ASSERT_EQ( + 0, options.statistics->getAndResetTickerCount(FILES_DELETED_IMMEDIATELY)); ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing(); } @@ -816,6 +820,12 @@ TEST_F(DBSSTTest, CancellingCompactionsWorks) { ASSERT_EQ(sfm->GetCompactionsReservedSize(), 0); // Make sure the stat is bumped ASSERT_GT(dbfull()->immutable_db_options().statistics.get()->getTickerCount(COMPACTION_CANCELLED), 0); + ASSERT_EQ(0, + dbfull()->immutable_db_options().statistics.get()->getTickerCount( + FILES_MARKED_TRASH)); + ASSERT_EQ(4, + dbfull()->immutable_db_options().statistics.get()->getTickerCount( + FILES_DELETED_IMMEDIATELY)); ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing(); } diff --git a/file/delete_scheduler.cc b/file/delete_scheduler.cc index 4595d8939..5552d1140 100644 --- a/file/delete_scheduler.cc +++ b/file/delete_scheduler.cc @@ -7,6 +7,7 @@ #include "file/delete_scheduler.h" +#include #include #include @@ -65,6 +66,12 @@ Status DeleteScheduler::DeleteFile(const std::string& file_path, s = fs_->DeleteFile(file_path, IOOptions(), nullptr); if (s.ok()) { sst_file_manager_->OnDeleteFile(file_path); + ROCKS_LOG_INFO(info_log_, + "Deleted file %s immediately, rate_bytes_per_sec %" PRIi64 + ", total_trash_size %" PRIu64 " max_trash_db_ratio %lf", + file_path.c_str(), rate_bytes_per_sec_.load(), + total_trash_size_.load(), max_trash_db_ratio_.load()); + RecordTick(stats_.get(), FILES_DELETED_IMMEDIATELY); } return s; } @@ -72,6 +79,8 @@ Status DeleteScheduler::DeleteFile(const std::string& file_path, // Move file to trash std::string trash_file; s = MarkAsTrash(file_path, &trash_file); + ROCKS_LOG_INFO(info_log_, "Mark file: %s as trash -- %s", trash_file.c_str(), + s.ToString().c_str()); if (!s.ok()) { ROCKS_LOG_ERROR(info_log_, "Failed to mark %s as trash -- %s", @@ -79,10 +88,14 @@ Status DeleteScheduler::DeleteFile(const std::string& file_path, s = fs_->DeleteFile(file_path, IOOptions(), nullptr); if (s.ok()) { sst_file_manager_->OnDeleteFile(file_path); + ROCKS_LOG_INFO(info_log_, "Deleted file %s immediately", + trash_file.c_str()); + RecordTick(stats_.get(), FILES_DELETED_IMMEDIATELY); } return s; } + RecordTick(stats_.get(), FILES_MARKED_TRASH); // Update the total trash size uint64_t trash_file_size = 0; fs_->GetFileSize(trash_file, IOOptions(), &trash_file_size, nullptr); @@ -210,6 +223,8 @@ void DeleteScheduler::BackgroundEmptyTrash() { current_delete_rate = rate_bytes_per_sec_.load(); start_time = env_->NowMicros(); total_deleted_bytes = 0; + ROCKS_LOG_INFO(info_log_, "rate_bytes_per_sec is changed to %" PRIi64, + current_delete_rate); } // Get new file to delete @@ -233,19 +248,27 @@ void DeleteScheduler::BackgroundEmptyTrash() { bg_errors_[path_in_trash] = s; } - // Apply penlty if necessary - uint64_t total_penlty; + // Apply penalty if necessary + uint64_t total_penalty; if (current_delete_rate > 0) { // rate limiting is enabled - total_penlty = + total_penalty = ((total_deleted_bytes * kMicrosInSecond) / current_delete_rate); - while (!closing_ && !cv_.TimedWait(start_time + total_penlty)) {} + ROCKS_LOG_INFO(info_log_, + "Rate limiting is enabled with penalty %" PRIu64 + "after deleting file %s", + total_penalty, path_in_trash.c_str()); + while (!closing_ && !cv_.TimedWait(start_time + total_penalty)) { + } } else { // rate limiting is disabled - total_penlty = 0; + total_penalty = 0; + ROCKS_LOG_INFO(info_log_, + "Rate limiting is disabled after deleting file %s", + path_in_trash.c_str()); } TEST_SYNC_POINT_CALLBACK("DeleteScheduler::BackgroundEmptyTrash:Wait", - &total_penlty); + &total_penalty); if (is_complete) { pending_files_--; @@ -353,9 +376,13 @@ void DeleteScheduler::WaitForEmptyTrash() { } void DeleteScheduler::MaybeCreateBackgroundThread() { - if(bg_thread_ == nullptr && rate_bytes_per_sec_.load() > 0) { + if (bg_thread_ == nullptr && rate_bytes_per_sec_.load() > 0) { bg_thread_.reset( new port::Thread(&DeleteScheduler::BackgroundEmptyTrash, this)); + ROCKS_LOG_INFO(info_log_, + "Created background thread for deletion scheduler with " + "rate_bytes_per_sec: %" PRIi64, + rate_bytes_per_sec_.load()); } } diff --git a/file/delete_scheduler.h b/file/delete_scheduler.h index e4bf00d32..59f46eeb7 100644 --- a/file/delete_scheduler.h +++ b/file/delete_scheduler.h @@ -83,6 +83,10 @@ class DeleteScheduler { static Status CleanupDirectory(Env* env, SstFileManagerImpl* sfm, const std::string& path); + void SetStatisticsPtr(const std::shared_ptr& stats) { + stats_ = stats; + } + private: Status MarkAsTrash(const std::string& file_path, std::string* path_in_trash); @@ -137,6 +141,7 @@ class DeleteScheduler { // immediately std::atomic max_trash_db_ratio_; static const uint64_t kMicrosInSecond = 1000 * 1000LL; + std::shared_ptr stats_; }; } // namespace ROCKSDB_NAMESPACE diff --git a/file/delete_scheduler_test.cc b/file/delete_scheduler_test.cc index 687eae512..993fba12a 100644 --- a/file/delete_scheduler_test.cc +++ b/file/delete_scheduler_test.cc @@ -32,6 +32,7 @@ class DeleteSchedulerTest : public testing::Test { ToString(i)); DestroyAndCreateDir(dummy_files_dirs_.back()); } + stats_ = ROCKSDB_NAMESPACE::CreateDBStatistics(); } ~DeleteSchedulerTest() override { @@ -99,6 +100,7 @@ class DeleteSchedulerTest : public testing::Test { new SstFileManagerImpl(env_, fs, nullptr, rate_bytes_per_sec_, /* max_trash_db_ratio= */ 1.1, 128 * 1024)); delete_scheduler_ = sst_file_mgr_->delete_scheduler(); + sst_file_mgr_->SetStatisticsPtr(stats_); } Env* env_; @@ -106,6 +108,7 @@ class DeleteSchedulerTest : public testing::Test { int64_t rate_bytes_per_sec_; DeleteScheduler* delete_scheduler_; std::unique_ptr sst_file_mgr_; + std::shared_ptr stats_; }; // Test the basic functionality of DeleteScheduler (Rate Limiting). @@ -182,6 +185,8 @@ TEST_F(DeleteSchedulerTest, BasicRateLimiting) { ASSERT_EQ(num_files, dir_synced); ASSERT_EQ(CountTrashFiles(), 0); + ASSERT_EQ(num_files, stats_->getAndResetTickerCount(FILES_MARKED_TRASH)); + ASSERT_EQ(0, stats_->getAndResetTickerCount(FILES_DELETED_IMMEDIATELY)); ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing(); } } @@ -219,6 +224,9 @@ TEST_F(DeleteSchedulerTest, MultiDirectoryDeletionsScheduled) { ASSERT_EQ(0, CountTrashFiles(i)); } + ASSERT_EQ(kNumFiles, stats_->getAndResetTickerCount(FILES_MARKED_TRASH)); + ASSERT_EQ(0, stats_->getAndResetTickerCount(FILES_DELETED_IMMEDIATELY)); + ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing(); } @@ -301,6 +309,10 @@ TEST_F(DeleteSchedulerTest, RateLimitingMultiThreaded) { ASSERT_EQ(CountNormalFiles(), 0); ASSERT_EQ(CountTrashFiles(), 0); + ASSERT_EQ(num_files * thread_cnt, + stats_->getAndResetTickerCount(FILES_MARKED_TRASH)); + ASSERT_EQ(0, stats_->getAndResetTickerCount(FILES_DELETED_IMMEDIATELY)); + ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing(); } } @@ -318,8 +330,9 @@ TEST_F(DeleteSchedulerTest, DisableRateLimiting) { rate_bytes_per_sec_ = 0; NewDeleteScheduler(); + constexpr int num_files = 10; - for (int i = 0; i < 10; i++) { + for (int i = 0; i < num_files; i++) { // Every file we delete will be deleted immediately std::string dummy_file = NewDummyFile("dummy.data"); ASSERT_OK(delete_scheduler_->DeleteFile(dummy_file, "")); @@ -329,6 +342,9 @@ TEST_F(DeleteSchedulerTest, DisableRateLimiting) { } ASSERT_EQ(bg_delete_file, 0); + ASSERT_EQ(0, stats_->getAndResetTickerCount(FILES_MARKED_TRASH)); + ASSERT_EQ(num_files, + stats_->getAndResetTickerCount(FILES_DELETED_IMMEDIATELY)); ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing(); } @@ -365,6 +381,8 @@ TEST_F(DeleteSchedulerTest, ConflictNames) { auto bg_errors = delete_scheduler_->GetBackgroundErrors(); ASSERT_EQ(bg_errors.size(), 0); + ASSERT_EQ(10, stats_->getAndResetTickerCount(FILES_MARKED_TRASH)); + ASSERT_EQ(0, stats_->getAndResetTickerCount(FILES_DELETED_IMMEDIATELY)); ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing(); } @@ -439,9 +457,12 @@ TEST_F(DeleteSchedulerTest, StartBGEmptyTrashMultipleTimes) { auto bg_errors = delete_scheduler_->GetBackgroundErrors(); ASSERT_EQ(bg_errors.size(), 0); + ASSERT_EQ(10, stats_->getAndResetTickerCount(FILES_MARKED_TRASH)); + ASSERT_EQ(0, stats_->getAndResetTickerCount(FILES_DELETED_IMMEDIATELY)); } ASSERT_EQ(bg_delete_file, 50); + ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->EnableProcessing(); } @@ -653,6 +674,8 @@ TEST_F(DeleteSchedulerTest, ImmediateDeleteOn25PercDBSize) { // When we end up with 26 files in trash we will start // deleting new files immediately ASSERT_EQ(fg_delete_file, 74); + ASSERT_EQ(26, stats_->getAndResetTickerCount(FILES_MARKED_TRASH)); + ASSERT_EQ(74, stats_->getAndResetTickerCount(FILES_DELETED_IMMEDIATELY)); ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing(); } diff --git a/file/sst_file_manager_impl.h b/file/sst_file_manager_impl.h index 323ffc7b2..516627f85 100644 --- a/file/sst_file_manager_impl.h +++ b/file/sst_file_manager_impl.h @@ -135,6 +135,11 @@ class SstFileManagerImpl : public SstFileManager { // once in the object's lifetime, and before the destructor void Close(); + void SetStatisticsPtr(const std::shared_ptr& stats) override { + stats_ = stats; + delete_scheduler_.SetStatisticsPtr(stats); + } + private: // REQUIRES: mutex locked void OnAddFileImpl(const std::string& file_path, uint64_t file_size, @@ -190,6 +195,7 @@ class SstFileManagerImpl : public SstFileManager { std::list error_handler_list_; // Pointer to ErrorHandler instance that is currently processing recovery ErrorHandler* cur_instance_; + std::shared_ptr stats_; }; } // namespace ROCKSDB_NAMESPACE diff --git a/include/rocksdb/sst_file_manager.h b/include/rocksdb/sst_file_manager.h index 92d0bbbf8..350dec7a8 100644 --- a/include/rocksdb/sst_file_manager.h +++ b/include/rocksdb/sst_file_manager.h @@ -11,6 +11,7 @@ #include #include "rocksdb/file_system.h" +#include "rocksdb/statistics.h" #include "rocksdb/status.h" namespace ROCKSDB_NAMESPACE { @@ -80,6 +81,9 @@ class SstFileManager { // Return the total size of trash files // thread-safe virtual uint64_t GetTotalTrashSize() = 0; + + // Set the statistics ptr to dump the stat information + virtual void SetStatisticsPtr(const std::shared_ptr& stats) = 0; }; // Create a new SstFileManager that can be shared among multiple RocksDB diff --git a/include/rocksdb/statistics.h b/include/rocksdb/statistics.h index 298e2bc9d..af09a1b8d 100644 --- a/include/rocksdb/statistics.h +++ b/include/rocksdb/statistics.h @@ -360,6 +360,12 @@ enum Tickers : uint32_t { // <= BLOCK_CACHE_COMPRESSION_DICT_ADD BLOCK_CACHE_COMPRESSION_DICT_ADD_REDUNDANT, + // # of files marked as trash by sst file manager and will be deleted + // later by background thread. + FILES_MARKED_TRASH, + // # of files deleted immediately by sst file manger through delete scheduler. + FILES_DELETED_IMMEDIATELY, + TICKER_ENUM_MAX }; diff --git a/java/rocksjni/portal.h b/java/rocksjni/portal.h index 90e1a0977..58111c846 100644 --- a/java/rocksjni/portal.h +++ b/java/rocksjni/portal.h @@ -1292,9 +1292,9 @@ class ByteBufferJni : public JavaClass { return constructWith(env, direct, nullptr, capacity, jbytebuffer_clazz); } - static jobject constructWith( - JNIEnv* env, const bool direct, const char* buf, const size_t capacity, - jclass jbytebuffer_clazz = nullptr) { + static jobject constructWith(JNIEnv* env, const bool direct, const char* buf, + const size_t capacity, + jclass jbytebuffer_clazz = nullptr) { if (direct) { bool allocated = false; if (buf == nullptr) { @@ -4945,6 +4945,11 @@ class TickerTypeJni { return -0x0C; case ROCKSDB_NAMESPACE::Tickers::TXN_GET_TRY_AGAIN: return -0x0D; + case ROCKSDB_NAMESPACE::Tickers::FILES_MARKED_TRASH: + return -0x0E; + case ROCKSDB_NAMESPACE::Tickers::FILES_DELETED_IMMEDIATELY: + return -0X0F; + case ROCKSDB_NAMESPACE::Tickers::TICKER_ENUM_MAX: // 0x5F for backwards compatibility on current minor version. return 0x5F; @@ -5240,6 +5245,10 @@ class TickerTypeJni { return ROCKSDB_NAMESPACE::Tickers::TXN_SNAPSHOT_MUTEX_OVERHEAD; case -0x0D: return ROCKSDB_NAMESPACE::Tickers::TXN_GET_TRY_AGAIN; + case -0x0E: + return ROCKSDB_NAMESPACE::Tickers::FILES_MARKED_TRASH; + case -0x0F: + return ROCKSDB_NAMESPACE::Tickers::FILES_DELETED_IMMEDIATELY; case 0x5F: // 0x5F for backwards compatibility on current minor version. return ROCKSDB_NAMESPACE::Tickers::TICKER_ENUM_MAX; diff --git a/java/src/main/java/org/rocksdb/TickerType.java b/java/src/main/java/org/rocksdb/TickerType.java index 678733513..095178df6 100644 --- a/java/src/main/java/org/rocksdb/TickerType.java +++ b/java/src/main/java/org/rocksdb/TickerType.java @@ -722,6 +722,16 @@ public enum TickerType { */ TXN_GET_TRY_AGAIN((byte) -0x0D), + /** + * # of files marked as trash by delete scheduler + */ + FILES_MARKED_TRASH((byte) -0x0E), + + /** + * # of files deleted immediately by delete scheduler + */ + FILES_DELETED_IMMEDIATELY((byte) -0x0f), + TICKER_ENUM_MAX((byte) 0x5F); private final byte value; diff --git a/monitoring/statistics.cc b/monitoring/statistics.cc index eb2d0c61e..cc523d58b 100644 --- a/monitoring/statistics.cc +++ b/monitoring/statistics.cc @@ -184,6 +184,8 @@ const std::vector> TickersNameMap = { {BLOCK_CACHE_DATA_ADD_REDUNDANT, "rocksdb.block.cache.data.add.redundant"}, {BLOCK_CACHE_COMPRESSION_DICT_ADD_REDUNDANT, "rocksdb.block.cache.compression.dict.add.redundant"}, + {FILES_MARKED_TRASH, "rocksdb.files.marked.trash"}, + {FILES_DELETED_IMMEDIATELY, "rocksdb.files.deleted.immediately"}, }; const std::vector> HistogramsNameMap = {