debug

diff --git a/src/crimson/os/seastore/backref/btree_backref_manager.cc b/src/crimson/os/seastore/backref/btree_backref_manager.cc
index 505ed21790dd721f378f6cda314e94cab8d8c65b..d818d02ac498d92ebcd3631c2a967ec16aacba78 100644 (file)
--- a/src/crimson/os/seastore/backref/btree_backref_manager.cc
+++ b/src/crimson/os/seastore/backref/btree_backref_manager.cc
@@ -473,22 +473,22 @@ BtreeBackrefManager::scan_device(
     auto bentry = cache.get_cached_backref_entry(key);
     if (bentry) {
       assert(bentry->paddr == key);
-      DEBUGT("found in cache: {} {}", t, bentry->paddr, bentry->laddr);
+      INFOT("found in cache: {} {}", t, bentry->paddr, bentry->laddr);
     }
     if (bentry && bentry->laddr == L_ADDR_NULL) {
-      DEBUGT("{} is removed", t, bentry->paddr);
+      INFOT("{} is removed", t, bentry->paddr);
       iter = co_await iter.next(c);
       continue;
     }
     if (key.get_device_id() == paddr.get_device_id()) {
       auto val = iter.get_val();
       if (bentry && bentry->laddr != val.laddr) {
-        DEBUGT("{} changed from {} to {}",
+        INFOT("{} changed from {} to {}",
           t, bentry->paddr, val.laddr, bentry->laddr);
         iter = co_await iter.next(c);
         continue;
       }
-      DEBUGT("scanned {}, {}", t, key, val.laddr);
+      INFOT("scanned {}, {}", t, key, val.laddr);
       auto ret = co_await f(key, val.len, val.type, val.laddr);
       if (ret == seastar::stop_iteration::yes) {
        break;

diff --git a/src/crimson/os/seastore/cache.cc b/src/crimson/os/seastore/cache.cc
index fc0fb45dc72caf5ce0bf5ea1870808871ff7a25b..5918996747bbb9ae6b8d80dc67586cc68c9e319e 100644 (file)
--- a/src/crimson/os/seastore/cache.cc
+++ b/src/crimson/os/seastore/cache.cc
@@ -1877,6 +1877,10 @@ record_t Cache::prepare_record(
       continue;
     }
 
+    DEBUGT("backref_entry alloc existing {}~0x{:x}",
+           t,
+           i->get_paddr(),
+           i->get_length());
     // Note: commit extents and backref allocations in the same place
     // Note: remapping is split into 2 steps, retire and alloc, they must be
     //       committed atomically together

diff --git a/src/crimson/os/seastore/extent_pinboard.cc b/src/crimson/os/seastore/extent_pinboard.cc
index 7c5df07bf977321d72a2ccaa82fbf578295d0b65..2c0b170a8173a710d7b78c8c480818cc84bb7a9e 100644 (file)
--- a/src/crimson/os/seastore/extent_pinboard.cc
+++ b/src/crimson/os/seastore/extent_pinboard.cc
@@ -322,6 +322,8 @@ public:
   }
 
   void add_extent(CachedExtent &extent) {
+    LOG_PREFIX(ExtentPromoter::add_extent);
+    INFO("{} current_contents: 0x{:x}", extent, current_contents);
     assert(!extent.is_linked_to_list());
     assert(extent.is_stable_clean());
     extent.set_pin_state(extent_pin_state_t::PendingPromote);
@@ -329,6 +331,7 @@ public:
     current_contents += extent.get_length();
     intrusive_ptr_add_ref(&extent);
     while (current_contents > promotion_size) {
+      INFO("removing front {}", list.front());
       remove_extent(list.front(), extent_pin_state_t::Fresh);
     }
     if (should_run_promote()) {
@@ -338,6 +341,8 @@ public:
   }
 
   void remove_extent(CachedExtent &extent, extent_pin_state_t new_state) {
+    LOG_PREFIX(ExtentPromoter::remove_extent);
+    INFO("{} {} curent_contents: 0x{:x}", extent, new_state, current_contents);
     assert(extent.is_linked_to_list());
     assert(extent.get_pin_state() == extent_pin_state_t::PendingPromote);
     assert(current_contents >= extent.get_length());
@@ -358,7 +363,7 @@ public:
     LOG_PREFIX(ExtentPromoter::run_promote);
     std::size_t promote_size = 0;
     std::list<CachedExtentRef> extents;
-    DEBUGT("start promote", t);
+    INFOT("start promote", t);
     if (current_contents < promotion_size && test_workload) {
       auto id = epm.get_cold_device_id();
       paddr_t start = P_ADDR_NULL;

diff --git a/src/crimson/os/seastore/extent_placement_manager.cc b/src/crimson/os/seastore/extent_placement_manager.cc
index 9bc1e80e12295490895a0beb6c7fbfab94de871e..46f5d13d65d568281f0e15a781487dfe4610c172 100644 (file)
--- a/src/crimson/os/seastore/extent_placement_manager.cc
+++ b/src/crimson/os/seastore/extent_placement_manager.cc
@@ -214,7 +214,7 @@ void ExtentPlacementManager::init(
   if (cold_cleaner) {
     dynamic_max_rewrite_generation = hot_tier_generations + cold_tier_generations - 1;
   }
-  DEBUG("dynamic_max_rewrite_generation: {}, "
+  INFO("dynamic_max_rewrite_generation: {}, "
         "hot_tier_generations{} , cold_tier_generations {}",
         dynamic_max_rewrite_generation, hot_tier_generations,
         cold_tier_generations);
@@ -637,12 +637,12 @@ ExtentPlacementManager::close()
 void ExtentPlacementManager::BackgroundProcess::log_state(const char *caller) const
 {
   LOG_PREFIX(BackgroundProcess::log_state);
-  DEBUG("caller {}, {}, {}",
+  INFO("caller {}, {}, {}",
         caller,
         JournalTrimmerImpl::stat_printer_t{*trimmer, true},
         AsyncCleaner::stat_printer_t{*main_cleaner, true});
   if (has_cold_tier()) {
-    DEBUG("caller {}, cold_cleaner: {}",
+    INFO("caller {}, cold_cleaner: {}",
           caller,
           AsyncCleaner::stat_printer_t{*cold_cleaner, true});
   }
@@ -1020,6 +1020,7 @@ seastar::future<>
 ExtentPlacementManager::BackgroundProcess::do_background_cycle()
 {
   LOG_PREFIX(BackgroundProcess::do_background_cycle);
+  INFO("");
   assert(is_ready());
   bool should_trim = trimmer->should_trim();
   bool proceed_trim = false;
@@ -1057,10 +1058,10 @@ ExtentPlacementManager::BackgroundProcess::do_background_cycle()
   }
 
   if (proceed_trim) {
-    DEBUG("started trimming...");
+    INFO("started trimming...");
     return trimmer->trim(force_trim
     ).finally([this, trim_usage, should_abort_cleaner_usage, FNAME] {
-      DEBUG("finished trimming");
+      INFO("finished trimming");
       if (should_abort_cleaner_usage) {
         abort_cleaner_usage(trim_usage, {true, true});
       }
@@ -1100,6 +1101,9 @@ ExtentPlacementManager::BackgroundProcess::do_background_cycle()
          logical_bucket->should_demote())) {
       proceed_demote = true;
     }
+    INFO("proceed_demote: {}, could_demote: {}, fast_mode: {}, should_demote {}",
+      proceed_demote, logical_bucket->could_demote(),
+      eviction_state.is_fast_mode(), logical_bucket->should_demote());
 
     bool abort_cold_cleaner_usage = true;
     if (unlikely(test_workload && force_process_state == ForceProcessState::CLEAN)) {

diff --git a/src/crimson/os/seastore/extent_placement_manager.h b/src/crimson/os/seastore/extent_placement_manager.h
index a533fbbd0d382fa3078e32101292ca38ec53fa62..01142294ffb6b004f7e6b0dadc78f5999805cbee 100644 (file)
--- a/src/crimson/os/seastore/extent_placement_manager.h
+++ b/src/crimson/os/seastore/extent_placement_manager.h
@@ -745,6 +745,7 @@ private:
       rewrite_gen_t gen,
       write_policy_t policy,
       bool is_tracked) {
+    LOG_PREFIX(ExtentPlacementManager::adjust_generation);
     assert(is_real_type(type));
     if (is_root_type(type)) {
       gen = INLINE_GENERATION;
@@ -792,6 +793,7 @@ private:
         hint != placement_hint_t::REWRITE &&
         hint != placement_hint_t::COLD) {
       gen = hot_tier_generations - 1;
+      SUBINFO(seastore_epm, "setting gen to {}", gen);
     }
 
     if (gen > dynamic_max_rewrite_generation) {
@@ -1098,6 +1100,8 @@ private:
     }
 
     seastar::future<> wait_background() {
+      LOG_PREFIX(BackgroundProcess::wait_background);
+      SUBINFO(seastore_epm, "");
       if (!blocking_io) {
         blocking_io = seastar::promise<>();
       }
@@ -1206,7 +1210,7 @@ private:
     }
 
     struct eviction_state_t {
-      enum class eviction_mode_t {
+      enum class eviction_mode_t : uint8_t {
         STOP,     // generation greater than or equal to MIN_COLD_GENERATION
                   // will be set to MIN_COLD_GENERATION - 1, which means
                   // no extents will be evicted.
@@ -1252,6 +1256,8 @@ private:
 
       rewrite_gen_t adjust_generation_with_eviction(rewrite_gen_t gen) {
         rewrite_gen_t ret = gen;
+        LOG_PREFIX(eviction_state_t::adjust_generation_with_eviction);
+        SUBINFO(seastore_epm, "gen={} mode={}", gen, (uint8_t)eviction_mode);
         switch(eviction_mode) {
         case eviction_mode_t::STOP:
           if (gen == hot_tier_generations) {

diff --git a/src/crimson/os/seastore/logical_bucket.cc b/src/crimson/os/seastore/logical_bucket.cc
index f234274bdcde888300e37ca70b5bddcdd43fc1ca..47989356c5521f5145e757b61b1071f0efafed37 100644 (file)
--- a/src/crimson/os/seastore/logical_bucket.cc
+++ b/src/crimson/os/seastore/logical_bucket.cc
@@ -41,11 +41,11 @@ public:
     assert(laddr == laddr.get_object_prefix());
     auto iter = index.find(laddr);
     if (iter != index.end()) {
-      TRACE("find bucket: {}", iter->first);
+      INFO("find bucket: {}", iter->first);
       iter->second->demoting = false;
       lru.splice(lru.end(), lru, iter->second);
     } else {
-      TRACE("create bucket: {}", laddr);
+      INFO("create bucket: {}", laddr);
       index[laddr] = lru.emplace(lru.end(), laddr);
       if (should_demote()) {
        assert(listener);
@@ -124,7 +124,7 @@ public:
 
     co_await ecb->submit_transaction_direct(t);
 
-    DEBUGT("finish demoting {} buckets with {} bytes evicted and {} bytes demoted",
+    INFOT("finish demoting {} buckets with {} bytes evicted and {} bytes demoted",
           t, completed_buckets.size(), evicted_size, demoted_size);
     stat.demoted_bucket_count += completed_buckets.size();
     stat.demoted_size += demoted_size;
@@ -169,7 +169,7 @@ private:
     auto iter = index.find(laddr);
     if (iter != index.end()) {
       if (iter->second->demoting) {
-       DEBUG("remove bucket: {}", laddr);
+       INFO("remove bucket: {}", laddr);
        lru.erase(iter->second);
        index.erase(iter);
       } else {

diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc
index 449502945c25a1229a1087d9b46f61ac9afcbe45..245a2e7d64914b399198088d78c9c76b35e6db9e 100644 (file)
--- a/src/crimson/os/seastore/transaction_manager.cc
+++ b/src/crimson/os/seastore/transaction_manager.cc
@@ -923,7 +923,7 @@ TransactionManager::rewrite_logical_extent(
     }
     nextent->rewrite(t, *extent, 0);
 
-    DEBUGT("rewriting meta -- {} to {}", t, *extent, *nextent);
+    INFOT("rewriting meta -- {} to {}", t, *extent, *nextent);
 
 #ifndef NDEBUG
     if (get_checksum_needed(extent->get_paddr())) {
@@ -991,7 +991,7 @@ TransactionManager::rewrite_logical_extent(
       bool first_extent = (off == 0);
       ceph_assert(left >= nextent->get_length());
       nextent->rewrite(t, *extent, off);
-      DEBUGT("rewriting data -- {} to {}", t, *extent, *nextent);
+      INFOT("rewriting data -- {} to {}", t, *extent, *nextent);
 
       /* This update_mapping is, strictly speaking, unnecessary for delayed_alloc
        * extents since we're going to do it again once we either do the ool write
@@ -1250,7 +1250,7 @@ TransactionManager::promote_extent(
 {
   LOG_PREFIX(TransactionManager::promote_extent);
   assert(epm->is_cold_device(extent->get_paddr().get_device_id()));
-  DEBUGT("promote extent: {}", t, *extent);
+  INFOT("promote extent: {}", t, *extent);
   ceph_assert(extent->is_logical());
 
   std::vector<LogicalChildNodeRef> promoted_extents;
@@ -1512,7 +1512,7 @@ TransactionManager::demote_region(
 {
   LOG_PREFIX(TransactionManager::demote_region);
   auto prefix = start.get_object_prefix();
-  DEBUGT("start demote {}", t, prefix);
+  INFOT("start demote {}", t, prefix);
   auto cursor = co_await lba_manager->upper_bound_right(
     t, start
   ).handle_error_interruptible(
@@ -1531,7 +1531,7 @@ TransactionManager::demote_region(
       continue;
     }
     if (it.has_shadow_val()) {
-      DEBUGT("demote shadow {}", t, it);
+      INFOT("demote shadow {}", t, it);
       auto extent = co_await relocate_shadow_extent(t, it);
       ret.demoted_size += extent->get_length();
       auto cursor = co_await lba_manager->demote_extent(
@@ -1540,14 +1540,14 @@ TransactionManager::demote_region(
       it = co_await nit.next();
     } else if (!it.is_indirect() && !it.is_zero_reserved() &&
       !epm->is_cold_device(it.get_val().get_device_id())) {
-      DEBUGT("demote hot {}", t, it);
+      INFOT("demote hot {}", t, it);
       auto extent = co_await read_cursor_by_type(
         t, it.direct_cursor, it.get_extent_type());
       ret.evicted_size += extent->get_length();
       extents.push_back(extent);
       it = co_await it.next();
     } else {
-      DEBUGT("skip {}", t, it);
+      INFOT("skip {}", t, it);
       it = co_await it.next();
     }
   }