Merge pull request ceph#44429 from cyx1231st/wip-crimson-improve-log-2

crimson/os/seastore: differentiate loggers in seastore Reviewed-by: Samuel Just <sjust@redhat.com>
Seagate · Jan 5, 2022 · c3f7bb8 · c3f7bb8
2 parents aa87b90 + 6329167
commit c3f7bb8
Show file tree

Hide file tree

Showing 39 changed files with 276 additions and 204 deletions.
diff --git a/src/common/subsys.h b/src/common/subsys.h
@@ -83,5 +83,14 @@ SUBSYS(prioritycache, 1, 5)
 SUBSYS(test, 0, 5)
 SUBSYS(cephfs_mirror, 0, 5)
 SUBSYS(cephsqlite, 0, 5)
-SUBSYS(seastore, 0, 5)
+SUBSYS(seastore, 0, 5)       // logs above seastore tm
+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_cleaner, 0, 5)
+SUBSYS(seastore_lba, 0, 5)
+SUBSYS(seastore_cache, 0, 5)
+SUBSYS(seastore_journal, 0, 5)
+SUBSYS(seastore_device, 0, 5)
 SUBSYS(alienstore, 0, 5)
diff --git a/src/crimson/os/seastore/cache.cc b/src/crimson/os/seastore/cache.cc
@@ -20,6 +20,8 @@
 
 using std::string_view;
 
+SET_SUBSYS(seastore_cache);
+
 namespace crimson::os::seastore {
 
 Cache::Cache(

diff --git a/src/crimson/os/seastore/cache.h b/src/crimson/os/seastore/cache.h
@@ -111,8 +111,8 @@ class Cache {
         return on_transaction_destruct(t);
       }
     );
-    DEBUGT("created name={}, source={}, is_weak={}",
-           *ret, name, src, is_weak);
+    SUBDEBUGT(seastore_cache, "created name={}, source={}, is_weak={}",
+              *ret, name, src, is_weak);
     return ret;
   }
 
@@ -123,7 +123,7 @@ class Cache {
       ++(get_by_src(stats.trans_created_by_src, t.get_src()));
     }
     t.reset_preserve_handle(last_commit);
