crimson/os/seastore: introduce seastore_t logs

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

5 files changed, 104 insertions, 51 deletions

diff --git a/src/common/subsys.h b/src/common/subsys.h
index 0667bbd79af..603a3be9c06 100644
--- a/src/common/subsys.h
+++ b/src/common/subsys.h
@@ -88,6 +88,7 @@ SUBSYS(seastore_onode, 0, 5)
 SUBSYS(seastore_odata, 0, 5)
 SUBSYS(seastore_omap, 0, 5)
 SUBSYS(seastore_tm, 0, 5)    // logs below seastore tm
+SUBSYS(seastore_t, 0, 5)
 SUBSYS(seastore_cleaner, 0, 5)
 SUBSYS(seastore_lba, 0, 5)
 SUBSYS(seastore_cache, 0, 5)
diff --git a/src/crimson/os/seastore/cache.cc b/src/crimson/os/seastore/cache.cc
index 3ee1d6ec838..5bb04886464 100644
--- a/src/crimson/os/seastore/cache.cc
+++ b/src/crimson/os/seastore/cache.cc
@@ -725,16 +725,19 @@ void Cache::invalidate_extent(
     Transaction& t,
     CachedExtent& extent)
 {
-  LOG_PREFIX(Cache::invalidate);
-  DEBUGT("conflict begin -- extent {}", t, extent);
+  LOG_PREFIX(Cache::invalidate_extent);
+  bool do_conflict_log = true;
   for (auto &&i: extent.transactions) {
     if (!i.t->conflicted) {
+      if (do_conflict_log) {
+        SUBDEBUGT(seastore_t, "conflict begin -- {}", t, extent);
+        do_conflict_log = false;
+      }
       assert(!i.t->is_weak());
       account_conflict(t.get_src(), i.t->get_src());
       mark_transaction_conflicted(*i.t, extent);
     }
   }
-  DEBUGT("conflict end", t);
   extent.state = CachedExtent::extent_state_t::INVALID;
 }
 
