crimson/os/seastore/lba_manager: consolidate logs

Signed-off-by: Yingxin Cheng <yingxin.cheng@intel.com>

diff --git a/src/crimson/os/seastore/lba_manager/btree/btree_lba_manager.cc b/src/crimson/os/seastore/lba_manager/btree/btree_lba_manager.cc
index 09cb7fe9be5adf006fdf8444b86563892effdf7b..dec4254344a1809f42e390feb96418f64ea08802 100644 (file)
--- a/src/crimson/os/seastore/lba_manager/btree/btree_lba_manager.cc
+++ b/src/crimson/os/seastore/lba_manager/btree/btree_lba_manager.cc
@@ -11,12 +11,20 @@
 #include "crimson/os/seastore/logging.h"
 
 SET_SUBSYS(seastore_lba);
+/*
+ * levels:
+ * - INFO:  mkfs
+ * - DEBUG: modification operations
+ * - TRACE: read operations, DEBUG details
+ */
 
 namespace crimson::os::seastore::lba_manager::btree {
 
 BtreeLBAManager::mkfs_ret BtreeLBAManager::mkfs(
   Transaction &t)
 {
+  LOG_PREFIX(BtreeLBAManager::mkfs);
+  INFOT("start", t);
   return cache.get_root(t).si_then([this, &t](auto croot) {
     croot->get_root().lba_root = LBABtree::mkfs(get_context(t));
     return mkfs_iertr::now();
@@ -34,20 +42,24 @@ BtreeLBAManager::get_mappings(
   laddr_t offset, extent_len_t length)
 {
   LOG_PREFIX(BtreeLBAManager::get_mappings);
-  DEBUGT("offset: {}, length{}", t, offset, length);
+  TRACET("{}~{}", t, offset, length);
   auto c = get_context(t);
   return with_btree_state<lba_pin_list_t>(
     c,
-    [c, offset, length](auto &btree, auto &ret) {
+    [c, offset, length, FNAME](auto &btree, auto &ret) {
       return LBABtree::iterate_repeat(
        c,
        btree.upper_bound_right(c, offset),
-       [&ret, offset, length](auto &pos) {
+       [&ret, offset, length, c, FNAME](auto &pos) {
          if (pos.is_end() || pos.get_key() >= (offset + length)) {
+           TRACET("{}~{} done with {} results",
+                  c.trans, offset, length, ret.size());
            return LBABtree::iterate_repeat_ret_inner(
              interruptible::ready_future_marker{},
              seastar::stop_iteration::yes);
          }
+         TRACET("{}~{} got {}, {}, repeat ...",
+                c.trans, offset, length, pos.get_key(), pos.get_val());
          ceph_assert((pos.get_key() + pos.get_val().len) > offset);
          ret.push_back(pos.get_pin());
          return LBABtree::iterate_repeat_ret_inner(
@@ -64,7 +76,7 @@ BtreeLBAManager::get_mappings(
   laddr_list_t &&list)
 {
   LOG_PREFIX(BtreeLBAManager::get_mappings);
-  DEBUGT("{}", t, list);
+  TRACET("{}", t, list);
   auto l = std::make_unique<laddr_list_t>(std::move(list));
   auto retptr = std::make_unique<lba_pin_list_t>();
   auto &ret = *retptr;
@@ -88,7 +100,7 @@ BtreeLBAManager::get_mapping(
   laddr_t offset)
 {
   LOG_PREFIX(BtreeLBAManager::get_mapping);
-  DEBUGT("{}", t, offset);
+  TRACET("{}", t, offset);
   auto c = get_context(t);
   return with_btree_ret<LBAPinRef>(
     c,
@@ -97,10 +109,12 @@ BtreeLBAManager::get_mapping(
        c, offset
       ).si_then([FNAME, offset, c](auto iter) -> get_mapping_ret {
        if (iter.is_end() || iter.get_key() != offset) {
+         DEBUGT("{} doesn't exist", c.trans, offset);
          return crimson::ct_error::enoent::make();
        } else {
+         TRACET("{} got {}, {}",
+                c.trans, offset, iter.get_key(), iter.get_val());
          auto e = iter.get_pin();
-         DEBUGT("got mapping {}", c.trans, *e);
          return get_mapping_ret(
            interruptible::ready_future_marker{},
            std::move(e));
@@ -127,47 +141,59 @@ BtreeLBAManager::alloc_extent(
   };
 
   LOG_PREFIX(BtreeLBAManager::alloc_extent);
-  DEBUGT("hint: {}, length: {}", t, hint, len);
+  TRACET("{}~{}, hint={}", t, addr, len, hint);
   auto c = get_context(t);
   ++stats.num_alloc_extents;
+  auto lookup_attempts = stats.num_alloc_extents_iter_nexts;
   return with_btree_state<state_t>(
     c,
     hint,
-    [this, FNAME, c, hint, len, addr, &t](auto &btree, auto &state) {
+    [this, FNAME, c, hint, len, addr, lookup_attempts, &t](auto &btree, auto &state) {
       return LBABtree::iterate_repeat(
        c,
        btree.upper_bound_right(c, hint),
-       [this, &state, len, &t, hint, FNAME](auto &pos) {
+       [this, &state, len, addr, &t, hint, FNAME, lookup_attempts](auto &pos) {
          ++stats.num_alloc_extents_iter_nexts;
-         if (!pos.is_end()) {
-           DEBUGT("iterate_repeat: pos: {}~{}, state: {}~{}, hint: {}",
-                   t,
-                   pos.get_key(),
-                   pos.get_val().len,
+         if (pos.is_end()) {
+           DEBUGT("{}~{}, hint={}, state: end, done with {} attempts, insert at {}",
+                   t, addr, len, hint,
+                   stats.num_alloc_extents_iter_nexts - lookup_attempts,
+                   state.last_end);
+           state.insert_iter = pos;
+           return LBABtree::iterate_repeat_ret_inner(
+             interruptible::ready_future_marker{},
+             seastar::stop_iteration::yes);
+         } else if (pos.get_key() >= (state.last_end + len)) {
+           DEBUGT("{}~{}, hint={}, state: {}~{}, done with {} attempts, insert at {} -- {}",
+                   t, addr, len, hint,
+                   pos.get_key(), pos.get_val().len,
+                   stats.num_alloc_extents_iter_nexts - lookup_attempts,
                    state.last_end,
-                   len,
-                   hint);
-         }
-         if (pos.is_end() || pos.get_key() >= (state.last_end + len)) {
+                   pos.get_val());
            state.insert_iter = pos;
            return LBABtree::iterate_repeat_ret_inner(
              interruptible::ready_future_marker{},
              seastar::stop_iteration::yes);
          } else {
            state.last_end = pos.get_key() + pos.get_val().len;
+           TRACET("{}~{}, hint={}, state: {}~{}, repeat ... -- {}",
+                   t, addr, len, hint,
+                   pos.get_key(), pos.get_val().len,
+                   pos.get_val());
            return LBABtree::iterate_repeat_ret_inner(
              interruptible::ready_future_marker{},
              seastar::stop_iteration::no);
          }
-       }).si_then([FNAME, c, addr, len, &btree, &state] {
-         DEBUGT("about to insert at addr {}~{}", c.trans, state.last_end, len);
+       }).si_then([FNAME, c, addr, len, hint, &btree, &state] {
          return btree.insert(
            c,
            *state.insert_iter,
            state.last_end,
            lba_map_val_t{len, addr, 1, 0}
-         ).si_then([&state](auto &&p) {
+         ).si_then([&state, FNAME, c, addr, len, hint](auto &&p) {
            auto [iter, inserted] = std::move(p);
+           TRACET("{}~{}, hint={}, inserted at {}",
+                  c.trans, addr, len, hint, state.last_end);
            ceph_assert(inserted);
            state.ret = iter;
          });
@@ -210,6 +236,7 @@ void BtreeLBAManager::complete_transaction(
   Transaction &t)
 {
   LOG_PREFIX(BtreeLBAManager::complete_transaction);
+  DEBUGT("start", t);
   std::vector<CachedExtentRef> to_clear;
   to_clear.reserve(t.get_retired_set().size());
   for (auto &e: t.get_retired_set()) {
@@ -223,7 +250,7 @@ void BtreeLBAManager::complete_transaction(
 
   for (auto &e: to_clear) {
     auto &pin = get_pin(*e);
-    DEBUGT("retiring {}, {}", t, *e, pin);
+    DEBUGT("retiring extent {} -- {}", t, pin, *e);
     pin_set.retire(pin);
   }
 
@@ -240,13 +267,13 @@ void BtreeLBAManager::complete_transaction(
     [](auto &l, auto &r) -> bool { return get_depth(*l) > get_depth(*r); });
 
   for (auto &e : to_link) {
-    DEBUGT("linking {}", t, *e);
+    DEBUGT("linking extent -- {}", t, *e);
     pin_set.add_pin(get_pin(*e));
   }
 
   for (auto &e: to_clear) {
     auto &pin = get_pin(*e);
-    DEBUGT("checking {}, {}", t, *e, pin);
+    TRACET("checking extent {} -- {}", t, pin, *e);
     pin_set.check_parent(pin);
   }
 }
@@ -256,15 +283,16 @@ BtreeLBAManager::init_cached_extent_ret BtreeLBAManager::init_cached_extent(
   CachedExtentRef e)
 {
   LOG_PREFIX(BtreeLBAManager::init_cached_extent);
-  DEBUGT("extent {}", t, *e);
-  return seastar::do_with(bool(), [this, e, &t](bool& ret) {
+  TRACET("{}", t, *e);
+  return seastar::do_with(bool(), [this, e, FNAME, &t](bool& ret) {
     auto c = get_context(t);
     return with_btree(c, [c, e, &ret](auto &btree) {
       return btree.init_cached_extent(c, e
       ).si_then([&ret](bool is_alive) {
         ret = is_alive;
       });
-    }).si_then([&ret] {
+    }).si_then([&ret, e, FNAME, c] {
+      DEBUGT("is_alive={} -- {}", c.trans, ret, *e);
       return ret;
     });
   });
@@ -306,7 +334,7 @@ BtreeLBAManager::scan_mapped_space_ret BtreeLBAManager::scan_mapped_space(
     scan_mapped_space_func_t &&f)
 {
   LOG_PREFIX(BtreeLBAManager::scan_mapped_space);
-  DEBUGT("", t);
+  DEBUGT("start", t);
   auto c = get_context(t);
   return seastar::do_with(
     std::move(f),
@@ -339,14 +367,13 @@ BtreeLBAManager::rewrite_extent_ret BtreeLBAManager::rewrite_extent(
 {
   LOG_PREFIX(BtreeLBAManager::rewrite_extent);
   if (extent->has_been_invalidated()) {
-    ERRORT("{} has been invalidated", t, *extent);
+    ERRORT("extent has been invalidated -- {}", t, *extent);
+    ceph_abort();
   }
-  assert(!extent->has_been_invalidated());
   assert(!extent->is_logical());
 
-  DEBUGT("rewriting {}", t, *extent);
-
   if (is_lba_node(*extent)) {
+    DEBUGT("rewriting lba extent -- {}", t, *extent);
     auto c = get_context(t);
     return with_btree(
       c,
@@ -354,6 +381,7 @@ BtreeLBAManager::rewrite_extent_ret BtreeLBAManager::rewrite_extent(
        return btree.rewrite_lba_extent(c, extent);
       });
   } else {
+    DEBUGT("skip non lba extent -- {}", t, *extent);
     return rewrite_extent_iertr::now();
   }
 }
@@ -365,6 +393,8 @@ BtreeLBAManager::update_mapping(
   paddr_t prev_addr,
   paddr_t addr)
 {
+  LOG_PREFIX(BtreeLBAManager::update_mapping);
+  TRACET("laddr={}, paddr {} => {}", t, laddr, prev_addr, addr);
   return update_mapping(
     t,
     laddr,
@@ -375,14 +405,17 @@ BtreeLBAManager::update_mapping(
       ceph_assert(in.paddr == prev_addr);
       ret.paddr = addr;
       return ret;
-    }).si_then(
-      [](auto) {},
-      update_le_mapping_iertr::pass_further{},
-      /* ENOENT in particular should be impossible */
-      crimson::ct_error::assert_all{
-       "Invalid error in BtreeLBAManager::rewrite_extent after update_mapping"
-      }
-    );
+    }
+  ).si_then([&t, laddr, prev_addr, addr, FNAME](auto result) {
+      DEBUGT("laddr={}, paddr {} => {} done -- {}",
+             t, laddr, prev_addr, addr, result);
+    },
+    update_le_mapping_iertr::pass_further{},
+    /* ENOENT in particular should be impossible */
+    crimson::ct_error::assert_all{
+      "Invalid error in BtreeLBAManager::rewrite_extent after update_mapping"
+    }
+  );
 }
 
 BtreeLBAManager::get_physical_extent_if_live_ret
@@ -393,6 +426,9 @@ BtreeLBAManager::get_physical_extent_if_live(
   laddr_t laddr,
   seastore_off_t len)
 {
+  LOG_PREFIX(BtreeLBAManager::get_physical_extent_if_live);
+  DEBUGT("{}, laddr={}, paddr={}, length={}",
+         t, type, laddr, addr, len);
   ceph_assert(is_lba_node(type));
   auto c = get_context(t);
   return with_btree_ret<CachedExtentRef>(
@@ -418,6 +454,8 @@ BtreeLBAManager::BtreeLBAManager(
 
 void BtreeLBAManager::register_metrics()
 {
+  LOG_PREFIX(BtreeLBAManager::register_metrics);
+  DEBUG("start");
   stats = {};
   namespace sm = seastar::metrics;
   metrics.add_group(
@@ -443,7 +481,7 @@ BtreeLBAManager::update_refcount_ret BtreeLBAManager::update_refcount(
   int delta)
 {
   LOG_PREFIX(BtreeLBAManager::update_refcount);
-  DEBUGT("addr {}, delta {}", t, addr, delta);
+  TRACET("laddr={}, delta={}", t, addr, delta);
   return update_mapping(
     t,
     addr,
@@ -452,13 +490,15 @@ BtreeLBAManager::update_refcount_ret BtreeLBAManager::update_refcount(
       ceph_assert((int)out.refcount + delta >= 0);
       out.refcount += delta;
       return out;
-    }).si_then([](auto result) {
-      return ref_update_result_t{
-       result.refcount,
-       result.paddr,
-       result.len
-       };
-    });
+    }
+  ).si_then([&t, addr, delta, FNAME](auto result) {
+    DEBUGT("laddr={}, delta={} done -- {}", t, addr, delta, result);
+    return ref_update_result_t{
+      result.refcount,
+      result.paddr,
+      result.len
+     };
+  });
 }
 
 BtreeLBAManager::update_mapping_ret BtreeLBAManager::update_mapping(
@@ -466,8 +506,6 @@ BtreeLBAManager::update_mapping_ret BtreeLBAManager::update_mapping(
   laddr_t addr,
   update_func_t &&f)
 {
-  LOG_PREFIX(BtreeLBAManager::update_mapping);
-  DEBUGT("addr {}", t, addr);
   auto c = get_context(t);
   return with_btree_ret<lba_map_val_t>(
     c,
@@ -477,6 +515,8 @@ BtreeLBAManager::update_mapping_ret BtreeLBAManager::update_mapping(
       ).si_then([&btree, f=std::move(f), c, addr](auto iter)
                -> update_mapping_ret {
        if (iter.is_end() || iter.get_key() != addr) {
+         LOG_PREFIX(BtreeLBAManager::update_mapping);
+         DEBUGT("laddr={} doesn't exist", c.trans, addr);
          return crimson::ct_error::enoent::make();
        }
 
@@ -505,7 +545,8 @@ BtreeLBAManager::~BtreeLBAManager()
 {
   pin_set.scan([](auto &i) {
     LOG_PREFIX(BtreeLBAManager::~BtreeLBAManager);
-    ERROR("Found {} {} has_ref={}", i, i.get_extent(), i.has_ref());
+    ERROR("Found {}, has_ref={} -- {}",
+          i, i.has_ref(), i.get_extent());
   });
 }
 

diff --git a/src/crimson/os/seastore/lba_manager/btree/btree_range_pin.cc b/src/crimson/os/seastore/lba_manager/btree/btree_range_pin.cc
index 694c702283535e600eca5c5c8f482347e57ab975..21c4279edc8bc3418253f79bc7783e1ca4c9f293 100644 (file)
--- a/src/crimson/os/seastore/lba_manager/btree/btree_range_pin.cc
+++ b/src/crimson/os/seastore/lba_manager/btree/btree_range_pin.cc
@@ -29,7 +29,7 @@ btree_range_pin_t::~btree_range_pin_t()
   ceph_assert(!pins == !is_linked());
   ceph_assert(!ref);
   if (pins) {
-    DEBUG("removing {}", *this);
+    TRACE("removing {}", *this);
     pins->remove_pin(*this, true);
   }
   extent = nullptr;
@@ -43,7 +43,7 @@ void btree_pin_set_t::replace_pin(btree_range_pin_t &to, btree_range_pin_t &from
 void btree_pin_set_t::remove_pin(btree_range_pin_t &pin, bool do_check_parent)
 {
   LOG_PREFIX(btree_pin_set_t::remove_pin);
-  DEBUG("{}", pin);
+  TRACE("{}", pin);
   ceph_assert(pin.is_linked());
   ceph_assert(pin.pins);
   ceph_assert(!pin.ref);
@@ -124,14 +124,14 @@ void btree_pin_set_t::add_pin(btree_range_pin_t &pin)
     auto *parent = maybe_get_parent(pin.range);
     ceph_assert(parent);
     if (!parent->has_ref()) {
-      DEBUG("acquiring parent {}", static_cast<void*>(parent));
+      TRACE("acquiring parent {}", static_cast<void*>(parent));
       parent->acquire_ref();
     } else {
-      DEBUG("parent has ref {}", static_cast<void*>(parent));
+      TRACE("parent has ref {}", static_cast<void*>(parent));
     }
   }
   if (maybe_get_first_child(pin.range) != nullptr) {
-    DEBUG("acquiring self {}", pin);
+    TRACE("acquiring self {}", pin);
     pin.acquire_ref();
   }
 }
@@ -147,7 +147,7 @@ void btree_pin_set_t::check_parent(btree_range_pin_t &pin)
   LOG_PREFIX(btree_pin_set_t::check_parent);
   auto parent = maybe_get_parent(pin.range);
   if (parent) {
-    DEBUG("releasing parent {}", *parent);
+    TRACE("releasing parent {}", *parent);
     release_if_no_children(*parent);
   }
 }

diff --git a/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.cc b/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.cc
index f83730b90b100a5f568ea1118b2668e5cd5bf464..a6ee25e9170240583c7738dcfa0f99a2a7bf1656 100644 (file)
--- a/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.cc
+++ b/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.cc
@@ -17,6 +17,16 @@ SET_SUBSYS(seastore_lba);
 
 namespace crimson::os::seastore::lba_manager::btree {
 
+std::ostream& operator<<(std::ostream& out, const lba_map_val_t& v)
+{
+  return out << "lba_map_val_t("
+             << v.paddr
+             << "~" << v.len
+             << ", refcount=" << v.refcount
+             << ", checksum=" << v.checksum
+             << ")";
+}
+
 std::ostream &LBAInternalNode::print_detail(std::ostream &out) const
 {
   return out << ", size=" << get_size()
@@ -29,7 +39,7 @@ void LBAInternalNode::resolve_relative_addrs(paddr_t base)
   for (auto i: *this) {
     if (i->get_val().is_relative()) {
       auto updated = base.add_relative(i->get_val());
-      DEBUG("{} -> {}", i->get_val(), updated);
+      TRACE("{} -> {}", i->get_val(), updated);
       i->set_val(updated);
     }
   }
@@ -48,7 +58,7 @@ void LBALeafNode::resolve_relative_addrs(paddr_t base)
     if (i->get_val().paddr.is_relative()) {
       auto val = i->get_val();
       val.paddr = base.add_relative(val.paddr);
-      DEBUG("{} -> {}", i->get_val().paddr, val.paddr);
+      TRACE("{} -> {}", i->get_val().paddr, val.paddr);
       i->set_val(val);
     }
   }

diff --git a/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.h b/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.h
index 7f5c97c8893dfd72102d20eccf737ec2f040e45a..683efbed46a7efde2a74c50c01c7c48c5ae38a59 100644 (file)
--- a/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.h
+++ b/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.h
@@ -55,6 +55,8 @@ WRITE_EQ_OPERATORS_4(
   refcount,
   checksum);
 
+std::ostream& operator<<(std::ostream& out, const lba_map_val_t&);
+
 class BtreeLBAPin;
 using BtreeLBAPinRef = std::unique_ptr<BtreeLBAPin>;