-    DEBUGT("reset", t);
+    SUBDEBUGT(seastore_cache, "reset", t);
   }
 
   /**
@@ -255,7 +255,7 @@ class Cache {
     auto result = t.get_extent(offset, &ret);
     if (result != Transaction::get_extent_ret::ABSENT) {
       // including get_extent_ret::RETIRED
-      DEBUGT(
+      SUBDEBUGT(seastore_cache,
 	"Found extent at offset {} on transaction: {}",
 	t, offset, *ret);
       return get_extent_if_cached_iertr::make_ready_future<
@@ -268,15 +268,15 @@ class Cache {
     if (!ret ||
         // retired_placeholder is not really cached yet
         ret->get_type() == extent_types_t::RETIRED_PLACEHOLDER) {
-      DEBUGT(
+      SUBDEBUGT(seastore_cache,
 	"No extent at offset {}, retired_placeholder: {}",
 	t, offset, !!ret);
       return get_extent_if_cached_iertr::make_ready_future<
         CachedExtentRef>();
     }
 
     // present in cache and is not a retired_placeholder
-    DEBUGT(
+    SUBDEBUGT(seastore_cache,
       "Found extent at offset {} in cache: {}",
       t, offset, *ret);
     t.add_to_read_set(ret);
@@ -309,7 +309,7 @@ class Cache {
     auto result = t.get_extent(offset, &ret);
     if (result != Transaction::get_extent_ret::ABSENT) {
       assert(result != Transaction::get_extent_ret::RETIRED);
-      DEBUGT(
+      SUBDEBUGT(seastore_cache,
 	"Found extent at offset {} on transaction: {}",
 	t, offset, *ret);
       return seastar::make_ready_future<TCachedExtentRef<T>>(
@@ -323,12 +323,12 @@ class Cache {
       ).si_then([this, FNAME, offset, &t](auto ref) {
 	(void)this; // silence incorrect clang warning about capture
 	if (!ref->is_valid()) {
-	  DEBUGT("got invalid extent: {}", t, ref);
+	  SUBDEBUGT(seastore_cache, "got invalid extent: {}", t, 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 {
-	  DEBUGT(
+	  SUBDEBUGT(seastore_cache,
 	    "Read extent at offset {} in cache: {}",
 	    t, offset, *ref);
 	  touch_extent(*ref);
@@ -415,7 +415,7 @@ class Cache {
       ).si_then([=, &t](CachedExtentRef ret) {
         if (!ret->is_valid()) {
           LOG_PREFIX(Cache::get_extent_by_type);
-          DEBUGT("got invalid extent: {}", t, ret);
+          SUBDEBUGT(seastore_cache, "got invalid extent: {}", t, 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>();

diff --git a/src/crimson/os/seastore/cached_extent.cc b/src/crimson/os/seastore/cached_extent.cc
@@ -7,7 +7,7 @@
 
 namespace {
   [[maybe_unused]] seastar::logger& logger() {
-    return crimson::get_logger(ceph_subsys_seastore);
+    return crimson::get_logger(ceph_subsys_seastore_tm);
   }
 }
 

diff --git a/src/crimson/os/seastore/extent_placement_manager.cc b/src/crimson/os/seastore/extent_placement_manager.cc
@@ -6,10 +6,12 @@
 
 namespace {
   seastar::logger& logger() {
-    return crimson::get_logger(ceph_subsys_seastore);
+    return crimson::get_logger(ceph_subsys_seastore_tm);
   }
 }
 
+SET_SUBSYS(seastore_tm);
+
 namespace crimson::os::seastore {
 
 SegmentedAllocator::SegmentedAllocator(

diff --git a/src/crimson/os/seastore/extent_placement_manager.h b/src/crimson/os/seastore/extent_placement_manager.h
@@ -255,7 +255,7 @@ class SegmentedAllocator : public ExtentAllocator {
     Transaction& t,
     std::list<LogicalCachedExtentRef>& extents) final {
     LOG_PREFIX(SegmentedAllocator::alloc_ool_extents_paddr);
-    DEBUGT("start", t);
+    SUBDEBUGT(seastore_tm, "start", t);
     return seastar::do_with(
       std::map<Writer*, std::list<LogicalCachedExtentRef>>(),
       [this, extents=std::move(extents), &t](auto& alloc_map) {
@@ -348,7 +348,7 @@ class ExtentPlacementManager {
   alloc_paddr_iertr::future<> delayed_alloc_or_ool_write(
     Transaction& t) {
     LOG_PREFIX(ExtentPlacementManager::delayed_alloc_or_ool_write);
-    DEBUGT("start", t);
+    SUBDEBUGT(seastore_tm, "start", t);
     return seastar::do_with(
         std::map<ExtentAllocator*, std::list<LogicalCachedExtentRef>>(),
         [this, &t](auto& alloc_map) {
@@ -368,7 +368,7 @@ class ExtentPlacementManager {
         alloc_map[allocator_ptr.get()].emplace_back(extent);
         num_ool_extents++;
       }
-      DEBUGT("{} ool extents", t, num_ool_extents);
+      SUBDEBUGT(seastore_tm, "{} ool extents", t, num_ool_extents);
       return trans_intr::do_for_each(alloc_map, [&t](auto& p) {
         auto allocator = p.first;
         auto& extents = p.second;
@@ -380,7 +380,7 @@ class ExtentPlacementManager {
   void add_allocator(device_type_t type, ExtentAllocatorRef&& allocator) {
     allocators[type].emplace_back(std::move(allocator));
     LOG_PREFIX(ExtentPlacementManager::add_allocator);
-    DEBUG("allocators for {}: {}",
+    SUBDEBUG(seastore_tm, "allocators for {}: {}",
       device_type_to_string(type),
       allocators[type].size());
   }

diff --git a/src/crimson/os/seastore/extent_reader.cc b/src/crimson/os/seastore/extent_reader.cc
@@ -7,7 +7,7 @@
 
 namespace {
   seastar::logger& logger() {
-    return crimson::get_logger(ceph_subsys_seastore);
+    return crimson::get_logger(ceph_subsys_seastore_tm);
   }
 }
 

diff --git a/src/crimson/os/seastore/journal.cc b/src/crimson/os/seastore/journal.cc
@@ -13,7 +13,7 @@
 
 namespace {
   seastar::logger& logger() {
-    return crimson::get_logger(ceph_subsys_seastore);
+    return crimson::get_logger(ceph_subsys_seastore_journal);
   }
 }
 

diff --git a/src/crimson/os/seastore/lba_manager/btree/btree_lba_manager.cc b/src/crimson/os/seastore/lba_manager/btree/btree_lba_manager.cc
@@ -15,10 +15,12 @@
 
 namespace {
   seastar::logger& logger() {
-    return crimson::get_logger(ceph_subsys_seastore);
+    return crimson::get_logger(ceph_subsys_seastore_lba);
   }
 }
 
+SET_SUBSYS(seastore_lba);
+
 namespace crimson::os::seastore::lba_manager::btree {
 
 BtreeLBAManager::mkfs_ret BtreeLBAManager::mkfs(

diff --git a/src/crimson/os/seastore/lba_manager/btree/btree_lba_manager.h b/src/crimson/os/seastore/lba_manager/btree/btree_lba_manager.h
@@ -15,7 +15,6 @@
 #include "common/interval_map.h"
 #include "crimson/osd/exceptions.h"
 
-#include "crimson/os/seastore/logging.h"
 #include "crimson/os/seastore/seastore_types.h"
 #include "crimson/os/seastore/lba_manager.h"
 #include "crimson/os/seastore/cache.h"

diff --git a/src/crimson/os/seastore/lba_manager/btree/btree_range_pin.cc b/src/crimson/os/seastore/lba_manager/btree/btree_range_pin.cc
@@ -7,7 +7,7 @@
 
 namespace {
   seastar::logger& logger() {
-    return crimson::get_logger(ceph_subsys_seastore);
+    return crimson::get_logger(ceph_subsys_seastore_lba);
   }
 }
 

diff --git a/src/crimson/os/seastore/lba_manager/btree/lba_btree.cc b/src/crimson/os/seastore/lba_manager/btree/lba_btree.cc
@@ -6,6 +6,8 @@
 
 #include "crimson/os/seastore/lba_manager/btree/lba_btree.h"
 
+SET_SUBSYS(seastore_lba);
+
 namespace crimson::os::seastore::lba_manager::btree {
 
 LBABtree::mkfs_ret LBABtree::mkfs(op_context_t c)

diff --git a/src/crimson/os/seastore/lba_manager/btree/lba_btree.h b/src/crimson/os/seastore/lba_manager/btree/lba_btree.h
@@ -555,7 +555,7 @@ class LBABtree {
     mapped_space_visitor_t *visitor ///< [in] mapped space visitor
   ) {
     LOG_PREFIX(LBATree::lookup_depth_range);
-    DEBUGT("{} -> {}", c.trans, from, to);
+    SUBDEBUGT(seastore_lba, "{} -> {}", c.trans, from, to);
     return seastar::do_with(
       from,
       [c, to, visitor, &iter, &li, &ll](auto &d) {
@@ -619,7 +619,7 @@ class LBABtree {
 	    auto riter = ll(*(root_entry.node));
 	    root_entry.pos = riter->get_offset();
 	  }
-	  DEBUGT("got root, depth {}", c.trans, root.get_depth());
+	  SUBDEBUGT(seastore_lba, "got root, depth {}", c.trans, root.get_depth());
 	  return lookup_depth_range(
 	    c,
 	    iter,

diff --git a/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.cc b/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.cc
@@ -14,7 +14,7 @@
 
 namespace {
   seastar::logger& logger() {
-    return crimson::get_logger(ceph_subsys_seastore);
+    return crimson::get_logger(ceph_subsys_seastore_lba);
   }
 }
 

diff --git a/src/crimson/os/seastore/logging.h b/src/crimson/os/seastore/logging.h
@@ -7,48 +7,63 @@
 
 #include "crimson/common/log.h"
 
-#define LOGGER crimson::get_logger(ceph_subsys_seastore)
+#define SET_SUBSYS(subname_) static constexpr auto SOURCE_SUBSYS = ceph_subsys_##subname_
+#define LOCAL_LOGGER crimson::get_logger(SOURCE_SUBSYS)
+#define LOGGER(subname_) crimson::get_logger(ceph_subsys_##subname_)
 #define LOG_PREFIX(x) constexpr auto FNAME = #x
 
 #ifdef NDEBUG
 
-#define LOG(level_, MSG, ...) LOGGER.log(level_, "{}: " MSG, FNAME , ##__VA_ARGS__)
-#define LOGT(level_, MSG, t, ...) LOGGER.log(level_, "{}({}): " MSG, FNAME, (void*)&t , ##__VA_ARGS__)
+#define LOG(level_, MSG, ...) \
+  LOCAL_LOGGER.log(level_, "{}: " MSG, FNAME , ##__VA_ARGS__)
+#define LOGT(level_, MSG, t, ...) \
+  LOCAL_LOGGER.log(level_, "{}({}): " MSG, FNAME, (void*)&t , ##__VA_ARGS__)
+#define SUBLOG(subname_, level_, MSG, ...) \
+  LOGGER(subname_).log(level_, "{}: " MSG, FNAME , ##__VA_ARGS__)
+#define SUBLOGT(subname_, level_, MSG, t, ...) \
+  LOGGER(subname_).log(level_, "{}({}): " MSG, FNAME, (void*)&t , ##__VA_ARGS__)
+
+#else
+
+// do compile-time format string validation
+using namespace fmt::literals;
+template<seastar::log_level lv>
+void _LOG(seastar::logger& logger, std::string_view info) {
+  logger.log(lv, info.data());
+}
+
+#define LOG(level_, MSG, ...) \
+  _LOG<level_>(LOCAL_LOGGER, "{}: " MSG ## _format(FNAME , ##__VA_ARGS__))
+#define LOGT(level_, MSG, t_, ...) \
+  _LOG<level_>(LOCAL_LOGGER, "{}({}): " MSG ## _format(FNAME, (void*)&t_ , ##__VA_ARGS__))
+#define SUBLOG(subname_, level_, MSG, ...) \
+  _LOG<level_>(LOGGER(subname_), "{}: " MSG ## _format(FNAME , ##__VA_ARGS__))
+#define SUBLOGT(subname_, level_, MSG, t_, ...) \
+  _LOG<level_>(LOGGER(subname_), "{}({}): " MSG ## _format(FNAME, (void*)&t_ , ##__VA_ARGS__))
+
+#endif
 
 #define TRACE(...) LOG(seastar::log_level::trace, __VA_ARGS__)
 #define TRACET(...) LOGT(seastar::log_level::trace, __VA_ARGS__)
+#define SUBTRACE(subname_, ...) SUBLOG(subname_, seastar::log_level::trace, __VA_ARGS__)
+#define SUBTRACET(subname_, ...) SUBLOGT(subname_, seastar::log_level::trace, __VA_ARGS__)
 
 #define DEBUG(...) LOG(seastar::log_level::debug, __VA_ARGS__)
 #define DEBUGT(...) LOGT(seastar::log_level::debug, __VA_ARGS__)
+#define SUBDEBUG(subname_, ...) SUBLOG(subname_, seastar::log_level::debug, __VA_ARGS__)
+#define SUBDEBUGT(subname_, ...) SUBLOGT(subname_, seastar::log_level::debug, __VA_ARGS__)
 
 #define INFO(...) LOG(seastar::log_level::info, __VA_ARGS__)
 #define INFOT(...) LOGT(seastar::log_level::info, __VA_ARGS__)
+#define SUBINFO(subname_, ...) SUBLOG(subname_, seastar::log_level::info, __VA_ARGS__)
+#define SUBINFOT(subname_, ...) SUBLOGT(subname_, seastar::log_level::info, __VA_ARGS__)
 
 #define WARN(...) LOG(seastar::log_level::warn, __VA_ARGS__)
 #define WARNT(...) LOGT(seastar::log_level::warn, __VA_ARGS__)
+#define SUBWARN(subname_, ...) SUBLOG(subname_, seastar::log_level::warn, __VA_ARGS__)
+#define SUBWARNT(subname_, ...) SUBLOGT(subname_, seastar::log_level::warn, __VA_ARGS__)
 
 #define ERROR(...) LOG(seastar::log_level::error, __VA_ARGS__)
 #define ERRORT(...) LOGT(seastar::log_level::error, __VA_ARGS__)
-
-#else
-// do compile-time format string validation
-using namespace fmt::literals;
-template<seastar::log_level lv>
-void LOG(std::string_view info) {
-  crimson::get_logger(ceph_subsys_seastore).log(lv, info.data());
-}
-#define TRACE(MSG_, ...) LOG<seastar::log_level::trace>("{}: " MSG_ ## _format(FNAME , ##__VA_ARGS__))
-#define TRACET(MSG_, t_, ...) LOG<seastar::log_level::trace>("{}({}): " MSG_ ## _format(FNAME, (void*)&t_ , ##__VA_ARGS__))
-
-#define DEBUG(MSG_, ...) LOG<seastar::log_level::debug>("{}: " MSG_ ## _format(FNAME , ##__VA_ARGS__))
-#define DEBUGT(MSG_, t_, ...) LOG<seastar::log_level::debug>("{}({}): " MSG_ ## _format(FNAME, (void*)&t_ , ##__VA_ARGS__))
-
-#define INFO(MSG_, ...) LOG<seastar::log_level::info>("{}: " MSG_ ## _format(FNAME , ##__VA_ARGS__))
-#define INFOT(MSG_, t_, ...) LOG<seastar::log_level::info>("{}({}): " MSG_ ## _format(FNAME, (void*)&t_ , ##__VA_ARGS__))
-
-#define WARN(MSG_, ...) LOG<seastar::log_level::warn>("{}: " MSG_ ## _format(FNAME , ##__VA_ARGS__))
-#define WARNT(MSG_, t_, ...) LOG<seastar::log_level::warn>("{}({}): " MSG_ ## _format(FNAME, (void*)&t_ , ##__VA_ARGS__))
-
-#define ERROR(MSG_, ...) LOG<seastar::log_level::error>("{}: " MSG_ ## _format(FNAME , ##__VA_ARGS__))
-#define ERRORT(MSG_, t_, ...) LOG<seastar::log_level::error>("{}({}): " MSG_ ## _format(FNAME, (void*)&t_ , ##__VA_ARGS__))
-#endif
+#define SUBERROR(subname_, ...) SUBLOG(subname_, seastar::log_level::error, __VA_ARGS__)
+#define SUBERRORT(subname_, ...) SUBLOGT(subname_, seastar::log_level::error, __VA_ARGS__)
diff --git a/src/crimson/os/seastore/object_data_handler.cc b/src/crimson/os/seastore/object_data_handler.cc
@@ -10,10 +10,12 @@
 
 namespace {
   seastar::logger& logger() {
-    return crimson::get_logger(ceph_subsys_seastore);
+    return crimson::get_logger(ceph_subsys_seastore_odata);
   }
 }
 
+SET_SUBSYS(seastore_odata);
+
 namespace crimson::os::seastore {
 #define assert_aligned(x) ceph_assert(((x)%ctx.tm.get_block_size()) == 0)
 

diff --git a/src/crimson/os/seastore/omap_manager/btree/btree_omap_manager.cc b/src/crimson/os/seastore/omap_manager/btree/btree_omap_manager.cc
@@ -11,7 +11,7 @@
 
 namespace {
   seastar::logger& logger() {
-    return crimson::get_logger(ceph_subsys_seastore);
+    return crimson::get_logger(ceph_subsys_seastore_omap);
   }
 }
 

diff --git a/src/crimson/os/seastore/omap_manager/btree/omap_btree_node_impl.cc b/src/crimson/os/seastore/omap_manager/btree/omap_btree_node_impl.cc
@@ -12,7 +12,7 @@
 
 namespace {
   seastar::logger& logger() {
-    return crimson::get_logger(ceph_subsys_seastore);
+    return crimson::get_logger(ceph_subsys_seastore_omap);
   }
 }
 

diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/fltree_onode_manager.cc b/src/crimson/os/seastore/onode_manager/staged-fltree/fltree_onode_manager.cc
@@ -5,6 +5,8 @@
 
 #include "crimson/os/seastore/onode_manager/staged-fltree/fltree_onode_manager.h"
 
+SET_SUBSYS(seastore_onode);
+
 namespace crimson::os::seastore::onode {
 
 FLTreeOnodeManager::contains_onode_ret FLTreeOnodeManager::contains_onode(

diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node.cc b/src/crimson/os/seastore/onode_manager/staged-fltree/node.cc
@@ -15,6 +15,8 @@
 #include "node_impl.h"
 #include "stages/node_stage_layout.h"
 
+SET_SUBSYS(seastore_onode);
+
 namespace crimson::os::seastore::onode {
 /*
  * tree_cursor_t