@@ -742,8 +745,8 @@ void Cache::mark_transaction_conflicted(
   Transaction& t, CachedExtent& conflicting_extent)
 {
   LOG_PREFIX(Cache::mark_transaction_conflicted);
+  SUBTRACET(seastore_t, "", t);
   assert(!t.conflicted);
-  DEBUGT("set conflict", t);
   t.conflicted = true;
 
   auto& efforts = get_by_src(stats.invalidated_efforts_by_src,
@@ -783,8 +786,8 @@ void Cache::mark_transaction_conflicted(
     auto& ool_stats = t.get_ool_write_stats();
     efforts.fresh_ool_written.increment_stat(ool_stats.extents);
     efforts.num_ool_records += ool_stats.num_records;
-    efforts.ool_record_bytes +=
-      (ool_stats.header_bytes + ool_stats.data_bytes);
+    auto ool_record_bytes = (ool_stats.header_bytes + ool_stats.data_bytes);
+    efforts.ool_record_bytes += ool_record_bytes;
     // Note: we only account overhead from committed ool records
 
     if (t.get_src() == Transaction::src_t::CLEANER_TRIM ||
@@ -798,6 +801,16 @@ void Cache::mark_transaction_conflicted(
 
     get_by_src(stats.invalidated_lba_tree_efforts, t.get_src()
         ).increment(t.lba_tree_stats);
+
+    SUBDEBUGT(seastore_t,
+        "discard {} read, {} fresh, {} delta, {} retire, {}({}B) ool-records",
+        t,
+        read_stat,
+        fresh_stat,
+        delta_stat,
+        retire_stat,
+        ool_stats.num_records,
+        ool_record_bytes);
   } else {
     // read transaction won't have non-read efforts
     assert(t.retired_set.empty());
@@ -806,23 +819,27 @@ void Cache::mark_transaction_conflicted(
     assert(t.get_ool_write_stats().is_clear());
     assert(t.onode_tree_stats.is_clear());
     assert(t.lba_tree_stats.is_clear());
+    SUBDEBUGT(seastore_t, "discard {} read", t, read_stat);
   }
 }
 
 void Cache::on_transaction_destruct(Transaction& t)
 {
   LOG_PREFIX(Cache::on_transaction_destruct);
+  SUBTRACET(seastore_t, "", t);
   if (t.get_src() == Transaction::src_t::READ &&
-      t.conflicted == false &&
-      !t.is_weak()) {
-    DEBUGT("read is successful", t);
+      t.conflicted == false) {
     io_stat_t read_stat;
     for (auto &i: t.read_set) {
       read_stat.increment(i.ref->get_length());
     }
+    SUBDEBUGT(seastore_t, "done {} read", t, read_stat);
 
-    ++stats.success_read_efforts.num_trans;
-    stats.success_read_efforts.read.increment_stat(read_stat);
+    if (!t.is_weak()) {
+      // exclude weak transaction as it is impossible to conflict
+      ++stats.success_read_efforts.num_trans;
+      stats.success_read_efforts.read.increment_stat(read_stat);
+    }
 
     // read transaction won't have non-read efforts
     assert(t.retired_set.empty());
@@ -900,7 +917,7 @@ CachedExtentRef Cache::duplicate_for_write(
 record_t Cache::prepare_record(Transaction &t)
 {
   LOG_PREFIX(Cache::prepare_record);
-  DEBUGT("enter", t);
+  SUBTRACET(seastore_t, "enter", t);
 
   auto trans_src = t.get_src();
   assert(!t.is_weak());
@@ -910,15 +927,17 @@ record_t Cache::prepare_record(Transaction &t)
                              trans_src);
 
   // Should be valid due to interruptible future
+  io_stat_t read_stat;
   for (auto &i: t.read_set) {
     if (!i.ref->is_valid()) {
-      DEBUGT("read_set invalid extent: {}, aborting", t, *i.ref);
+      SUBERRORT(seastore_t,
+          "read_set got invalid extent, aborting -- {}", t, *i.ref);
       ceph_abort("no invalid extent allowed in transactions' read_set");
     }
     get_by_ext(efforts.read_by_ext,
                i.ref->get_type()).increment(i.ref->get_length());
+    read_stat.increment(i.ref->get_length());
   }
-  DEBUGT("read_set validated", t);
   t.read_set.clear();
   t.write_set.clear();
 
@@ -926,16 +945,20 @@ record_t Cache::prepare_record(Transaction &t)
 
   // Add new copy of mutated blocks, set_io_wait to block until written
   record.deltas.reserve(t.mutated_block_list.size());
+  io_stat_t delta_stat;
   for (auto &i: t.mutated_block_list) {
     if (!i->is_valid()) {
-      DEBUGT("ignoring invalid {}", t, *i);
+      DEBUGT("invalid mutated extent -- {}", t, *i);
       continue;
     }
-    DEBUGT("mutating {}", t, *i);
+    assert(i->prior_instance);
+    auto delta_bl = i->get_delta();
+    auto delta_length = delta_bl.length();
+    DEBUGT("mutated extent with {}B delta -- {}, prior={}",
+           t, delta_length, *i, *i->prior_instance);
     get_by_ext(efforts.mutate_by_ext,
                i->get_type()).increment(i->get_length());
 
-    assert(i->prior_instance);
     commit_replace_extent(t, i, i->prior_instance);
 
     i->prepare_write();
@@ -944,9 +967,10 @@ record_t Cache::prepare_record(Transaction &t)
     assert(i->get_version() > 0);
     auto final_crc = i->get_crc32c();
     if (i->get_type() == extent_types_t::ROOT) {
+      SUBTRACET(seastore_t, "writing out root delta {}B -- {}",
+                t, delta_length, *i);
       assert(t.root == i);
       root = t.root;
-      DEBUGT("writing out root delta for {}", t, *t.root);
       record.push_back(
 	delta_info_t{
 	  extent_types_t::ROOT,
@@ -956,7 +980,7 @@ record_t Cache::prepare_record(Transaction &t)
 	  0,
 	  0,
 	  t.root->get_version() - 1,
-	  t.root->get_delta()
+	  std::move(delta_bl)
 	});
     } else {
       record.push_back(
@@ -970,22 +994,24 @@ record_t Cache::prepare_record(Transaction &t)
 	  final_crc,
 	  (seastore_off_t)i->get_length(),
 	  i->get_version() - 1,
-	  i->get_delta()
+	  std::move(delta_bl)
 	});
       i->last_committed_crc = final_crc;
     }
-    auto delta_length = record.deltas.back().bl.length();
     assert(delta_length);
     get_by_ext(efforts.delta_bytes_by_ext,
                i->get_type()) += delta_length;
+    delta_stat.increment(delta_length);
   }
 
   // Transaction is now a go, set up in-memory cache state
   // invalidate now invalid blocks
+  io_stat_t retire_stat;
   for (auto &i: t.retired_set) {
     DEBUGT("retiring {}", t, *i);
     get_by_ext(efforts.retire_by_ext,
                i->get_type()).increment(i->get_length());
+    retire_stat.increment(i->get_length());
     commit_retire_extent(t, i);
     if (i->backend_type == device_type_t::RANDOM_BLOCK) {
       paddr_t paddr = i->get_paddr();
@@ -997,14 +1023,18 @@ record_t Cache::prepare_record(Transaction &t)
   }
 
   record.extents.reserve(t.inline_block_list.size());
+  io_stat_t fresh_stat;
+  io_stat_t fresh_invalid_stat;
   for (auto &i: t.inline_block_list) {
     if (!i->is_valid()) {
       DEBUGT("fresh inline block (invalid) {}", 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);
     }
+    fresh_stat.increment(i->get_length());
     get_by_ext(efforts.fresh_inline_by_ext,
                i->get_type()).increment(i->get_length());
     assert(i->is_inline());
@@ -1053,23 +1083,29 @@ record_t Cache::prepare_record(Transaction &t)
   ceph_assert(ool_stats.extents.num == t.ool_block_list.size());
 
   if (record.is_empty()) {
-    // XXX: improve osd logic to not submit empty transactions.
-    DEBUGT("record to submit is empty, src={}!", t, trans_src);
+    SUBINFOT(seastore_t,
+        "record to submit is empty, src={}", t, trans_src);
     assert(t.onode_tree_stats.is_clear());
     assert(t.lba_tree_stats.is_clear());
     assert(ool_stats.is_clear());
   }
 
-  DEBUGT("record is ready to submit, src={}, mdsize={}, dsize={}; "
-         "{} ool records, mdsize={}, dsize={}, fillness={}",
-         t, trans_src,
-         record.size.get_raw_mdlength(),
-         record.size.dlength,
-         ool_stats.num_records,
-         ool_stats.header_raw_bytes,
-         ool_stats.data_bytes,
-         ((double)(ool_stats.header_raw_bytes + ool_stats.data_bytes) /
-          (ool_stats.header_bytes + ool_stats.data_bytes)));
+  SUBDEBUGT(seastore_t,
+      "commit H{} {} read, {} fresh with {} invalid, {} delta, {} retire, "
+      "{}(md={}B, data={}B, fill={}) ool-records, {}B md, {}B data",
+      t, (void*)&t.get_handle(),
+      read_stat,
+      fresh_stat,
+      fresh_invalid_stat,
+      delta_stat,
+      retire_stat,
+      ool_stats.num_records,
+      ool_stats.header_raw_bytes,
+      ool_stats.data_bytes,
+      ((double)(ool_stats.header_raw_bytes + ool_stats.data_bytes) /
+       (ool_stats.header_bytes + ool_stats.data_bytes)),
+      record.size.get_raw_mdlength(),
+      record.size.dlength);
   if (trans_src == Transaction::src_t::CLEANER_TRIM ||
       trans_src == Transaction::src_t::CLEANER_RECLAIM) {
     // CLEANER transaction won't contain any onode tree operations
@@ -1107,7 +1143,8 @@ void Cache::complete_commit(
   SegmentCleaner *cleaner)
 {
   LOG_PREFIX(Cache::complete_commit);
-  DEBUGT("enter", t);
+  SUBTRACET(seastore_t, "final_block_start={}, seq={}",
+            t, final_block_start, seq);
 
   t.for_each_fresh_block([&](auto &i) {
     if (i->is_inline()) {
diff --git a/src/crimson/os/seastore/cache.h b/src/crimson/os/seastore/cache.h
index 515d62c698b..0060dd8ad5e 100644
--- a/src/crimson/os/seastore/cache.h
+++ b/src/crimson/os/seastore/cache.h
@@ -83,6 +83,12 @@ namespace crimson::os::seastore {
  *   CachedExtent::delta_written(paddr_t) with the address of the start
  *   of the record
  * - Complete all promises with the final record start paddr_t
+ *
+ *
+ * Cache logs
+ *
+ * levels:
+ * - seastore_t logs
  */
 class Cache {
 public:
@@ -111,8 +117,8 @@ public:
         return on_transaction_destruct(t);
       }
     );
-    SUBDEBUGT(seastore_cache, "created name={}, source={}, is_weak={}",
-              *ret, name, src, is_weak);
+    SUBDEBUGT(seastore_t, "created name={}, source={}, is_weak={}",
+             *ret, name, src, is_weak);
     return ret;
   }
 
@@ -120,10 +126,10 @@ public:
   void reset_transaction_preserve_handle(Transaction &t) {
     LOG_PREFIX(Cache::reset_transaction_preserve_handle);
     if (t.did_reset()) {
+      SUBTRACET(seastore_t, "reset", t);
       ++(get_by_src(stats.trans_created_by_src, t.get_src()));
     }
     t.reset_preserve_handle(last_commit);
-    SUBDEBUGT(seastore_cache, "reset", t);
   }
 
   /// Declare ref retired in t
diff --git a/src/crimson/os/seastore/transaction.h b/src/crimson/os/seastore/transaction.h
index 5f1ee1d31fa..9fe502ab33a 100644
--- a/src/crimson/os/seastore/transaction.h
+++ b/src/crimson/os/seastore/transaction.h
@@ -45,6 +45,11 @@ inline std::ostream& operator<<(std::ostream& out, const io_stat_t& stat) {
  * Transaction
  *
  * Representation of in-progress mutation. Used exclusively through Cache methods.
+ *
+ * Transaction log levels:
+ * seastore_t
+ * - DEBUG: transaction create, conflict, commit events
+ * - TRACE: DEBUG details
  */
 class Transaction {
 public:
diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc
index 3dfb8977af6..15c6672b5b4 100644
--- a/src/crimson/os/seastore/transaction_manager.cc
+++ b/src/crimson/os/seastore/transaction_manager.cc
@@ -9,6 +9,12 @@
 #include "crimson/os/seastore/segment_manager.h"
 #include "crimson/os/seastore/journal.h"
 
+/*
+ * TransactionManager logs
+ *
+ * levels:
+ * - seastore_t logs
+ */
 SET_SUBSYS(seastore_tm);
 
 namespace crimson::os::seastore {
@@ -239,17 +245,18 @@ TransactionManager::submit_transaction(
   Transaction &t)
 {
   LOG_PREFIX(TransactionManager::submit_transaction);
+  SUBTRACET(seastore_t, "start", t);
   return trans_intr::make_interruptible(
     t.get_handle().enter(write_pipeline.reserve_projected_usage)
   ).then_interruptible([this, FNAME, &t] {
     size_t projected_usage = t.get_allocation_size();
-    DEBUGT("waiting for projected_usage: {}", t, projected_usage);
+    SUBTRACET(seastore_t, "waiting for projected_usage: {}", t, projected_usage);
     return trans_intr::make_interruptible(
       segment_cleaner->reserve_projected_usage(projected_usage)
     ).then_interruptible([this, &t] {
       return submit_transaction_direct(t);
     }).finally([this, FNAME, projected_usage, &t] {
-      DEBUGT("releasing projected_usage: {}", t, projected_usage);
+      SUBTRACET(seastore_t, "releasing projected_usage: {}", t, projected_usage);
       segment_cleaner->release_projected_usage(projected_usage);
     });
   });
@@ -260,18 +267,18 @@ TransactionManager::submit_transaction_direct(
   Transaction &tref)
 {
   LOG_PREFIX(TransactionManager::submit_transaction_direct);
-  DEBUGT("about to alloc delayed extents", tref);
-
+  SUBTRACET(seastore_t, "start", tref);
   return trans_intr::make_interruptible(
     tref.get_handle().enter(write_pipeline.ool_writes)
-  ).then_interruptible([this, &tref] {
+  ).then_interruptible([this, FNAME, &tref] {
+    SUBTRACET(seastore_t, "process delayed and out-of-line extents", tref);
     return epm->delayed_alloc_or_ool_write(tref
     ).handle_error_interruptible(
       crimson::ct_error::input_output_error::pass_further(),
       crimson::ct_error::assert_all("invalid error")
     );
   }).si_then([this, FNAME, &tref] {
-    DEBUGT("about to prepare", tref);
+    SUBTRACET(seastore_t, "about to prepare", tref);
     return tref.get_handle().enter(write_pipeline.prepare);
   }).si_then([this, FNAME, &tref]() mutable
 	      -> submit_transaction_iertr::future<> {
@@ -279,17 +286,12 @@ TransactionManager::submit_transaction_direct(
 
     tref.get_handle().maybe_release_collection_lock();
 
-    DEBUGT("about to submit to journal", tref);
-
+    SUBTRACET(seastore_t, "about to submit to journal", tref);
     return journal->submit_record(std::move(record), tref.get_handle()
     ).safe_then([this, FNAME, &tref](auto submit_result) mutable {
+      SUBDEBUGT(seastore_t, "committed with {}", tref, submit_result);
       auto start_seq = submit_result.write_result.start_seq;
       auto end_seq = submit_result.write_result.get_end_seq();
-      DEBUGT("journal commit to record_block_base={}, start_seq={}, end_seq={}",
-             tref,
-             submit_result.record_block_base,
-             start_seq,
-             end_seq);
       segment_cleaner->set_journal_head(end_seq);
       cache->complete_commit(
           tref,
@@ -301,6 +303,7 @@ TransactionManager::submit_transaction_direct(
 	cache->get_oldest_dirty_from().value_or(start_seq));
       auto to_release = tref.get_segment_to_release();
       if (to_release != NULL_SEG_ID) {
+        SUBDEBUGT(seastore_t, "releasing segment {}", tref, to_release);
 	return segment_manager.release(to_release
 	).safe_then([this, to_release] {
 	  segment_cleaner->mark_segment_released(to_release);
@@ -308,7 +311,8 @@ TransactionManager::submit_transaction_direct(
       } else {
 	return SegmentManager::release_ertr::now();
       }
-    }).safe_then([&tref] {
+    }).safe_then([FNAME, &tref] {
+      SUBTRACET(seastore_t, "completed", tref);
       return tref.get_handle().complete();
     }).handle_error(
       submit_transaction_iertr::pass_further{},