crimson/os/seastore: misc log improvements

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 5a711a1b45c8f407d1b552267a71ec438387ba9d..b9d62693cc1e985206bb50d504c57e4ef5f8a0f9 100644 (file)
--- a/src/crimson/os/seastore/cache.cc
+++ b/src/crimson/os/seastore/cache.cc
@@ -84,12 +84,13 @@ 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);
     ext->set_paddr(addr);
     ext->state = CachedExtent::extent_state_t::CLEAN;
+    DEBUGT("retire {}~{} as placeholder, add extent -- {}",
+           t, addr, length, *ext);
     add_extent(ext);
   }
 
@@ -624,8 +625,6 @@ 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()) {
@@ -670,8 +669,6 @@ void Cache::remove_from_dirty(CachedExtentRef ref)
 
 void Cache::remove_extent(CachedExtentRef ref)
 {
-  LOG_PREFIX(Cache::remove_extent);
-  TRACE("extent -- {}", *ref);
   assert(ref->is_valid());
   if (ref->is_dirty()) {
     remove_from_dirty(ref);
@@ -958,13 +955,13 @@ record_t Cache::prepare_record(Transaction &t)
       continue;
     }
     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());
 
+    auto delta_bl = i->get_delta();
+    auto delta_length = delta_bl.length();
+    DEBUGT("mutated extent with {}B delta, commit replace extent ... -- {}, prior={}",
+           t, delta_length, *i, *i->prior_instance);
     commit_replace_extent(t, i, i->prior_instance);
 
     i->prepare_write();
@@ -1014,10 +1011,10 @@ record_t Cache::prepare_record(Transaction &t)
   // invalidate now invalid blocks
   io_stat_t retire_stat;
   for (auto &i: t.retired_set) {
-    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());
+    DEBUGT("retired and remove extent -- {}", t, *i);
     commit_retire_extent(t, i);
     // FIXME: whether the extent belongs to RBM should be available through its
     // device-id from its paddr after RBM is properly integrated.
@@ -1042,7 +1039,7 @@ record_t Cache::prepare_record(Transaction &t)
       get_by_ext(efforts.fresh_invalid_by_ext,
                  i->get_type()).increment(i->get_length());
     } else {
-      DEBUGT("fresh inline extent -- {}", t, *i);
+      TRACET("fresh inline extent -- {}", t, *i);
     }
     fresh_stat.increment(i->get_length());
     get_by_ext(efforts.fresh_inline_by_ext,
@@ -1078,8 +1075,9 @@ record_t Cache::prepare_record(Transaction &t)
   }
 
   for (auto &i: t.ool_block_list) {
+    TRACET("fresh ool extent -- {}", t, *i);
     ceph_assert(i->is_valid());
-    DEBUGT("fresh ool extent -- {}", t, *i);
+    assert(!i->is_inline());
     get_by_ext(efforts.fresh_ool_by_ext,
                i->get_type()).increment(i->get_length());
   }
