crimson/os/seastore: better epm output

Signed-off-by: Xuehan Xu <xxhdx1985126@gmail.com>

diff --git a/src/crimson/os/seastore/extent_placement_manager.cc b/src/crimson/os/seastore/extent_placement_manager.cc
index 77ccd1a7e84eba678a13b1f65942fd41a2e50563..2f4bb480523dc126484f73263c391ba970eb8907 100644 (file)
--- a/src/crimson/os/seastore/extent_placement_manager.cc
+++ b/src/crimson/os/seastore/extent_placement_manager.cc
@@ -44,9 +44,10 @@ SegmentedAllocator::Writer::finish_write(
   ool_record_t& record) {
   return trans_intr::do_for_each(record.get_extents(),
     [this, &t](auto& ool_extent) {
+    LOG_PREFIX(SegmentedAllocator::Writer::finish_write);
     auto& lextent = ool_extent.get_lextent();
-    logger().debug("SegmentedAllocator::Writer::finish_write: "
-      "extent: {}, ool_paddr: {}",
+    DEBUGT("extent: {}, ool_paddr: {}",
+      t,
       *lextent,
       ool_extent.get_ool_paddr());
     return lba_manager.update_mapping(
@@ -74,10 +75,11 @@ SegmentedAllocator::Writer::_write(
   bufferlist bl = record.encode(current_segment->segment->get_segment_id(), 0);
   seastar::promise<> pr;
   current_segment->inflight_writes.emplace_back(pr.get_future());
+  LOG_PREFIX(SegmentedAllocator::Writer::_write);
 
-  logger().debug(
-    "SegmentedAllocator::Writer::write: written {} extents,"
-    " {} bytes to segment {} at {}",
+  DEBUGT(
+    "written {} extents, {} bytes to segment {} at {}",
+    t,
     record.get_num_extents(),
     bl.length(),
     current_segment->segment->get_segment_id(),
@@ -85,12 +87,15 @@ SegmentedAllocator::Writer::_write(
 
   return trans_intr::make_interruptible(
     current_segment->segment->write(record.get_base(), bl).safe_then(
-      [this, pr=std::move(pr),
+      [this, pr=std::move(pr), &t,
       it=(--current_segment->inflight_writes.end()),
       cs=current_segment]() mutable {
+        LOG_PREFIX(SegmentedAllocator::Writer::_write);
         if (cs->outdated) {
+          DEBUGT("segment rolled", t);
           pr.set_value();
         } else{
+          DEBUGT("segment not rolled", t);
           current_segment->inflight_writes.erase(it);
         }
         return seastar::now();
@@ -131,6 +136,7 @@ SegmentedAllocator::Writer::write(
             return !rolling_segment;
           },
           [this, &record, &extents, &t]() -> write_iertr::future<> {
+            LOG_PREFIX(SegmentedAllocator::Writer::write);
             record.set_base(allocated_to);
             for (auto it = extents.begin();
                  it != extents.end();) {
@@ -142,8 +148,9 @@ SegmentedAllocator::Writer::write(
                 assert(!rolling_segment);
                 rolling_segment = true;
                 auto num_extents = record.get_num_extents();
-                logger().debug(
-                  "SegmentedAllocator::Writer::write: end of segment, writing {} extents to segment {} at {}",
+                DEBUGT(
+                  "end of segment, writing {} extents to segment {} at {}",
+                  t,
                   num_extents,
                   current_segment->segment->get_segment_id(),
                   allocated_to);
@@ -159,8 +166,9 @@ SegmentedAllocator::Writer::write(
             }
             record_size_t rsize = record.get_encoded_record_length();
 
-            logger().debug(
-              "SegmentedAllocator::Writer::write: writing {} extents to segment {} at {}",
+            DEBUGT(
+              "writing {} extents to segment {} at {}",
+              t,
               record.get_num_extents(),
               current_segment->segment->get_segment_id(),
               allocated_to);
@@ -222,6 +230,8 @@ SegmentedAllocator::Writer::init_segment(Segment& segment) {
 
 SegmentedAllocator::Writer::roll_segment_ertr::future<>
 SegmentedAllocator::Writer::roll_segment(bool set_rolling) {
+  LOG_PREFIX(SegmentedAllocator::Writer::roll_segment);
+  DEBUG("set_rolling {}", set_rolling);
   if (set_rolling) {
     rolling_segment = true;
   }
@@ -238,15 +248,16 @@ SegmentedAllocator::Writer::roll_segment(bool set_rolling) {
       return fut.then(
         [cs=std::move(current_segment), this, it=(--open_segments.end())] {
         return cs->segment->close().safe_then([this, cs, it] {
+          LOG_PREFIX(SegmentedAllocator::Writer::roll_segment);
           assert((*it).get() == cs.get());
           segment_provider.close_segment(cs->segment->get_segment_id());
           open_segments.erase(it);
+          DEBUG("closed segment: {}", cs->segment->get_segment_id());
         });
       });
     }).handle_exception_type([](seastar::gate_closed_exception e) {
-      logger().debug(
-        "SegmentedAllocator::Writer::roll_segment:"
-        " writer_guard closed, should be stopping");
+      LOG_PREFIX(SegmentedAllocator::Writer::roll_segment);
+      DEBUG(" writer_guard closed, should be stopping");
       return seastar::now();
     });
   }
@@ -254,13 +265,17 @@ SegmentedAllocator::Writer::roll_segment(bool set_rolling) {
   return segment_provider.get_segment().safe_then([this](auto segment) {
     return segment_manager.open(segment);
   }).safe_then([this](auto segref) {
+    LOG_PREFIX(SegmentedAllocator::Writer::roll_segment);
+    DEBUG("opened new segment: {}", segref->get_segment_id());
     return init_segment(*segref).safe_then([segref=std::move(segref), this] {
+      LOG_PREFIX(SegmentedAllocator::Writer::roll_segment);
       assert(!current_segment.get());
       current_segment.reset(new open_segment_wrapper_t());
       current_segment->segment = segref;
       open_segments.emplace_back(current_segment);
       rolling_segment = false;
       segment_rotation_guard.broadcast();
+      DEBUG("inited new segment: {}", segref->get_segment_id());
     });
   }).handle_error(
     roll_segment_ertr::pass_further{},

diff --git a/src/crimson/os/seastore/extent_placement_manager.h b/src/crimson/os/seastore/extent_placement_manager.h
index e7cfb8a8abd52a3341e57f064019c7d54112651d..29e590b0d20ffa21ab5e3b93ee782fdd21f7c5db 100644 (file)
--- a/src/crimson/os/seastore/extent_placement_manager.h
+++ b/src/crimson/os/seastore/extent_placement_manager.h
@@ -6,7 +6,7 @@
 #include "seastar/core/gate.hh"
 
 #include "crimson/common/condition_variable.h"
-#include "crimson/common/log.h"
+#include "crimson/os/seastore/logging.h"
 #include "crimson/os/seastore/cache.h"
 #include "crimson/os/seastore/cached_extent.h"
 #include "crimson/os/seastore/lba_manager.h"
@@ -259,6 +259,8 @@ public:
   alloc_paddr_iertr::future<> alloc_ool_extents_paddr(
     Transaction& t,
     std::list<LogicalCachedExtentRef>& extents) final {
+    LOG_PREFIX(SegmentedAllocator::alloc_ool_extents_paddr);
+    DEBUGT("start", t);
     return seastar::do_with(
       std::map<Writer*, std::list<LogicalCachedExtentRef>>(),
       [this, extents=std::move(extents), &t](auto& alloc_map) {
@@ -355,11 +357,15 @@ public:
   using alloc_paddr_iertr = ExtentOolWriter::write_iertr;
   alloc_paddr_iertr::future<> delayed_alloc_or_ool_write(
     Transaction& t) {
+    LOG_PREFIX(ExtentPlacementManager::delayed_alloc_or_ool_write);
+    DEBUGT("start", t);
     return seastar::do_with(
       std::map<ExtentAllocator*, std::list<LogicalCachedExtentRef>>(),
       std::list<std::pair<paddr_t, LogicalCachedExtentRef>>(),
       [this, &t](auto& alloc_map, auto& inline_list) mutable {
+      LOG_PREFIX(ExtentPlacementManager::delayed_alloc_or_ool_write);
       auto& alloc_list = t.get_delayed_alloc_list();
+      uint64_t num_ool_extents = 0;
       for (auto& extent : alloc_list) {
         // extents may be invalidated
         if (!extent->is_valid()) {
@@ -373,12 +379,19 @@ public:
         }
         auto& allocator_ptr = get_allocator(extent->backend_type, extent->hint);
         alloc_map[allocator_ptr.get()].emplace_back(extent);
+        num_ool_extents++;
       }
+      DEBUGT("{} inline extents, {} ool extents",
+        t,
+        inline_list.size(),
+        num_ool_extents);
       return trans_intr::do_for_each(alloc_map, [&t](auto& p) {
         auto allocator = p.first;
         auto& extents = p.second;
         return allocator->alloc_ool_extents_paddr(t, extents);
       }).si_then([&inline_list, this, &t] {
+        LOG_PREFIX(ExtentPlacementManager::delayed_alloc_or_ool_write);
+        DEBUGT("processing {} inline extents", t, inline_list.size());
         return trans_intr::do_for_each(inline_list, [this, &t](auto& p) {
           auto old_addr = p.first;
           auto& extent = p.second;

diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc
index 8cc0e0b44a470acddaeb7dcc18c2cc05689c63bf..df14ed2fb2ad914e3a2c36b87f1f25accdfb5d85 100644 (file)
--- a/src/crimson/os/seastore/transaction_manager.cc
+++ b/src/crimson/os/seastore/transaction_manager.cc
@@ -236,13 +236,15 @@ TransactionManager::submit_transaction_direct(
   Transaction &tref)
 {
   LOG_PREFIX(TransactionManager::submit_transaction_direct);
-  DEBUGT("about to prepare", tref);
+  DEBUGT("about to alloc delayed 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([&tref, this] {
+    LOG_PREFIX(TransactionManager::submit_transaction_direct);
+    DEBUGT("about to prepare", tref);
     return tref.get_handle().enter(write_pipeline.prepare);
   }).si_then([this, FNAME, &tref]() mutable
              -> submit_transaction_iertr::future<> {