crimson/os/seastore/transaction_manager: consolidate logs in levels

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

diff --git a/src/crimson/os/seastore/seastore_types.cc b/src/crimson/os/seastore/seastore_types.cc
index f738870544cf61c76818e98f47708c43363a0771..d6f5fb94ba85e8ddc177f17d9c40debf873c385f 100644 (file)
--- a/src/crimson/os/seastore/seastore_types.cc
+++ b/src/crimson/os/seastore/seastore_types.cc
@@ -513,6 +513,20 @@ try_decode_deltas(
   return record_deltas;
 }
 
+std::ostream& operator<<(std::ostream& out, placement_hint_t h)
+{
+  switch (h) {
+  case placement_hint_t::HOT:
+    return out << "HOT";
+  case placement_hint_t::COLD:
+    return out << "COLD";
+  case placement_hint_t::REWRITE:
+    return out << "REWRITE";
+  default:
+    return out << "INVALID_PLACEMENT_HINT_TYPE!";
+  }
+}
+
 bool can_delay_allocation(device_type_t type) {
   // Some types of device may not support delayed allocation, for example PMEM.
   return type <= device_type_t::RANDOM_BLOCK;

diff --git a/src/crimson/os/seastore/seastore_types.h b/src/crimson/os/seastore/seastore_types.h
index db7c907a29a987e405f8606f49c5e8e0e9a96ad7..10f70afafa5cef56f502b76d162264a9ef7ca5cd 100644 (file)
--- a/src/crimson/os/seastore/seastore_types.h
+++ b/src/crimson/os/seastore/seastore_types.h
@@ -696,6 +696,8 @@ enum class placement_hint_t {
   NUM_HINTS  // Constant for number of hints
 };
 
+std::ostream& operator<<(std::ostream& out, placement_hint_t h);
+
 enum class device_type_t {
   NONE = 0,
   SEGMENTED, // i.e. Hard_Disk, SATA_SSD, NAND_NVME

diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc
index 769d759177c61d8361f680fe77e3a1f2138d0ca0..25252b34afd8fc9f8033b5cacfcecf47cbc5bd2b 100644 (file)
--- a/src/crimson/os/seastore/transaction_manager.cc
+++ b/src/crimson/os/seastore/transaction_manager.cc
@@ -13,6 +13,9 @@
  * TransactionManager logs
  *
  * levels:
+ * - INFO: major initiation, closing operations
+ * - DEBUG: major extent related operations, INFO details
+ * - TRACE: DEBUG details
  * - seastore_t logs
  */
 SET_SUBSYS(seastore_tm);
@@ -42,24 +45,23 @@ TransactionManager::TransactionManager(
 TransactionManager::mkfs_ertr::future<> TransactionManager::mkfs()
 {
   LOG_PREFIX(TransactionManager::mkfs);
+  INFO("enter");
   segment_cleaner->mount(
     segment_manager.get_device_id(),
     scanner.get_segment_managers());
   return journal->open_for_write().safe_then([this, FNAME](auto addr) {
-    DEBUG("about to do_with");
     segment_cleaner->init_mkfs(addr);
     return with_transaction_intr(
       Transaction::src_t::MUTATE,
       "mkfs_tm",
       [this, FNAME](auto& t)
     {
-      DEBUGT("about to cache->mkfs", t);
       cache->init();
       return cache->mkfs(t
       ).si_then([this, &t] {
         return lba_manager->mkfs(t);
       }).si_then([this, FNAME, &t] {
-        DEBUGT("about to submit_transaction", t);
+        INFOT("submitting mkfs transaction", t);
         return submit_transaction_direct(t);
       });
     }).handle_error(
@@ -71,12 +73,15 @@ TransactionManager::mkfs_ertr::future<> TransactionManager::mkfs()
     );
   }).safe_then([this] {
     return close();
+  }).safe_then([FNAME] {
+    INFO("completed");
   });
 }
 
 TransactionManager::mount_ertr::future<> TransactionManager::mount()
 {
   LOG_PREFIX(TransactionManager::mount);
+  INFO("enter");
   cache->init();
   segment_cleaner->mount(
     segment_manager.get_device_id(),
@@ -128,8 +133,9 @@ TransactionManager::mount_ertr::future<> TransactionManager::mount()
            });
          });
       });
