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

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

3 files changed, 159 insertions, 78 deletions

diff --git a/src/crimson/os/seastore/cache.cc b/src/crimson/os/seastore/cache.cc
index 5bb04886464..39ac510b96b 100644
--- a/src/crimson/os/seastore/cache.cc
+++ b/src/crimson/os/seastore/cache.cc
@@ -30,6 +30,8 @@ Cache::Cache(
     lru(crimson::common::get_conf<Option::size_t>(
 	  "seastore_cache_lru_size"))
 {
+  LOG_PREFIX(Cache::Cache);
+  INFO("created, lru_size={}", lru.get_capacity());
   register_metrics();
 }
 
@@ -37,7 +39,7 @@ Cache::~Cache()
 {
   LOG_PREFIX(Cache::~Cache);
   for (auto &i: extents) {
-    ERROR("extent {} still alive", i);
+    ERROR("extent is still alive -- {}", i);
   }
   ceph_assert(extents.empty());
 }
@@ -45,17 +47,19 @@ Cache::~Cache()
 Cache::retire_extent_ret Cache::retire_extent_addr(
   Transaction &t, paddr_t addr, extent_len_t length)
 {
+  LOG_PREFIX(Cache::retire_extent_addr);
+  TRACET("retire {}~{}", t, addr, length);
+
   assert(addr.is_real() && !addr.is_block_relative());
 
-  LOG_PREFIX(Cache::retire_extent);
   CachedExtentRef ext;
   auto result = t.get_extent(addr, &ext);
   if (result == Transaction::get_extent_ret::PRESENT) {
-    DEBUGT("found {} in t", t, addr);
+    DEBUGT("retire {}~{} on t -- {}", t, addr, length, *ext);
     t.add_to_retired_set(CachedExtentRef(&*ext));
     return retire_extent_iertr::now();
   } else if (result == Transaction::get_extent_ret::RETIRED) {
-    ERRORT("{} is already retired", t, addr);
+    ERRORT("retire {}~{} failed, already retired -- {}", t, addr, length, *ext);
     ceph_abort();
   }
 
@@ -66,6 +70,7 @@ Cache::retire_extent_ret Cache::retire_extent_addr(
   // retiring is not included by the cache hit metrics
   ext = query_cache(addr, nullptr);
   if (ext) {
+    DEBUGT("retire {}~{} in cache -- {}", t, addr, length, *ext);
     if (ext->get_type() != extent_types_t::RETIRED_PLACEHOLDER) {
       t.add_to_read_set(ext);
       return trans_intr::make_interruptible(
@@ -77,6 +82,7 @@ Cache::retire_extent_ret Cache::retire_extent_addr(
     }
     // the retired-placeholder exists
   } else {
+    DEBUGT("retire {}~{} as placeholder", t, addr, length);
     // add a new placeholder to Cache
     ext = CachedExtent::make_cached_extent_ref<
       RetiredExtentPlaceholder>(length);
@@ -103,6 +109,9 @@ void Cache::dump_contents()
 
 void Cache::register_metrics()
 {
+  LOG_PREFIX(Cache::register_metrics);
+  DEBUG("");
+
   stats = {};
 
   namespace sm = seastar::metrics;
@@ -614,6 +623,7 @@ void Cache::register_metrics()
 void Cache::add_extent(CachedExtentRef ref)
 {
   LOG_PREFIX(Cache::add_extent);
+  TRACE("extent -- {}", *ref);
   assert(ref->is_valid());
   extents.insert(*ref);
   if (ref->is_dirty()) {
@@ -621,12 +631,10 @@ void Cache::add_extent(CachedExtentRef ref)
   } else {
     touch_extent(*ref);
   }
-  DEBUG("extent {}", *ref);
 }
 
 void Cache::mark_dirty(CachedExtentRef ref)
 {
-  LOG_PREFIX(Cache::mark_dirty);
   if (ref->is_dirty()) {
     assert(ref->primary_ref_list_hook.is_linked());
     return;
@@ -635,8 +643,6 @@ void Cache::mark_dirty(CachedExtentRef ref)
   lru.remove_from_lru(*ref);
   add_to_dirty(ref);
   ref->state = CachedExtent::extent_state_t::DIRTY;
-
-  DEBUG("extent: {}", *ref);
 }
 
 void Cache::add_to_dirty(CachedExtentRef ref)
@@ -663,7 +669,7 @@ void Cache::remove_from_dirty(CachedExtentRef ref)
 void Cache::remove_extent(CachedExtentRef ref)
 {
   LOG_PREFIX(Cache::remove_extent);
-  DEBUG("extent {}", *ref);
+  TRACE("extent -- {}", *ref);
   assert(ref->is_valid());
   if (ref->is_dirty()) {
     remove_from_dirty(ref);
@@ -677,8 +683,6 @@ void Cache::commit_retire_extent(
     Transaction& t,
     CachedExtentRef ref)
 {
-  LOG_PREFIX(Cache::commit_retire_extent);
-  DEBUGT("extent {}", t, *ref);
   remove_extent(ref);
 
   ref->dirty_from_or_retired_at = JOURNAL_SEQ_MAX;
@@ -690,8 +694,6 @@ void Cache::commit_replace_extent(
     CachedExtentRef next,
     CachedExtentRef prev)
 {
-  LOG_PREFIX(Cache::commit_replace_extent);
-  DEBUGT("prev {}, next {}", t, *prev, *next);
   assert(next->get_paddr() == prev->get_paddr());
   assert(next->version == prev->version + 1);
   extents.replace(*next, *prev);
@@ -777,7 +779,6 @@ void Cache::mark_transaction_conflicted(
       if (!i->is_valid()) {
         continue;
       }
-      DEBUGT("was mutating extent: {}", t, *i);
       efforts.mutate.increment(i->get_length());
       delta_stat.increment(i->get_delta().length());
     }
@@ -857,6 +858,9 @@ CachedExtentRef Cache::alloc_new_extent_by_type(
   bool delay 		///< [in] whether to delay paddr alloc
 )
 {
+  LOG_PREFIX(Cache::alloc_new_extent_by_type);
+  SUBDEBUGT(seastore_cache, "allocate {} {}B, delay={}",
+            t, type, length, delay);
   switch (type) {
   case extent_types_t::ROOT:
     ceph_assert(0 == "ROOT is never directly alloc'd");
@@ -1008,7 +1012,7 @@ record_t Cache::prepare_record(Transaction &t)
   // invalidate now invalid blocks
   io_stat_t retire_stat;
   for (auto &i: t.retired_set) {
-    DEBUGT("retiring {}", t, *i);
+    DEBUGT("retired extent -- {}", t, *i);
     get_by_ext(efforts.retire_by_ext,
                i->get_type()).increment(i->get_length());
     retire_stat.increment(i->get_length());
@@ -1027,12 +1031,12 @@ record_t Cache::prepare_record(Transaction &t)
   io_stat_t fresh_invalid_stat;
   for (auto &i: t.inline_block_list) {
     if (!i->is_valid()) {
-      DEBUGT("fresh inline block (invalid) {}", t, *i);
+      DEBUGT("invalid fresh inline extent -- {}", t, *i);
       fresh_invalid_stat.increment(i->get_length());
       get_by_ext(efforts.fresh_invalid_by_ext,
                  i->get_type()).increment(i->get_length());
     } else {
-      DEBUGT("fresh inline block {}", t, *i);
+      DEBUGT("fresh inline extent -- {}", t, *i);
     }
     fresh_stat.increment(i->get_length());
     get_by_ext(efforts.fresh_inline_by_ext,
@@ -1069,7 +1073,7 @@ record_t Cache::prepare_record(Transaction &t)
 
   for (auto &i: t.ool_block_list) {
     ceph_assert(i->is_valid());
-    DEBUGT("fresh ool block {}", t, *i);
+    DEBUGT("fresh ool extent -- {}", t, *i);
     get_by_ext(efforts.fresh_ool_by_ext,
                i->get_type()).increment(i->get_length());
   }
@@ -1155,7 +1159,6 @@ void Cache::complete_commit(
 
     if (i->is_valid()) {
       i->state = CachedExtent::extent_state_t::CLEAN;
-      DEBUGT("fresh {}", t, *i);
       add_extent(i);
       if (cleaner) {
 	cleaner->mark_space_used(
@@ -1170,7 +1173,6 @@ void Cache::complete_commit(
     if (!i->is_valid()) {
       continue;
     }
-    DEBUGT("mutated {}", t, *i);
     assert(i->prior_instance);
     i->on_delta_write(final_block_start);
     i->prior_instance = CachedExtentRef();
@@ -1197,12 +1199,14 @@ void Cache::complete_commit(
 
   last_commit = seq;
   for (auto &i: t.retired_set) {
-    DEBUGT("retiring {}", t, *i);
     i->dirty_from_or_retired_at = last_commit;
   }
 }
 
-void Cache::init() {
+void Cache::init()
+{
+  LOG_PREFIX(Cache::init);
+  INFO("init root");
   if (root) {
     // initial creation will do mkfs followed by mount each of which calls init
     remove_extent(root);
@@ -1215,6 +1219,8 @@ void Cache::init() {
 
 Cache::mkfs_iertr::future<> Cache::mkfs(Transaction &t)
 {
+  LOG_PREFIX(Cache::mkfs);
+  INFOT("create root", t);
   return get_root(t).si_then([this, &t](auto croot) {
     duplicate_for_write(t, croot);
     return mkfs_iertr::now();
@@ -1228,6 +1234,15 @@ Cache::mkfs_iertr::future<> Cache::mkfs(Transaction &t)
 
 Cache::close_ertr::future<> Cache::close()
 {
+  LOG_PREFIX(Cache::close);
+  INFO("close with {}({}B) dirty from {}, {}({}B) lru, totally {}({}B) indexed extents",
+       dirty.size(),
+       stats.dirty_bytes,
+       get_oldest_dirty_from().value_or(journal_seq_t{}),
+       lru.get_current_contents_extents(),
+       lru.get_current_contents_bytes(),
+       extents.size(),
+       extents.get_bytes());
   root.reset();
   for (auto i = dirty.begin(); i != dirty.end(); ) {
     auto ptr = &*i;
@@ -1248,7 +1263,7 @@ Cache::replay_delta(
 {
   LOG_PREFIX(Cache::replay_delta);
   if (delta.type == extent_types_t::ROOT) {
-    DEBUG("found root delta");
+    DEBUG("replay root delta {} at {} {}", delta, journal_seq, record_base);
     remove_extent(root);
     root->apply_delta_and_adjust_crc(record_base, delta.bl);
     root->dirty_from_or_retired_at = journal_seq;
@@ -1290,14 +1305,14 @@ Cache::replay_delta(
     );
     return extent_fut.safe_then([=, &delta](auto extent) {
       if (!extent) {
+	DEBUG("replay extent is not present, so delta is obsolete {} at {} {}",
+	      delta, journal_seq, record_base);
 	assert(delta.pversion > 0);
-	DEBUG(
-	  "replaying {}, extent not present so delta is obsolete",
-	  delta);
 	return;
       }
 
-      DEBUG("replaying {} on {}", *extent, delta);
+      DEBUG("replay extent delta {} at {} {} -- {} ...",
+            delta, journal_seq, record_base, *extent);
 
       assert(extent->version == delta.pversion);
 
@@ -1320,6 +1335,13 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents(
   size_t max_bytes)
 {
   LOG_PREFIX(Cache::get_next_dirty_extents);
+  if (dirty.empty()) {
+    DEBUGT("max_bytes={}B, seq={}, dirty is empty",
+           t, max_bytes, seq);
+  } else {
+    DEBUGT("max_bytes={}B, seq={}, dirty_from={}",
+           t, max_bytes, seq, dirty.begin()->get_dirty_from());
+  }
   std::vector<CachedExtentRef> cand;
   size_t bytes_so_far = 0;
   for (auto i = dirty.begin();
@@ -1330,9 +1352,10 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents(
                 dirty_from != JOURNAL_SEQ_MAX &&
                 dirty_from != NO_DELTAS);
     if (dirty_from < seq) {
-      DEBUGT("next {}", t, *i);
+      TRACET("next extent -- {}", t, *i);
       if (!cand.empty() && cand.back()->get_dirty_from() > dirty_from) {
-	ERRORT("last {}, next {}", t, *cand.back(), *i);
+	ERRORT("dirty extents are not ordered by dirty_from -- last={}, next={}",
+               t, *cand.back(), *i);
         ceph_abort();
       }
       bytes_so_far += i->get_length();
@@ -1348,8 +1371,7 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents(
       return trans_intr::do_for_each(
 	cand,
 	[FNAME, this, &t, &ret](auto &ext) {
-	  DEBUG("waiting on {}", *ext);
-
+	  TRACET("waiting on extent -- {}", t, *ext);
 	  return trans_intr::make_interruptible(
 	    ext->wait_io()
 	  ).then_interruptible([FNAME, this, ext, &t, &ret] {
@@ -1362,7 +1384,7 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents(
 	    CachedExtentRef on_transaction;
 	    auto result = t.get_extent(ext->get_paddr(), &on_transaction);
 	    if (result == Transaction::get_extent_ret::ABSENT) {
-	      DEBUGT("{} absent on t", t, *ext);
+	      DEBUGT("extent is absent on t -- {}", t, *ext);
 	      t.add_to_read_set(ext);
 	      if (ext->get_type() == extent_types_t::ROOT) {
 		if (t.root) {
@@ -1375,11 +1397,11 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents(
 	      }
 	      ret.push_back(ext);
 	    } else if (result == Transaction::get_extent_ret::PRESENT) {
-	      DEBUGT("{} present on t as {}", t, *ext, *on_transaction);
+	      DEBUGT("extent is present on t -- {}, on t {}", t, *ext, *on_transaction);
 	      ret.push_back(on_transaction);
 	    } else {
 	      assert(result == Transaction::get_extent_ret::RETIRED);
-	      DEBUGT("{} retired on t", t, *ext);
+	      DEBUGT("extent is retired on t -- {}", t, *ext);
 	    }
 	  });
 	}).then_interruptible([&ret] {
@@ -1392,16 +1414,16 @@ Cache::get_root_ret Cache::get_root(Transaction &t)
 {
   LOG_PREFIX(Cache::get_root);
   if (t.root) {
-    DEBUGT("root already on transaction {}", t, *t.root);
+    TRACET("root already on t -- {}", t, *t.root);
     return get_root_iertr::make_ready_future<RootBlockRef>(
       t.root);
   } else {
     auto ret = root;
-    DEBUGT("waiting root {}", t, *ret);
+    DEBUGT("root not on t -- {}", t, *ret);
     return ret->wait_io().then([this, FNAME, ret, &t] {
-      DEBUGT("got root read {}", t, *ret);
+      TRACET("root wait io done -- {}", t, *ret);
       if (!ret->is_valid()) {
-	DEBUGT("root became invalid: {}", t, *ret);
+	DEBUGT("root is invalid -- {}", t, *ret);
 	++(get_by_src(stats.trans_conflicts_by_unknown, t.get_src()));
 	mark_transaction_conflicted(t, *ret);
 	return get_root_iertr::make_ready_future<RootBlockRef>();
diff --git a/src/crimson/os/seastore/cache.h b/src/crimson/os/seastore/cache.h
index 0060dd8ad5e..a63162a45a0 100644
--- a/src/crimson/os/seastore/cache.h
+++ b/src/crimson/os/seastore/cache.h
@@ -88,6 +88,9 @@ namespace crimson::os::seastore {
  * Cache logs
  *
  * levels:
+ * - INFO: major initiation, closing operations
+ * - DEBUG: major extent related operations, INFO details
+ * - TRACE: DEBUG details
  * - seastore_t logs
  */
 class Cache {
@@ -134,6 +137,8 @@ public:
 
   /// Declare ref retired in t
   void retire_extent(Transaction &t, CachedExtentRef ref) {
+    LOG_PREFIX(Cache::retire_extent);
+    SUBDEBUGT(seastore_cache, "retire extent -- {}", t, *ref);
     t.add_to_retired_set(ref);
   }
 
@@ -158,6 +163,8 @@ public:
    * returns t.root and assume it is already present/read in t
    */
   RootBlockRef get_root_fast(Transaction &t) {
+    LOG_PREFIX(Cache::get_root_fast);
+    SUBTRACET(seastore_cache, "root already on t -- {}", t, *t.root);
     assert(t.root);
     return t.root;
   }
@@ -180,8 +187,11 @@ public:
     const src_ext_t* p_metric_key, ///< [in] cache query metric key
     Func &&extent_init_func        ///< [in] init func for extent
   ) {
+    LOG_PREFIX(Cache::get_extent);
     auto cached = query_cache(offset, p_metric_key);
     if (!cached) {
+      SUBDEBUG(seastore_cache,
+          "{} {}~{} is absent, reading ...", T::TYPE, offset, length);
       auto ret = CachedExtent::make_cached_extent_ref<T>(
         alloc_cache_buf(length));
       ret->set_paddr(offset);
@@ -194,6 +204,9 @@ public:
 
     // extent PRESENT in cache
     if (cached->get_type() == extent_types_t::RETIRED_PLACEHOLDER) {
+      SUBDEBUG(seastore_cache,
+          "{} {}~{} is absent(placeholder), reading ...",
+          T::TYPE, offset, length);
       auto ret = CachedExtent::make_cached_extent_ref<T>(
         alloc_cache_buf(length));
       ret->set_paddr(offset);
@@ -211,6 +224,9 @@ public:
       return read_extent<T>(
 	std::move(ret));
     } else {
+      SUBTRACE(seastore_cache,
+          "{} {}~{} is present in cache -- {}",
+          T::TYPE, offset, length, *cached);
       auto ret = TCachedExtentRef<T>(static_cast<T*>(cached.get()));
       return ret->wait_io(
       ).then([ret=std::move(ret)]() mutable
@@ -248,11 +264,14 @@ public:
     CachedExtentRef ret;
     LOG_PREFIX(Cache::get_extent_if_cached);
     auto result = t.get_extent(offset, &ret);
-    if (result != Transaction::get_extent_ret::ABSENT) {
-      // including get_extent_ret::RETIRED
-      SUBDEBUGT(seastore_cache,
-	"Found extent at offset {} on transaction: {}",
-	t, offset, *ret);
+    if (result == Transaction::get_extent_ret::RETIRED) {
+      SUBDEBUGT(seastore_cache, "{} {} is retired on t -- {}",
+          t, type, offset, *ret);
+      return get_extent_if_cached_iertr::make_ready_future<
+        CachedExtentRef>(ret);
+    } else if (result == Transaction::get_extent_ret::PRESENT) {
+      SUBTRACET(seastore_cache, "{} {} is present on t -- {}",
+          t, type, offset, *ret);
       return get_extent_if_cached_iertr::make_ready_future<
         CachedExtentRef>(ret);
     }
@@ -263,17 +282,15 @@ public:
     if (!ret ||
         // retired_placeholder is not really cached yet
         ret->get_type() == extent_types_t::RETIRED_PLACEHOLDER) {
-      SUBDEBUGT(seastore_cache,
-	"No extent at offset {}, retired_placeholder: {}",
-	t, offset, !!ret);
+      SUBDEBUGT(seastore_cache, "{} {} is absent{}",
+                t, type, offset, !!ret ? "(placeholder)" : "");
       return get_extent_if_cached_iertr::make_ready_future<
         CachedExtentRef>();
     }
 
     // present in cache and is not a retired_placeholder
-    SUBDEBUGT(seastore_cache,
-      "Found extent at offset {} in cache: {}",
-      t, offset, *ret);
+    SUBDEBUGT(seastore_cache, "{} {} is present in cache -- {}",
+              t, type, offset, *ret);
     t.add_to_read_set(ret);
     touch_extent(*ret);
     return ret->wait_io().then([ret] {
@@ -303,29 +320,33 @@ public:
     LOG_PREFIX(Cache::get_extent);
     auto result = t.get_extent(offset, &ret);
     if (result != Transaction::get_extent_ret::ABSENT) {
+      SUBTRACET(seastore_cache, "{} {}~{} is {} on t -- {}",
+          t,
+          T::TYPE,
+          offset,
+          length,
+          result == Transaction::get_extent_ret::PRESENT ? "present" : "retired",
+          *ret);
       assert(result != Transaction::get_extent_ret::RETIRED);
-      SUBDEBUGT(seastore_cache,
-	"Found extent at offset {} on transaction: {}",
-	t, offset, *ret);
       return seastar::make_ready_future<TCachedExtentRef<T>>(
 	ret->cast<T>());
     } else {
+      SUBTRACET(seastore_cache, "{} {}~{} is absent on t, query cache ...",
+                t, T::TYPE, offset, length);
       auto metric_key = std::make_pair(t.get_src(), T::TYPE);
       return trans_intr::make_interruptible(
 	get_extent<T>(
 	  offset, length, &metric_key,
 	  std::forward<Func>(extent_init_func))
-      ).si_then([this, FNAME, offset, &t](auto ref) {
+      ).si_then([this, FNAME, offset, length, &t](auto ref) {
 	(void)this; // silence incorrect clang warning about capture
 	if (!ref->is_valid()) {
-	  SUBDEBUGT(seastore_cache, "got invalid extent: {}", t, ref);
+	  SUBDEBUGT(seastore_cache, "{} {}~{} is invalid -- {}",
+	            t, T::TYPE, offset, length, *ref);
 	  ++(get_by_src(stats.trans_conflicts_by_unknown, t.get_src()));
 	  mark_transaction_conflicted(t, *ref);
 	  return get_extent_iertr::make_ready_future<TCachedExtentRef<T>>();
 	} else {
-	  SUBDEBUGT(seastore_cache,
-	    "Read extent at offset {} in cache: {}",
-	    t, offset, *ref);
 	  touch_extent(*ref);
 	  t.add_to_read_set(ref);
 	  return get_extent_iertr::make_ready_future<TCachedExtentRef<T>>(
@@ -387,14 +408,22 @@ private:
     paddr_t offset,
     laddr_t laddr,
     seastore_off_t length,
-    extent_init_func_t &&extent_init_func) {
+    extent_init_func_t &&extent_init_func
+  ) {
+    LOG_PREFIX(Cache::get_extent_by_type);
     CachedExtentRef ret;
     auto status = t.get_extent(offset, &ret);
     if (status == Transaction::get_extent_ret::RETIRED) {
+      SUBDEBUGT(seastore_cache, "{} {}~{} {} is retired on t -- {}",
+                t, type, offset, length, laddr, *ret);
       return seastar::make_ready_future<CachedExtentRef>();
     } else if (status == Transaction::get_extent_ret::PRESENT) {
+      SUBTRACET(seastore_cache, "{} {}~{} {} is present on t -- {}",
+                t, type, offset, length, laddr, *ret);
       return seastar::make_ready_future<CachedExtentRef>(ret);
     } else {
+      SUBTRACET(seastore_cache, "{} {}~{} {} is absent on t, query cache ...",
+                t, type, offset, length, laddr);
       auto src = t.get_src();
       return trans_intr::make_interruptible(
 	_get_extent_by_type(
@@ -402,8 +431,8 @@ private:
 	  std::move(extent_init_func))
       ).si_then([=, &t](CachedExtentRef ret) {
         if (!ret->is_valid()) {
-          LOG_PREFIX(Cache::get_extent_by_type);
-          SUBDEBUGT(seastore_cache, "got invalid extent: {}", t, ret);
+          SUBDEBUGT(seastore_cache, "{} {}~{} {} is invalid -- {}",
+                    t, type, offset, length, laddr, *ret);
           ++(get_by_src(stats.trans_conflicts_by_unknown, t.get_src()));
           mark_transaction_conflicted(t, *ret.get());
           return get_extent_ertr::make_ready_future<CachedExtentRef>();
@@ -464,6 +493,9 @@ public:
     seastore_off_t length, ///< [in] length
     bool delayed = false  ///< [in] whether the paddr allocation of extent is delayed
   ) {
+    LOG_PREFIX(Cache::alloc_new_extent);
+    SUBDEBUGT(seastore_cache, "allocate {} {}B, delay={}",
+              t, T::TYPE, length, delayed);
     auto ret = CachedExtent::make_cached_extent_ref<T>(
       alloc_cache_buf(length));
     t.add_fresh_extent(ret, delayed);
@@ -473,14 +505,21 @@ public:
 
   void mark_delayed_extent_inline(
     Transaction& t,
-    LogicalCachedExtentRef& ref) {
+    LogicalCachedExtentRef& ref
+  ) {
+    LOG_PREFIX(Cache::mark_delayed_extent_inline);
+    SUBDEBUGT(seastore_cache, "-- {}", t, *ref);
     t.mark_delayed_extent_inline(ref);
   }
 
   void mark_delayed_extent_ool(
     Transaction& t,
     LogicalCachedExtentRef& ref,
-    paddr_t final_addr) {
+    paddr_t final_addr
+  ) {
+    LOG_PREFIX(Cache::mark_delayed_extent_ool);
+    SUBDEBUGT(seastore_cache, "final_addr={} -- {}",
+              t, final_addr, *ref);
     t.mark_delayed_extent_ool(ref, final_addr);
   }
 
@@ -588,6 +627,15 @@ public:
     Transaction &t,
     F &&f)
   {
+    LOG_PREFIX(Cache::init_cached_extents);
+    SUBINFOT(seastore_cache,
+        "start with {}({}B) extents, {} dirty, from {}",
+        t,
+        extents.size(),
+        extents.get_bytes(),
+        dirty.size(),
+        get_oldest_dirty_from().value_or(journal_seq_t{}));
+
     // journal replay should has been finished at this point,
     // Cache::root should have been inserted to the dirty list
     assert(root->is_dirty());
@@ -598,16 +646,20 @@ public:
     return seastar::do_with(
       std::forward<F>(f),
       std::move(_dirty),
-      [this, &t](auto &f, auto &refs) mutable
+      [this, FNAME, &t](auto &f, auto &refs) mutable
     {
       return trans_intr::do_for_each(
         refs,
-        [this, &t, &f](auto &e)
+        [this, FNAME, &t, &f](auto &e)
       {
+        SUBTRACET(seastore_cache, "inspecting extent ... -- {}", t, *e);
         return f(t, e
-        ).si_then([this, &t, e](bool is_alive) {
+        ).si_then([this, FNAME, &t, e](bool is_alive) {
           if (!is_alive) {
+            SUBDEBUGT(seastore_cache, "extent is not alive, remove -- {}", t, *e);
             remove_extent(e);
+          } else {
+            SUBDEBUGT(seastore_cache, "extent is alive -- {}", t, *e);
           }
         });
       });
@@ -616,7 +668,15 @@ public:
       crimson::ct_error::assert_all{
         "Invalid error in Cache::init_cached_extents"
       }
-    );
+    ).si_then([this, FNAME, &t] {
+      SUBINFOT(seastore_cache,
+          "finish with {}({}B) extents, {} dirty, from {}",
+          t,
+          extents.size(),
+          extents.get_bytes(),
+          dirty.size(),
+          get_oldest_dirty_from().value_or(journal_seq_t{}));
+    });
   }
 
   /**
@@ -742,6 +802,10 @@ private:
   public:
     LRU(size_t capacity) : capacity(capacity) {}
 
+    size_t get_capacity() const {
+      return capacity;
+    }
+
     size_t get_current_contents_bytes() const {
       return contents;
     }
@@ -974,12 +1038,14 @@ private:
       extent->get_bptr()
     ).safe_then(
       [extent=std::move(extent)]() mutable {
+        LOG_PREFIX(Cache::read_extent);
         extent->state = CachedExtent::extent_state_t::CLEAN;
         /* TODO: crc should be checked against LBA manager */
         extent->last_committed_crc = extent->get_crc32c();
 
         extent->on_clean_read();
         extent->complete_io();
+        SUBDEBUG(seastore_cache, "read extent done -- {}", *extent);
         return get_extent_ertr::make_ready_future<TCachedExtentRef<T>>(
           std::move(extent));
       },
diff --git a/src/crimson/os/seastore/transaction.h b/src/crimson/os/seastore/transaction.h
index 9fe502ab33a..8e4cb8d17f5 100644
--- a/src/crimson/os/seastore/transaction.h
+++ b/src/crimson/os/seastore/transaction.h
@@ -50,6 +50,7 @@ inline std::ostream& operator<<(std::ostream& out, const io_stat_t& stat) {
  * seastore_t
  * - DEBUG: transaction create, conflict, commit events
  * - TRACE: DEBUG details
+ * - seastore_cache logs
  */
 class Transaction {
 public:
@@ -68,7 +69,8 @@ public:
 	iter != write_set.end()) {
       if (out)
 	*out = CachedExtentRef(&*iter);
-      SUBTRACET(seastore_tm, "Found offset {} in write_set: {}", *this, addr, *iter);
+      SUBTRACET(seastore_cache, "{} is present in write_set -- {}",
+                *this, addr, *iter);
       return get_extent_ret::PRESENT;
     } else if (
       auto iter = read_set.find(addr);
@@ -78,7 +80,8 @@ public:
       assert(iter->ref->get_type() != extent_types_t::RETIRED_PLACEHOLDER);
       if (out)
 	*out = iter->ref;
-      SUBTRACET(seastore_tm, "Found offset {} in read_set: {}", *this, addr, *(iter->ref));
+      SUBTRACET(seastore_cache, "{} is present in read_set -- {}",
+                *this, addr, *(iter->ref));
       return get_extent_ret::PRESENT;
     } else {
       return get_extent_ret::ABSENT;
@@ -115,7 +118,6 @@ public:
   void add_fresh_extent(
     CachedExtentRef ref,
     bool delayed = false) {
-    LOG_PREFIX(Transaction::add_fresh_extent);
     ceph_assert(!is_weak());
     if (delayed) {
       assert(ref->is_logical());
@@ -128,39 +130,30 @@ public:
       inline_block_list.push_back(ref);
     }
     fresh_block_stats.increment(ref->get_length());
-    SUBTRACET(seastore_tm, "adding {} to write_set", *this, *ref);
     write_set.insert(*ref);
   }
 
   void mark_delayed_extent_inline(LogicalCachedExtentRef& ref) {
-    LOG_PREFIX(Transaction::mark_delayed_extent_inline);
-    SUBTRACET(seastore_tm, "removing {} from write_set", *this, *ref);
     write_set.erase(*ref);
     ref->set_paddr(make_record_relative_paddr(offset));
     offset += ref->get_length();
     inline_block_list.push_back(ref);
-    SUBTRACET(seastore_tm, "adding {} to write_set", *this, *ref);
     write_set.insert(*ref);
   }
 
   void mark_delayed_extent_ool(LogicalCachedExtentRef& ref, paddr_t final_addr) {
-    LOG_PREFIX(Transaction::mark_delayed_extent_ool);
-    SUBTRACET(seastore_tm, "removing {} from write_set", *this, *ref);
     write_set.erase(*ref);
     ref->set_paddr(final_addr);
     assert(!ref->get_paddr().is_null());
     assert(!ref->is_inline());
     ool_block_list.push_back(ref);
-    SUBTRACET(seastore_tm, "adding {} to write_set", *this, *ref);
     write_set.insert(*ref);
   }
 
   void add_mutated_extent(CachedExtentRef ref) {
-    LOG_PREFIX(Transaction::add_mutated_extent);
     ceph_assert(!is_weak());
     assert(read_set.count(ref->prior_instance->get_paddr()));
     mutated_block_list.push_back(ref);
-    SUBTRACET(seastore_tm, "adding {} to write_set", *this, *ref);
     write_set.insert(*ref);
   }