crimson/os/seastore: improve seastore_t logs

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

diff --git a/src/crimson/os/seastore/cache.cc b/src/crimson/os/seastore/cache.cc
index db3b8b3766c532a2fef75b8fb5c29a378985830a..801ba356fbe4f65ad84d89d34f46ef00978dea96 100644 (file)
--- a/src/crimson/os/seastore/cache.cc
+++ b/src/crimson/os/seastore/cache.cc
@@ -1083,7 +1083,8 @@ record_t Cache::prepare_record(
   const journal_seq_t &journal_dirty_tail)
 {
   LOG_PREFIX(Cache::prepare_record);
-  SUBTRACET(seastore_t, "enter", t);
+  SUBTRACET(seastore_t, "enter, journal_head={}, dirty_tail={}",
+            t, journal_head, journal_dirty_tail);
 
   auto trans_src = t.get_src();
   assert(!t.is_weak());

diff --git a/src/crimson/os/seastore/cache.h b/src/crimson/os/seastore/cache.h
index 86f27ee7d12671e235f52a61d76078c434eb438f..a3becb78ee9aadf43acede0fd9cf26287124b218 100644 (file)
--- a/src/crimson/os/seastore/cache.h
+++ b/src/crimson/os/seastore/cache.h
@@ -218,7 +218,7 @@ public:
       ++next_id
     );
     SUBDEBUGT(seastore_t, "created name={}, source={}, is_weak={}",
-             *ret, name, src, is_weak);
+              *ret, name, src, is_weak);
     assert(!is_weak || src == Transaction::src_t::READ);
     return ret;
   }
@@ -227,7 +227,7 @@ public:
   void reset_transaction_preserve_handle(Transaction &t) {
     LOG_PREFIX(Cache::reset_transaction_preserve_handle);
     if (t.did_reset()) {
-      SUBTRACET(seastore_t, "reset", t);
+      SUBDEBUGT(seastore_t, "reset", t);
       ++(get_by_src(stats.trans_created_by_src, t.get_src()));
     }
     t.reset_preserve_handle(last_commit);

diff --git a/src/crimson/os/seastore/seastore.cc b/src/crimson/os/seastore/seastore.cc
index 39d7e7ec2314427511c3ea72c5d262831469aa55..a8dba42b34af5880b1f217752c47fb807561fe9b 100644 (file)
--- a/src/crimson/os/seastore/seastore.cc
+++ b/src/crimson/os/seastore/seastore.cc
@@ -1251,8 +1251,10 @@ seastar::future<> SeaStore::Shard::do_transaction_no_callbacks(
     op_type_t::TRANSACTION,
     [this](auto &ctx) {
       return with_trans_intr(*ctx.transaction, [&, this](auto &t) {
+        LOG_PREFIX(SeaStore::Shard::do_transaction_no_callbacks);
+        SUBDEBUGT(seastore_t, "start with {} objects",
+                  t, ctx.iter.objects.size());
 #ifndef NDEBUG
-       LOG_PREFIX(SeaStore::Shard::do_transaction_no_callbacks);
        TRACET(" transaction dump:\n", t);
        JSONFormatter f(true);
        f.open_object_section("transaction");
@@ -1311,7 +1313,9 @@ SeaStore::Shard::_do_transaction_step(
   std::vector<OnodeRef> &d_onodes,
   ceph::os::Transaction::iterator &i)
 {
+  LOG_PREFIX(SeaStore::Shard::_do_transaction_step);
   auto op = i.decode_op();
+  SUBTRACET(seastore_t, "got op {}", *ctx.transaction, op->op);
 
   using ceph::os::Transaction;
   if (op->op == Transaction::OP_NOP)

diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc
index 581777e68f111c060deb57496ebab94a4883c01c..b5ea2feec6b445dc68ee61d2684c9e9614869dac 100644 (file)
--- a/src/crimson/os/seastore/transaction_manager.cc
+++ b/src/crimson/os/seastore/transaction_manager.cc
@@ -283,7 +283,7 @@ TransactionManager::submit_transaction(
   Transaction &t)
 {
   LOG_PREFIX(TransactionManager::submit_transaction);
-  SUBTRACET(seastore_t, "start", t);
+  SUBDEBUGT(seastore_t, "start, entering reserve_projected_usage", t);
   return trans_intr::make_interruptible(
     t.get_handle().enter(write_pipeline.reserve_projected_usage)
   ).then_interruptible([this, FNAME, &t] {
@@ -380,13 +380,14 @@ TransactionManager::do_submit_transaction(
   std::optional<journal_seq_t> trim_alloc_to)
 {
   LOG_PREFIX(TransactionManager::do_submit_transaction);
-  SUBTRACET(seastore_t, "start", tref);
+  SUBDEBUGT(seastore_t, "start, entering ool_writes", tref);
   return trans_intr::make_interruptible(
     tref.get_handle().enter(write_pipeline.ool_writes_and_lba_updates)
-  ).then_interruptible([this, &tref,
+  ).then_interruptible([this, FNAME, &tref,
                        dispatch_result = std::move(dispatch_result)] {
     return seastar::do_with(std::move(dispatch_result),
-                           [this, &tref](auto &dispatch_result) {
+                           [this, FNAME, &tref](auto &dispatch_result) {
+      SUBTRACET(seastore_t, "write delayed ool extents", tref);
       return epm->write_delayed_ool_extents(tref, dispatch_result.alloc_map
       ).handle_error_interruptible(
         crimson::ct_error::input_output_error::pass_further(),
@@ -409,11 +410,12 @@ TransactionManager::do_submit_transaction(
       });
     });
   }).si_then([this, FNAME, &tref] {
-    SUBTRACET(seastore_t, "about to prepare", tref);
+    SUBTRACET(seastore_t, "entering prepare", tref);
     return tref.get_handle().enter(write_pipeline.prepare);
   }).si_then([this, FNAME, &tref, trim_alloc_to=std::move(trim_alloc_to)]() mutable
              -> submit_transaction_iertr::future<> {
     if (trim_alloc_to && *trim_alloc_to != JOURNAL_SEQ_NULL) {
+      SUBTRACET(seastore_t, "trim backref_bufs to {}", tref, *trim_alloc_to);
       cache->trim_backref_bufs(*trim_alloc_to);
     }
 
@@ -424,7 +426,7 @@ TransactionManager::do_submit_transaction(
 
     tref.get_handle().maybe_release_collection_lock();
 
-    SUBTRACET(seastore_t, "about to submit to journal", tref);
+    SUBTRACET(seastore_t, "submitting record", 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);