-  }).safe_then([this] {
+  }).safe_then([this, FNAME] {
     segment_cleaner->complete_init();
+    INFO("completed");
   }).handle_error(
     mount_ertr::pass_further{},
     crimson::ct_error::all_same_way([] {
@@ -140,7 +146,7 @@ TransactionManager::mount_ertr::future<> TransactionManager::mount()
 
 TransactionManager::close_ertr::future<> TransactionManager::close() {
   LOG_PREFIX(TransactionManager::close);
-  DEBUG("enter");
+  INFO("enter");
   return segment_cleaner->stop(
   ).then([this] {
     return cache->close();
@@ -148,7 +154,7 @@ TransactionManager::close_ertr::future<> TransactionManager::close() {
     cache->dump_contents();
     return journal->close();
   }).safe_then([FNAME] {
-    DEBUG("completed");
+    INFO("completed");
     return seastar::now();
   });
 }
@@ -157,8 +163,13 @@ TransactionManager::ref_ret TransactionManager::inc_ref(
   Transaction &t,
   LogicalCachedExtentRef &ref)
 {
-  return lba_manager->incref_extent(t, ref->get_laddr()).si_then([](auto r) {
-    return r.refcount;
+  LOG_PREFIX(TransactionManager::inc_ref);
+  TRACET("{}", t, *ref);
+  return lba_manager->incref_extent(t, ref->get_laddr()
+  ).si_then([FNAME, ref, &t](auto result) {
+    DEBUGT("extent refcount is incremented to {} -- {}",
+           t, result.refcount, *ref);
+    return result.refcount;
   }).handle_error_interruptible(
     ref_iertr::pass_further{},
     ct_error::all_same_way([](auto e) {
@@ -170,7 +181,12 @@ TransactionManager::ref_ret TransactionManager::inc_ref(
   Transaction &t,
   laddr_t offset)
 {
-  return lba_manager->incref_extent(t, offset).si_then([](auto result) {
+  LOG_PREFIX(TransactionManager::inc_ref);
+  TRACET("{}", t, offset);
+  return lba_manager->incref_extent(t, offset
+  ).si_then([FNAME, offset, &t](auto result) {
+    DEBUGT("extent refcount is incremented to {} -- {}~{}, {}",
+           t, result.refcount, offset, result.length, result.addr);
     return result.refcount;
   });
 }
@@ -180,16 +196,15 @@ TransactionManager::ref_ret TransactionManager::dec_ref(
   LogicalCachedExtentRef &ref)
 {
   LOG_PREFIX(TransactionManager::dec_ref);
+  TRACET("{}", t, *ref);
   return lba_manager->decref_extent(t, ref->get_laddr()
-  ).si_then([this, FNAME, &t, ref](auto ret) {
-    if (ret.refcount == 0) {
-      DEBUGT(
-       "extent {} refcount 0",
-       t,
-       *ref);
+  ).si_then([this, FNAME, &t, ref](auto result) {
+    DEBUGT("extent refcount is decremented to {} -- {}",
+           t, result.refcount, *ref);
+    if (result.refcount == 0) {
       cache->retire_extent(t, ref);
     }
-    return ret.refcount;
+    return result.refcount;
   });
 }
 
@@ -198,10 +213,12 @@ TransactionManager::ref_ret TransactionManager::dec_ref(
   laddr_t offset)
 {
   LOG_PREFIX(TransactionManager::dec_ref);
+  TRACET("{}", t, offset);
   return lba_manager->decref_extent(t, offset
   ).si_then([this, FNAME, offset, &t](auto result) -> ref_ret {
+    DEBUGT("extent refcount is decremented to {} -- {}~{}, {}",
+           t, result.refcount, offset, result.length, result.addr);
     if (result.refcount == 0 && !result.addr.is_zero()) {
-      DEBUGT("offset {} refcount 0", t, offset);
       return cache->retire_extent_addr(
        t, result.addr, result.length
       ).si_then([] {
@@ -221,6 +238,8 @@ TransactionManager::refs_ret TransactionManager::dec_ref(
   Transaction &t,
   std::vector<laddr_t> offsets)
 {
+  LOG_PREFIX(TransactionManager::dec_ref);
+  DEBUG("{} offsets", offsets.size());
   return seastar::do_with(std::move(offsets), std::vector<unsigned>(),
       [this, &t] (auto &&offsets, auto &refcnt) {
       return trans_intr::do_for_each(offsets.begin(), offsets.end(),
@@ -322,6 +341,8 @@ TransactionManager::submit_transaction_direct(
 
 seastar::future<> TransactionManager::flush(OrderingHandle &handle)
 {
+  LOG_PREFIX(TransactionManager::flush);
+  SUBDEBUG(seastore_t, "H{} start", (void*)&handle);
   return handle.enter(write_pipeline.reserve_projected_usage
   ).then([this, &handle] {
     return handle.enter(write_pipeline.ool_writes);
@@ -330,6 +351,8 @@ seastar::future<> TransactionManager::flush(OrderingHandle &handle)
   }).then([this, &handle] {
     handle.maybe_release_collection_lock();
     return journal->flush(handle);
+  }).then([FNAME, &handle] {
+    SUBDEBUG(seastore_t, "H{} completed", (void*)&handle);
   });
 }
 
@@ -339,6 +362,8 @@ TransactionManager::get_next_dirty_extents(
   journal_seq_t seq,
   size_t max_bytes)
 {
+  LOG_PREFIX(TransactionManager::get_next_dirty_extents);
+  DEBUGT("max_bytes={}B, seq={}", t, max_bytes, seq);
   return cache->get_next_dirty_extents(t, seq, max_bytes);
 }
 
@@ -349,10 +374,10 @@ TransactionManager::rewrite_logical_extent(
 {
   LOG_PREFIX(TransactionManager::rewrite_logical_extent);
   if (extent->has_been_invalidated()) {
-    ERRORT("{} has been invalidated", t, *extent);
+    ERRORT("extent has been invalidated -- {}", t, *extent);
     ceph_abort();
   }
-  DEBUGT("rewriting {}", t, *extent);
+  TRACET("rewriting extent -- {}", t, *extent);
 
   auto lextent = extent->cast<LogicalCachedExtent>();
   cache->retire_extent(t, extent);
@@ -368,11 +393,7 @@ TransactionManager::rewrite_logical_extent(
   nlextent->set_laddr(lextent->get_laddr());
   nlextent->set_pin(lextent->get_pin().duplicate());
 
-  DEBUGT(
-    "rewriting {} into {}",
-    t,
-    *lextent,
-    *nlextent);
+  DEBUGT("rewriting extent -- {} to {}", t, *lextent, *nlextent);
 
   /* 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
@@ -393,14 +414,14 @@ TransactionManager::rewrite_extent_ret TransactionManager::rewrite_extent(
   {
     auto updated = cache->update_extent_from_transaction(t, extent);
     if (!updated) {
-      DEBUGT("{} is already retired, skipping", t, *extent);
+      DEBUGT("extent is already retired, skipping -- {}", t, *extent);
       return rewrite_extent_iertr::now();
     }
     extent = updated;
   }
 
   if (extent->get_type() == extent_types_t::ROOT) {
-    DEBUGT("marking root {} for rewrite", t, *extent);
+    DEBUGT("marking root for rewrite -- {}", t, *extent);
     cache->duplicate_for_write(t, extent);
     return rewrite_extent_iertr::now();
   }
@@ -408,6 +429,7 @@ TransactionManager::rewrite_extent_ret TransactionManager::rewrite_extent(
   if (extent->is_logical()) {
     return rewrite_logical_extent(t, extent->cast<LogicalCachedExtent>());
   } else {
+    DEBUGT("rewriting physical extent -- {}", t, *extent);
     return lba_manager->rewrite_extent(t, extent);
   }
 }
@@ -420,12 +442,14 @@ TransactionManager::get_extent_if_live_ret TransactionManager::get_extent_if_liv
   seastore_off_t len)
 {
   LOG_PREFIX(TransactionManager::get_extent_if_live);
-  DEBUGT("type {}, addr {}, laddr {}, len {}", t, type, addr, laddr, len);
+  TRACET("{} {}~{} {}", t, type, laddr, len, addr);
 
   return cache->get_extent_if_cached(t, addr, type
   ).si_then([this, FNAME, &t, type, addr, laddr, len](auto extent)
            -> get_extent_if_live_ret {
     if (extent) {
+      DEBUGT("{} {}~{} {} is live in cache -- {}",
+             t, type, laddr, len, addr, *extent);
       return get_extent_if_live_ret (
        interruptible::ready_future_marker{},
        extent);
@@ -440,14 +464,16 @@ TransactionManager::get_extent_if_live_ret TransactionManager::get_extent_if_liv
          if (pin->get_paddr() == addr) {
            if (pin->get_length() != (extent_len_t)len) {
              ERRORT(
-               "Invalid pin laddr {} paddr {} len {} found for "
-               "extent laddr {} len{}",
+               "Invalid pin {}~{} {} found for "
+               "extent {} {}~{} {}",
                t,
                pin->get_laddr(),
-               pin->get_paddr(),
                pin->get_length(),
+               pin->get_paddr(),
+               type,
                laddr,
-               len);
+               len,
+               addr);
              ceph_abort();
            }
            return cache->get_extent_by_type(
@@ -463,8 +489,14 @@ TransactionManager::get_extent_if_live_ret TransactionManager::get_extent_if_liv
                assert(!pin->has_been_invalidated());
                lref->set_pin(std::move(pin));
                lba_manager->add_pin(lref->get_pin());
+             }).si_then([=, &t](auto ret) {;
+               DEBUGT("{} {}~{} {} is live as logical extent -- {}",
+                      t, type, laddr, len, addr, extent);
+               return ret;
              });
          } else {
+           DEBUGT("{} {}~{} {} is not live as logical extent",
+                  t, type, laddr, len, addr);
            return inner_ret(
              interruptible::ready_future_marker{},
              CachedExtentRef());
@@ -473,13 +505,22 @@ TransactionManager::get_extent_if_live_ret TransactionManager::get_extent_if_liv
          return CachedExtentRef();
        }), crimson::ct_error::pass_further_all{});
     } else {
-      DEBUGT("non-logical extent {}", t, addr);
       return lba_manager->get_physical_extent_if_live(
        t,
        type,
        addr,
        laddr,
-       len);
+       len
+      ).si_then([=, &t](auto ret) {
+        if (ret) {
+          DEBUGT("{} {}~{} {} is live as physical extent -- {}",
+                 t, type, laddr, len, addr, *ret);
+        } else {
+          DEBUGT("{} {}~{} {} is not live as physical extent",
+                 t, type, laddr, len, addr);
+        }
+        return ret;
+      });
     }
   });
 }

diff --git a/src/crimson/os/seastore/transaction_manager.h b/src/crimson/os/seastore/transaction_manager.h
index cc3683993130c164870c86fb357045b3c461e6b4..34f32e39217f0caf59e3ddb71af5ca0ed75a001e 100644 (file)
--- a/src/crimson/os/seastore/transaction_manager.h
+++ b/src/crimson/os/seastore/transaction_manager.h
@@ -34,24 +34,22 @@ class Journal;
 
 template <typename F>
 auto repeat_eagain(F &&f) {
-  LOG_PREFIX("repeat_eagain");
   return seastar::do_with(
     std::forward<F>(f),
-    [FNAME](auto &f) {
-      return crimson::repeat(
-       [FNAME, &f] {
-         return std::invoke(f
-         ).safe_then([] {
-           return seastar::stop_iteration::yes;
-         }).handle_error(
-           [FNAME](const crimson::ct_error::eagain &e) {
-             SUBDEBUG(seastore_tm, "hit eagain, restarting");
-             return seastar::stop_iteration::no;
-           },
-           crimson::ct_error::pass_further_all{}
-         );
-       });
+    [](auto &f)
+  {
+    return crimson::repeat([&f] {
+      return std::invoke(f
+      ).safe_then([] {
+        return seastar::stop_iteration::yes;
+      }).handle_error(
+        [](const crimson::ct_error::eagain &e) {
+          return seastar::stop_iteration::no;
+        },
+        crimson::ct_error::pass_further_all{}
+      );
     });
+  });
 }
 
 /**
@@ -115,6 +113,8 @@ public:
   get_pin_ret get_pin(
     Transaction &t,
     laddr_t offset) {
+    LOG_PREFIX(TransactionManager::get_pin);
+    SUBTRACET(seastore_tm, "{}", t, offset);
     return lba_manager->get_mapping(t, offset);
   }
 
@@ -129,6 +129,8 @@ public:
     Transaction &t,
     laddr_t offset,
     extent_len_t length) {
+    LOG_PREFIX(TransactionManager::get_pins);
+    SUBDEBUGT(seastore_tm, "{}~{}", t, offset, length);
     return lba_manager->get_mappings(
       t, offset, length);
   }
@@ -148,8 +150,8 @@ public:
     Transaction &t,
     LBAPinRef pin) {
     LOG_PREFIX(TransactionManager::pin_to_extent);
+    SUBTRACET(seastore_tm, "getting extent {}", t, *pin);
     using ret = pin_to_extent_ret<T>;
-    SUBDEBUGT(seastore_tm, "getting extent {}", t, *pin);
     auto &pref = *pin;
     return cache->get_extent<T>(
       t,
@@ -163,7 +165,7 @@ public:
        lba_manager->add_pin(extent.get_pin());
       }
     ).si_then([FNAME, &t](auto ref) mutable -> ret {
-      SUBDEBUGT(seastore_tm, "got extent {}", t, *ref);
+      SUBTRACET(seastore_tm, "got extent -- {}", t, *ref);
       return pin_to_extent_ret<T>(
        interruptible::ready_future_marker{},
        std::move(ref));
@@ -186,6 +188,7 @@ public:
     laddr_t offset,
     extent_len_t length) {
     LOG_PREFIX(TransactionManager::read_extent);
+    SUBTRACET(seastore_tm, "{}~{}", t, offset, length);
     return get_pin(
       t, offset
     ).si_then([this, FNAME, &t, offset, length] (auto pin) {
@@ -209,6 +212,7 @@ public:
     Transaction &t,
     laddr_t offset) {
     LOG_PREFIX(TransactionManager::read_extent);
+    SUBTRACET(seastore_tm, "{}", t, offset);
     return get_pin(
       t, offset
     ).si_then([this, FNAME, &t, offset] (auto pin) {
@@ -230,14 +234,14 @@ public:
       ref)->cast<LogicalCachedExtent>();
     if (!ret->has_pin()) {
       SUBDEBUGT(seastore_tm,
-       "duplicating {} for write: {}",
+       "duplicating extent for write -- {} -> {}",
        t,
        *ref,
        *ret);
       ret->set_pin(ref->get_pin().duplicate());
     } else {
-      SUBDEBUGT(seastore_tm,
-       "{} already pending",
+      SUBTRACET(seastore_tm,
+       "extent is already duplicated -- {}",
        t,
        *ref);
       assert(ref->is_pending());
@@ -297,6 +301,9 @@ public:
     } else {
       placement_hint = placement_hint_t::HOT;
     }
+    LOG_PREFIX(TransactionManager::alloc_extent);
+    SUBTRACET(seastore_tm, "{} len={}, placement_hint={}, laddr_hint={}",
+              t, T::TYPE, len, placement_hint, laddr_hint);
     auto ext = epm->alloc_new_extent<T>(
       t,
       len,
@@ -306,8 +313,7 @@ public:
       laddr_hint,
       len,
       ext->get_paddr()
-    ).si_then([ext=std::move(ext), laddr_hint, &t](auto &&ref) mutable {
-      LOG_PREFIX(TransactionManager::alloc_extent);
+    ).si_then([ext=std::move(ext), laddr_hint, &t, FNAME](auto &&ref) mutable {
       ext->set_pin(std::move(ref));
       SUBDEBUGT(seastore_tm, "new extent: {}, laddr_hint: {}", t, *ext, laddr_hint);
       return alloc_extent_iertr::make_ready_future<TCachedExtentRef<T>>(
@@ -321,6 +327,8 @@ public:
     Transaction &t,
     laddr_t hint,
     extent_len_t len) {
+    LOG_PREFIX(TransactionManager::reserve_region);
+    SUBDEBUGT(seastore_tm, "len={}, laddr_hint={}", t, len, hint);
     return lba_manager->alloc_extent(
       t,
       hint,
@@ -340,6 +348,9 @@ public:
      laddr_t hint,
      extent_len_t len,
      int num) {
+     LOG_PREFIX(TransactionManager::alloc_extents);
+     SUBDEBUGT(seastore_tm, "len={}, laddr_hint={}, num={}",
+               t, len, hint, num);
      return seastar::do_with(std::vector<TCachedExtentRef<T>>(),
        [this, &t, hint, len, num] (auto &extents) {
        return trans_intr::do_for_each(
@@ -402,6 +413,8 @@ public:
     SegmentCleaner::ExtentCallbackInterface::release_segment_ret;
   release_segment_ret release_segment(
     segment_id_t id) final {
+    LOG_PREFIX(TransactionManager::release_segment);
+    SUBDEBUG(seastore_tm, "{}", id);
     return segment_manager.release(id);
   }
 
@@ -419,12 +432,15 @@ public:
     const std::string &key) {
     return cache->get_root(
       t
-    ).si_then([&key](auto root) {
+    ).si_then([&key, &t](auto root) {
+      LOG_PREFIX(TransactionManager::read_root_meta);
       auto meta = root->root.get_meta();
       auto iter = meta.find(key);
       if (iter == meta.end()) {
+        SUBDEBUGT(seastore_tm, "{} -> nullopt", t, key);
        return seastar::make_ready_future<read_root_meta_bare>(std::nullopt);
       } else {
+        SUBDEBUGT(seastore_tm, "{} -> {}", t, key, iter->second);
        return seastar::make_ready_future<read_root_meta_bare>(iter->second);
       }
     });
@@ -441,6 +457,8 @@ public:
     Transaction& t,
     const std::string& key,
     const std::string& value) {
+    LOG_PREFIX(TransactionManager::update_root_meta);
+    SUBDEBUGT(seastore_tm, "seastore_tm, {} -> {}", t, key, value);
     return cache->get_root(
       t
     ).si_then([this, &t, &key, &value](RootBlockRef root) {
@@ -462,8 +480,10 @@ public:
   using read_onode_root_iertr = base_iertr;
   using read_onode_root_ret = read_onode_root_iertr::future<laddr_t>;
   read_onode_root_ret read_onode_root(Transaction &t) {
-    return cache->get_root(t).si_then([](auto croot) {
+    return cache->get_root(t).si_then([&t](auto croot) {
+      LOG_PREFIX(TransactionManager::read_onode_root);
       laddr_t ret = croot->get_root().onode_root;
+      SUBTRACET(seastore_tm, "{}", t, ret);
       return ret;
     });
   }
@@ -474,6 +494,8 @@ public:
    * Write onode-tree root logical address, must be called after read.
    */
   void write_onode_root(Transaction &t, laddr_t addr) {
+    LOG_PREFIX(TransactionManager::write_onode_root);
+    SUBDEBUGT(seastore_tm, "{}", t, addr);
     auto croot = cache->get_root_fast(t);
     croot = cache->duplicate_for_write(t, croot)->cast<RootBlock>();
     croot->get_root().onode_root = addr;
@@ -488,8 +510,12 @@ public:
   using read_collection_root_ret = read_collection_root_iertr::future<
     coll_root_t>;
   read_collection_root_ret read_collection_root(Transaction &t) {
-    return cache->get_root(t).si_then([](auto croot) {
-      return croot->get_root().collection_root.get();
+    return cache->get_root(t).si_then([&t](auto croot) {
+      LOG_PREFIX(TransactionManager::read_collection_root);
+      auto ret = croot->get_root().collection_root.get();
+      SUBTRACET(seastore_tm, "{}~{}",
+                t, ret.get_location(), ret.get_size());
+      return ret;
     });
   }
 
@@ -499,6 +525,9 @@ public:
    * Update collection root addr
    */
   void write_collection_root(Transaction &t, coll_root_t cmroot) {
+    LOG_PREFIX(TransactionManager::write_collection_root);
+    SUBDEBUGT(seastore_tm, "{}~{}",
+              t, cmroot.get_location(), cmroot.get_size());
     auto croot = cache->get_root_fast(t);
     croot = cache->duplicate_for_write(t, croot)->cast<RootBlock>();
     croot->get_root().collection_root.update(cmroot);