@@ -1101,9 +1099,11 @@ record_t Cache::prepare_record(Transaction &t)
   }
 
   SUBDEBUGT(seastore_t,
-      "commit H{} {} read, {} fresh with {} invalid, {} delta, {} retire, "
-      "{}(md={}B, data={}B, fill={}) ool-records, {}B md, {}B data",
+      "commit H{} dirty_from={}, {} read, {} fresh with {} invalid, "
+      "{} delta, {} retire, {}(md={}B, data={}B, fill={}) ool-records, "
+      "{}B md, {}B data",
       t, (void*)&t.get_handle(),
+      get_oldest_dirty_from().value_or(journal_seq_t{}),
       read_stat,
       fresh_stat,
       fresh_invalid_stat,
@@ -1157,7 +1157,9 @@ void Cache::complete_commit(
             t, final_block_start, seq);
 
   t.for_each_fresh_block([&](auto &i) {
+    bool is_inline = false;
     if (i->is_inline()) {
+      is_inline = true;
       i->set_paddr(final_block_start.add_relative(i->get_paddr()));
     }
     i->last_committed_crc = i->get_crc32c();
@@ -1165,6 +1167,8 @@ void Cache::complete_commit(
 
     if (i->is_valid()) {
       i->state = CachedExtent::extent_state_t::CLEAN;
+      DEBUGT("add extent as fresh, inline={} -- {}",
+             t, is_inline, *i);
       add_extent(i);
       if (cleaner) {
        cleaner->mark_space_used(
@@ -1183,8 +1187,12 @@ void Cache::complete_commit(
     i->on_delta_write(final_block_start);
     i->prior_instance = CachedExtentRef();
     i->state = CachedExtent::extent_state_t::DIRTY;
+    assert(i->version > 0);
     if (i->version == 1 || i->get_type() == extent_types_t::ROOT) {
       i->dirty_from_or_retired_at = seq;
+      DEBUGT("commit extent done, become dirty -- {}", t, *i);
+    } else {
+      DEBUGT("commit extent done -- {}", t, *i);
     }
   }
 
@@ -1212,14 +1220,15 @@ void Cache::complete_commit(
 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
+    DEBUG("remove extent -- prv_root={}", *root);
     remove_extent(root);
     root = nullptr;
   }
   root = new RootBlock();
   root->state = CachedExtent::extent_state_t::CLEAN;
+  INFO("init root -- {}", *root);
   extents.insert(*root);
 }
 
@@ -1269,11 +1278,14 @@ Cache::replay_delta(
 {
   LOG_PREFIX(Cache::replay_delta);
   if (delta.type == extent_types_t::ROOT) {
-    DEBUG("replay root delta {} at {} {}", delta, journal_seq, record_base);
+    TRACE("replay root delta at {} {}, remove extent ... -- {}, prv_root={}",
+          journal_seq, record_base, delta, *root);
     remove_extent(root);
     root->apply_delta_and_adjust_crc(record_base, delta.bl);
     root->dirty_from_or_retired_at = journal_seq;
     root->state = CachedExtent::extent_state_t::DIRTY;
+    DEBUG("replayed root delta at {} {}, add extent -- {}, root={}",
+          journal_seq, record_base, delta, *root);
     add_extent(root);
     return replay_delta_ertr::now();
   } else {
@@ -1311,14 +1323,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);
+       DEBUG("replay extent is not present, so delta is obsolete at {} {} -- {}",
+             journal_seq, record_base, delta);
        assert(delta.pversion > 0);
        return;
       }
 
-      DEBUG("replay extent delta {} at {} {} -- {} ...",
-            delta, journal_seq, record_base, *extent);
+      TRACE("replay extent delta at {} {} ... -- {}, prv_extent={}",
+            journal_seq, record_base, delta, *extent);
 
       assert(extent->version == delta.pversion);
 
@@ -1326,10 +1338,15 @@ Cache::replay_delta(
       extent->apply_delta_and_adjust_crc(record_base, delta.bl);
       assert(extent->last_committed_crc == delta.final_crc);
 
-      if (extent->version == 0) {
+      extent->version++;
+      if (extent->version == 1) {
        extent->dirty_from_or_retired_at = journal_seq;
+        DEBUG("replayed extent delta at {} {}, become dirty -- {}, extent={}" ,
+              journal_seq, record_base, delta, *extent);
+      } else {
+        DEBUG("replayed extent delta at {} {} -- {}, extent={}" ,
+              journal_seq, record_base, delta, *extent);
       }
-      extent->version++;
       mark_dirty(extent);
     });
   }

diff --git a/src/crimson/os/seastore/cache.h b/src/crimson/os/seastore/cache.h
index 2d7042bd643a38f994e9729c26f234c57b00f1be..cc6e48648af10956412e642e9e17553fd0dc400a 100644 (file)
--- a/src/crimson/os/seastore/cache.h
+++ b/src/crimson/os/seastore/cache.h
@@ -191,12 +191,13 @@ public:
     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);
       ret->state = CachedExtent::extent_state_t::CLEAN_PENDING;
+      SUBDEBUG(seastore_cache,
+          "{} {}~{} is absent, add extent and reading ... -- {}",
+          T::TYPE, offset, length, *ret);
       add_extent(ret);
       extent_init_func(*ret);
       return read_extent<T>(
@@ -205,13 +206,13 @@ 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);
       ret->state = CachedExtent::extent_state_t::CLEAN_PENDING;
+      SUBDEBUG(seastore_cache,
+          "{} {}~{} is absent(placeholder), reading ... -- {}",
+          T::TYPE, offset, length, *ret);
       extents.replace(*ret, *cached);
 
       // replace placeholder in transactions
@@ -640,7 +641,7 @@ public:
         return f(t, e
         ).si_then([this, FNAME, &t, e](bool is_alive) {
           if (!is_alive) {
-            SUBDEBUGT(seastore_cache, "extent is not alive, remove -- {}", t, *e);
+            SUBDEBUGT(seastore_cache, "extent is not alive, remove extent -- {}", t, *e);
             remove_extent(e);
           } else {
             SUBDEBUGT(seastore_cache, "extent is alive -- {}", t, *e);

diff --git a/src/crimson/os/seastore/extent_reader.cc b/src/crimson/os/seastore/extent_reader.cc
index 15ca6cad765a6b3586eb853eec11baf45ad7df37..0baaa12c9445cf9213f70bf40a9aae5ba5a52c3d 100644 (file)
--- a/src/crimson/os/seastore/extent_reader.cc
+++ b/src/crimson/os/seastore/extent_reader.cc
@@ -114,6 +114,7 @@ ExtentReader::scan_valid_records_ret ExtentReader::scan_valid_records(
   auto& segment_manager =
     *segment_managers[cursor.get_segment_id().device_id()];
   if (cursor.get_segment_offset() == 0) {
+    INFO("start to scan segment {}", cursor.get_segment_id());
     cursor.increment_seq(segment_manager.get_block_size());
   }
   DEBUG("starting at {}, budget={}", cursor, budget);

diff --git a/src/crimson/os/seastore/journal.cc b/src/crimson/os/seastore/journal.cc
index dd2bd28ca5628af9b92c1309b9213d3472c3cb25..acba0e3ce411c6c1a88b63ac58fa4537e529c2ab 100644 (file)
--- a/src/crimson/os/seastore/journal.cc
+++ b/src/crimson/os/seastore/journal.cc
@@ -194,6 +194,7 @@ Journal::replay_segment(
             record_deltas.deltas,
             [locator,
              this,
+             FNAME,
              &handler](delta_info_t& delta)
           {
             /* The journal may validly contain deltas for extents in
@@ -211,6 +212,11 @@ Journal::replay_segment(
               if (delta_paddr_segment_type == segment_type_t::NULL_SEG ||
                   (delta_paddr_segment_type == segment_type_t::JOURNAL &&
                    delta_paddr_segment_seq > locator_segment_seq)) {
+                SUBDEBUG(seastore_cache,
+                         "delta is obsolete, delta_paddr_segment_seq={}, locator_segment_seq={} -- {}",
+                         segment_seq_printer_t{delta_paddr_segment_seq},
+                         segment_seq_printer_t{locator_segment_seq},
+                         delta);
                 return replay_ertr::now();
               }
             }

diff --git a/src/crimson/os/seastore/segment_cleaner.cc b/src/crimson/os/seastore/segment_cleaner.cc
index 846bb72b24c4c5d060533f388cc22acce1678a5b..8b87dc97f71c3b4ba81a77e953a2134ae54f7272 100644 (file)
--- a/src/crimson/os/seastore/segment_cleaner.cc
+++ b/src/crimson/os/seastore/segment_cleaner.cc
@@ -283,6 +283,7 @@ SegmentCleaner::rewrite_dirty_ret SegmentCleaner::rewrite_dirty(
     limit,
     config.journal_rewrite_per_cycle
   ).si_then([=, &t](auto dirty_list) {
+    DEBUGT("rewrite {} dirty extents", t, dirty_list.size());
     return seastar::do_with(
       std::move(dirty_list),
       [FNAME, this, &t](auto &dirty_list) {