crimson/os/seastore: add logs for background

Signed-off-by: Yingxin Cheng <yingxin.cheng@intel.com>
(cherry picked from commit 86041f1a3f639a4779c476aee1e32c0d35800c8e)

diff --git a/src/crimson/os/seastore/async_cleaner.cc b/src/crimson/os/seastore/async_cleaner.cc
index b895a88879f97c292f998a4483b7e81b59a192d2..aa6fcd8a95d6c08086b70347d90b0079f75e92af 100644 (file)
--- a/src/crimson/os/seastore/async_cleaner.cc
+++ b/src/crimson/os/seastore/async_cleaner.cc
@@ -1162,7 +1162,7 @@ SegmentCleaner::clean_space_ret SegmentCleaner::clean_space()
   if (!reclaim_state) {
     segment_id_t seg_id = get_next_reclaim_segment();
     auto &segment_info = segments[seg_id];
-    INFO("reclaim {} {} start, usage={}, time_bound={}",
+    INFO("reclaim start... {} {}, usage={}, time_bound={}",
          seg_id, segment_info,
          space_tracker->calc_utilization(seg_id),
          sea_time_point_printer_t{segments.get_time_bound()});
@@ -1239,7 +1239,7 @@ SegmentCleaner::clean_space_ret SegmentCleaner::clean_space()
               d, pavail_ratio, runs);
         if (reclaim_state->is_complete()) {
           auto segment_to_release = reclaim_state->get_segment_id();
-          INFO("reclaim {} finish, reclaimed alive/total={}",
+          INFO("reclaim finish {}, reclaimed alive/total={}",
                segment_to_release,
                stats.reclaiming_bytes/(double)segments.get_segment_size());
           stats.reclaimed_bytes += stats.reclaiming_bytes;
@@ -1263,7 +1263,7 @@ SegmentCleaner::clean_space_ret SegmentCleaner::clean_space()
             segments.mark_empty(segment_to_release);
             auto new_usage = calc_utilization(segment_to_release);
             adjust_segment_util(old_usage, new_usage);
-            INFO("released {}, {}",
+            INFO("reclaim released {}, {}",
                  segment_to_release, stat_printer_t{*this, false});
             background_callback->maybe_wake_blocked_io();
           });

diff --git a/src/crimson/os/seastore/extent_placement_manager.cc b/src/crimson/os/seastore/extent_placement_manager.cc
index 77bf1c5184c696de77282ec26accd105b7170de9..5f967e444d76ff6606a77a98b694b030d5360ef6 100644 (file)
--- a/src/crimson/os/seastore/extent_placement_manager.cc
+++ b/src/crimson/os/seastore/extent_placement_manager.cc
@@ -430,21 +430,25 @@ void ExtentPlacementManager::BackgroundProcess::start_background()
 seastar::future<>
 ExtentPlacementManager::BackgroundProcess::stop_background()
 {
-  return seastar::futurize_invoke([this] {
+  LOG_PREFIX(BackgroundProcess::stop_background);
+  return seastar::futurize_invoke([this, FNAME] {
     if (!is_running()) {
       if (state != state_t::HALT) {
+        INFO("isn't RUNNING or HALT, STOP");
         state = state_t::STOP;
+      } else {
+        INFO("isn't RUNNING, already HALT");
       }
       return seastar::now();
     }
+    INFO("is RUNNING, going to HALT...");
     auto ret = std::move(*process_join);
     process_join.reset();
     state = state_t::HALT;
     assert(!is_running());
     do_wake_background();
     return ret;
-  }).then([this] {
-    LOG_PREFIX(BackgroundProcess::stop_background);
+  }).then([this, FNAME] {
     INFO("done, {}, {}",
          JournalTrimmerImpl::stat_printer_t{*trimmer, true},
          AsyncCleaner::stat_printer_t{*main_cleaner, true});
@@ -452,18 +456,21 @@ ExtentPlacementManager::BackgroundProcess::stop_background()
       INFO("done, cold_cleaner: {}",
            AsyncCleaner::stat_printer_t{*cold_cleaner, true});
     }
-    // run_until_halt() can be called at HALT
   });
 }
 
 seastar::future<>
 ExtentPlacementManager::BackgroundProcess::run_until_halt()
 {
+  // unit test only
+  LOG_PREFIX(BackgroundProcess::run_until_halt);
   ceph_assert(state == state_t::HALT);
   assert(!is_running());
   if (is_running_until_halt) {
+    WARN("already running");
     return seastar::now();
   }
+  INFO("started...");
   is_running_until_halt = true;
   return seastar::do_until(
     [this] {
@@ -479,7 +486,9 @@ ExtentPlacementManager::BackgroundProcess::run_until_halt()
     [this] {
       return do_background_cycle();
     }
-  );
+  ).finally([FNAME] {
+    INFO("finished");
+  });
 }
 
 seastar::future<>
@@ -498,6 +507,12 @@ ExtentPlacementManager::BackgroundProcess::reserve_projected_usage(
   if (res.is_successful()) {
     return seastar::now();
   } else {
+    LOG_PREFIX(BackgroundProcess::reserve_projected_usage);
+    DEBUG("blocked: inline={}, main={}, cold={}, usage={}",
+          res.reserve_inline_success,
+          res.cleaner_result.reserve_main_success,
+          res.cleaner_result.reserve_cold_success,
+          usage);
     abort_io_usage(usage, res);
     if (!res.reserve_inline_success) {
       ++stats.io_blocked_count_trim;
@@ -509,18 +524,25 @@ ExtentPlacementManager::BackgroundProcess::reserve_projected_usage(
     ++stats.io_blocked_count;
     stats.io_blocked_sum += stats.io_blocking_num;
 
-    return seastar::repeat([this, usage] {
+    return seastar::repeat([this, usage, FNAME] {
+      DEBUG("setup and wait blocking_io...");
       blocking_io = seastar::promise<>();
       return blocking_io->get_future(
-      ).then([this, usage] {
+      ).then([this, usage, FNAME] {
         ceph_assert(!blocking_io);
         auto res = try_reserve_io(usage);
         if (res.is_successful()) {
+          DEBUG("unblocked");
           assert(stats.io_blocking_num == 1);
           --stats.io_blocking_num;
           return seastar::make_ready_future<seastar::stop_iteration>(
             seastar::stop_iteration::yes);
         } else {
+          DEBUG("blocked again: inline={}, main={}, cold={}, usage={}",
+                res.reserve_inline_success,
+                res.cleaner_result.reserve_main_success,
+                res.cleaner_result.reserve_cold_success,
+                usage);
           abort_io_usage(usage, res);
           return seastar::make_ready_future<seastar::stop_iteration>(
             seastar::stop_iteration::no);
@@ -530,6 +552,20 @@ ExtentPlacementManager::BackgroundProcess::reserve_projected_usage(
   }
 }
 
+void
+ExtentPlacementManager::BackgroundProcess::maybe_wake_blocked_io()
+{
+  if (!is_ready()) {
+    return;
+  }
+  LOG_PREFIX(ExtentPlacementManager::maybe_wake_blocked_io);
+  if (!should_block_io() && blocking_io) {
+    DEBUG("");
+    blocking_io->set_value();
+    blocking_io = std::nullopt;
+  }
+}
+
 seastar::future<>
 ExtentPlacementManager::BackgroundProcess::run()
 {
@@ -657,6 +693,7 @@ void ExtentPlacementManager::BackgroundProcess::abort_io_usage(
 seastar::future<>
 ExtentPlacementManager::BackgroundProcess::do_background_cycle()
 {
+  LOG_PREFIX(BackgroundProcess::do_background_cycle);
   assert(is_ready());
   bool should_trim = trimmer->should_trim();
   bool proceed_trim = false;
@@ -684,20 +721,19 @@ ExtentPlacementManager::BackgroundProcess::do_background_cycle()
   }
 
   if (proceed_trim) {
+    DEBUG("started trimming...");
     return trimmer->trim(
-    ).finally([this, trim_usage] {
+    ).finally([this, trim_usage, FNAME] {
+      DEBUG("finished trimming");
       abort_cleaner_usage(trim_usage, {true, true});
     });
   } else {
+    assert(!proceed_trim);
+    bool should_clean_main_for_trim =
+      should_trim && !trim_reserve_res.reserve_main_success;
     bool should_clean_main =
-      main_cleaner_should_run() ||
-      // make sure cleaner will start
-      // when the trimmer should run but
-      // failed to reserve space.
-      (should_trim && !proceed_trim &&
-       !trim_reserve_res.reserve_main_success);
+      main_cleaner_should_run() || should_clean_main_for_trim;
     bool proceed_clean_main = false;
-
     auto main_cold_usage = main_cleaner->get_reclaim_size_per_cycle();
     if (should_clean_main) {
       if (has_cold_tier()) {
@@ -707,12 +743,15 @@ ExtentPlacementManager::BackgroundProcess::do_background_cycle()
       }
     }
 
+    bool should_clean_cold_for_trim =
+      should_trim && !trim_reserve_res.reserve_cold_success;
+    bool should_clean_cold_for_main =
+      should_clean_main && !proceed_clean_main;
     bool proceed_clean_cold = false;
     if (has_cold_tier() &&
         (cold_cleaner->should_clean_space() ||
-         (should_trim && !proceed_trim &&
-          !trim_reserve_res.reserve_cold_success) ||
-         (should_clean_main && !proceed_clean_main))) {
+         should_clean_cold_for_trim ||
+         should_clean_cold_for_main)) {
       proceed_clean_cold = true;
     }
 
@@ -720,29 +759,44 @@ ExtentPlacementManager::BackgroundProcess::do_background_cycle()
       ceph_abort("no background process will start");
     }
     return seastar::when_all(
-      [this, proceed_clean_main, main_cold_usage] {
+      [this, FNAME, proceed_clean_main,
+       should_clean_main_for_trim, main_cold_usage] {
         if (!proceed_clean_main) {
           return seastar::now();
         }
+        DEBUG("started clean main... "
+              "should_clean={}, for_trim={}, for_fast_evict={}",
+              main_cleaner->should_clean_space(),
+              should_clean_main_for_trim,
+              main_cleaner_should_fast_evict());
         return main_cleaner->clean_space(
         ).handle_error(
           crimson::ct_error::assert_all{
             "do_background_cycle encountered invalid error in main clean_space"
           }
-        ).finally([this, main_cold_usage] {
+        ).finally([this, main_cold_usage, FNAME] {
+          DEBUG("finished clean main");
           abort_cold_usage(main_cold_usage, true);
         });
       },
-      [this, proceed_clean_cold] {
+      [this, FNAME, proceed_clean_cold,
+       should_clean_cold_for_trim, should_clean_cold_for_main] {
         if (!proceed_clean_cold) {
           return seastar::now();
         }
+        DEBUG("started clean cold... "
+              "should_clean={}, for_trim={}, for_main={}",
+              cold_cleaner->should_clean_space(),
+              should_clean_cold_for_trim,
+              should_clean_cold_for_main);
         return cold_cleaner->clean_space(
         ).handle_error(
           crimson::ct_error::assert_all{
             "do_background_cycle encountered invalid error in cold clean_space"
           }
-        );
+        ).finally([FNAME] {
+          DEBUG("finished clean cold");
+        });
       }
     ).discard_result();
   }

diff --git a/src/crimson/os/seastore/extent_placement_manager.h b/src/crimson/os/seastore/extent_placement_manager.h
index 10f00ce956e6300e2c7f27708ce585691985b9da..458336c02e9196c21ebc2e3599561e7cfb0cb2c1 100644 (file)
--- a/src/crimson/os/seastore/extent_placement_manager.h
+++ b/src/crimson/os/seastore/extent_placement_manager.h
@@ -794,15 +794,7 @@ private:
       }
     }
 
-    void maybe_wake_blocked_io() final {
-      if (!is_ready()) {
-        return;
-      }
-      if (!should_block_io() && blocking_io) {
-        blocking_io->set_value();
-        blocking_io = std::nullopt;
-      }
-    }
+    void maybe_wake_blocked_io() final;
 
   private:
     // reserve helpers
@@ -848,12 +840,16 @@ private:
         || trimmer->should_trim();
     }
 
+    bool main_cleaner_should_fast_evict() const {
+      return has_cold_tier() &&
+         main_cleaner->can_clean_space() &&
+         eviction_state.is_fast_mode();
+    }
+
     bool main_cleaner_should_run() const {
       assert(is_ready());
       return main_cleaner->should_clean_space() ||
-        (has_cold_tier() &&
-         main_cleaner->can_clean_space() &&
-         eviction_state.is_fast_mode());
+        main_cleaner_should_fast_evict();
     }
 
     bool cold_cleaner_should_run() const {