From 632916721b9ec64037c139aedf058581bef23cb4 Mon Sep 17 00:00:00 2001 From: Yingxin Cheng Date: Fri, 31 Dec 2021 11:48:07 +0800 Subject: [PATCH] crimson/os/seastore: differentiate loggers in seastore To enable fine-grain logger control for easier bug triage. See common/subsys.h for the new classifications. Signed-off-by: Yingxin Cheng --- src/common/subsys.h | 11 ++- src/crimson/os/seastore/cache.cc | 2 + src/crimson/os/seastore/cache.h | 20 ++-- src/crimson/os/seastore/cached_extent.cc | 2 +- .../os/seastore/extent_placement_manager.cc | 4 +- .../os/seastore/extent_placement_manager.h | 8 +- src/crimson/os/seastore/extent_reader.cc | 2 +- src/crimson/os/seastore/journal.cc | 2 +- .../lba_manager/btree/btree_lba_manager.cc | 4 +- .../lba_manager/btree/btree_range_pin.cc | 2 +- .../seastore/lba_manager/btree/lba_btree.cc | 2 + .../os/seastore/lba_manager/btree/lba_btree.h | 4 +- .../lba_manager/btree/lba_btree_node.cc | 2 +- src/crimson/os/seastore/logging.h | 30 +++++- .../os/seastore/object_data_handler.cc | 4 +- .../omap_manager/btree/btree_omap_manager.cc | 2 +- .../btree/omap_btree_node_impl.cc | 2 +- .../staged-fltree/fltree_onode_manager.cc | 2 + .../onode_manager/staged-fltree/node.cc | 2 + .../staged-fltree/node_extent_accessor.h | 73 ++++++++------ .../staged-fltree/node_extent_manager/dummy.h | 27 ++--- .../node_extent_manager/seastore.cc | 2 + .../node_extent_manager/seastore.h | 43 ++++---- .../onode_manager/staged-fltree/node_layout.h | 98 ++++++++++--------- .../onode_manager/staged-fltree/tree.h | 12 +-- .../random_block_manager/nvme_manager.cc | 2 +- .../random_block_manager/nvmedevice.cc | 2 +- src/crimson/os/seastore/seastore.cc | 2 + src/crimson/os/seastore/seastore_types.cc | 2 +- src/crimson/os/seastore/segment_cleaner.cc | 4 +- src/crimson/os/seastore/segment_cleaner.h | 18 ++-- src/crimson/os/seastore/segment_manager.cc | 2 +- .../os/seastore/segment_manager/block.cc | 2 +- .../os/seastore/segment_manager/ephemeral.cc | 2 +- .../os/seastore/segment_manager/zns.cc | 2 +- src/crimson/os/seastore/transaction.h | 16 +-- .../os/seastore/transaction_manager.cc | 2 + src/crimson/os/seastore/transaction_manager.h | 24 ++--- 38 files changed, 260 insertions(+), 182 deletions(-) diff --git a/src/common/subsys.h b/src/common/subsys.h index 6ba0da58514..70557fdc672 100644 --- 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 index 28138643756..adb40e51a84 100644 --- a/src/crimson/os/seastore/cache.cc +++ b/src/crimson/os/seastore/cache.cc @@ -19,6 +19,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 index 08f2b6b350c..e28878b5582 100644 --- a/src/crimson/os/seastore/cache.h +++ b/src/crimson/os/seastore/cache.h @@ -111,8 +111,8 @@ public: 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 @@ public: ++(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 @@ public: 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,7 +268,7 @@ public: 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< @@ -276,7 +276,7 @@ public: } // 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); @@ -308,7 +308,7 @@ public: 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>( @@ -322,12 +322,12 @@ public: ).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>(); } else { - DEBUGT( + SUBDEBUGT(seastore_cache, "Read extent at offset {} in cache: {}", t, offset, *ref); t.add_to_read_set(ref); @@ -413,7 +413,7 @@ private: ).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(); diff --git a/src/crimson/os/seastore/cached_extent.cc b/src/crimson/os/seastore/cached_extent.cc index fbfd8dad049..08c94249604 100644 --- 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 index c0e6d0a38c8..c4d5d285668 100644 --- 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 index 506edde8147..e3269538c2e 100644 --- a/src/crimson/os/seastore/extent_placement_manager.h +++ b/src/crimson/os/seastore/extent_placement_manager.h @@ -255,7 +255,7 @@ public: Transaction& t, std::list& extents) final { LOG_PREFIX(SegmentedAllocator::alloc_ool_extents_paddr); - DEBUGT("start", t); + SUBDEBUGT(seastore_tm, "start", t); return seastar::do_with( std::map>(), [this, extents=std::move(extents), &t](auto& alloc_map) { @@ -348,7 +348,7 @@ public: 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>(), [this, &t](auto& alloc_map) { @@ -368,7 +368,7 @@ public: 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 @@ public: 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 index dd245d5eaf7..33f30d1f459 100644 --- 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 index 6f0a0559552..33257b99f3d 100644 --- 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 index 11d23f8bfc0..143f71af1a5 100644 --- 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_range_pin.cc b/src/crimson/os/seastore/lba_manager/btree/btree_range_pin.cc index a5416e17486..ffd0462682a 100644 --- 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 index b933f7fe986..4bfb5edf474 100644 --- 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 index 96b92c73d31..ab604e302ae 100644 --- 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 @@ private: 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 @@ private: 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 index 8fadc00d8d8..21154fe375b 100644 --- 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 index a0c8b8e45ce..7153850eca3 100644 --- a/src/crimson/os/seastore/logging.h +++ b/src/crimson/os/seastore/logging.h @@ -7,15 +7,21 @@ #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__) + LOCAL_LOGGER.log(level_, "{}: " MSG, FNAME , ##__VA_ARGS__) #define LOGT(level_, MSG, t, ...) \ - LOGGER.log(level_, "{}({}): " MSG, FNAME, (void*)&t , ##__VA_ARGS__) + 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 @@ -27,23 +33,37 @@ void _LOG(seastar::logger& logger, std::string_view info) { } #define LOG(level_, MSG, ...) \ - _LOG(LOGGER, "{}: " MSG ## _format(FNAME , ##__VA_ARGS__)) + _LOG(LOCAL_LOGGER, "{}: " MSG ## _format(FNAME , ##__VA_ARGS__)) #define LOGT(level_, MSG, t_, ...) \ - _LOG(LOGGER, "{}({}): " MSG ## _format(FNAME, (void*)&t_ , ##__VA_ARGS__)) + _LOG(LOCAL_LOGGER, "{}({}): " MSG ## _format(FNAME, (void*)&t_ , ##__VA_ARGS__)) +#define SUBLOG(subname_, level_, MSG, ...) \ + _LOG(LOGGER(subname_), "{}: " MSG ## _format(FNAME , ##__VA_ARGS__)) +#define SUBLOGT(subname_, level_, MSG, t_, ...) \ + _LOG(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__) +#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 index 2b91cf4835b..9bc90405c9c 100644 --- 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 index 8753ad40370..e666879b1e1 100644 --- 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 index dc1294dc371..64f72b1592f 100644 --- 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 index 2865cba4b97..33cf10e3588 100644 --- 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 index 35180cc9df1..0236a3c6bbe 100644 --- 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 diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_accessor.h b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_accessor.h index bec13d2b918..379583523d8 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_accessor.h +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_accessor.h @@ -121,7 +121,7 @@ class DeltaRecorderT final: public DeltaRecorder { ceph::decode(op, delta); switch (op) { case node_delta_op_t::INSERT: { - DEBUG("decoding INSERT ..."); + SUBDEBUG(seastore_onode, "decoding INSERT ..."); auto key = key_hobj_t::decode(delta); auto value = decode_value(delta); auto insert_pos = position_t::decode(delta); @@ -129,23 +129,24 @@ class DeltaRecorderT final: public DeltaRecorder { ceph::decode(insert_stage, delta); node_offset_t insert_size; ceph::decode(insert_size, delta); - DEBUG("apply {}, {}, insert_pos({}), insert_stage={}, " - "insert_size={}B ...", - key, value, insert_pos, insert_stage, insert_size); + SUBDEBUG(seastore_onode, + "apply {}, {}, insert_pos({}), insert_stage={}, " + "insert_size={}B ...", + key, value, insert_pos, insert_stage, insert_size); layout_t::template insert( mut, stage, key, value, insert_pos, insert_stage, insert_size); break; } case node_delta_op_t::SPLIT: { - DEBUG("decoding SPLIT ..."); + SUBDEBUG(seastore_onode, "decoding SPLIT ..."); auto split_at = StagedIterator::decode( mut.get_read(), mut.get_length(), delta); - DEBUG("apply split_at={} ...", split_at); + SUBDEBUG(seastore_onode, "apply split_at={} ...", split_at); layout_t::split(mut, stage, split_at); break; } case node_delta_op_t::SPLIT_INSERT: { - DEBUG("decoding SPLIT_INSERT ..."); + SUBDEBUG(seastore_onode, "decoding SPLIT_INSERT ..."); auto split_at = StagedIterator::decode( mut.get_read(), mut.get_length(), delta); auto key = key_hobj_t::decode(delta); @@ -155,45 +156,47 @@ class DeltaRecorderT final: public DeltaRecorder { ceph::decode(insert_stage, delta); node_offset_t insert_size; ceph::decode(insert_size, delta); - DEBUG("apply split_at={}, {}, {}, insert_pos({}), insert_stage={}, " - "insert_size={}B ...", - split_at, key, value, insert_pos, insert_stage, insert_size); + SUBDEBUG(seastore_onode, + "apply split_at={}, {}, {}, insert_pos({}), insert_stage={}, " + "insert_size={}B ...", + split_at, key, value, insert_pos, insert_stage, insert_size); layout_t::template split_insert( mut, stage, split_at, key, value, insert_pos, insert_stage, insert_size); break; } case node_delta_op_t::UPDATE_CHILD_ADDR: { - DEBUG("decoding UPDATE_CHILD_ADDR ..."); + SUBDEBUG(seastore_onode, "decoding UPDATE_CHILD_ADDR ..."); laddr_t new_addr; ceph::decode(new_addr, delta); node_offset_t update_offset; ceph::decode(update_offset, delta); auto p_addr = reinterpret_cast( mut.get_write() + update_offset); - DEBUG("apply {:#x} to offset {:#x} ...", - new_addr, update_offset); + SUBDEBUG(seastore_onode, + "apply {:#x} to offset {:#x} ...", + new_addr, update_offset); layout_t::update_child_addr(mut, new_addr, p_addr); break; } case node_delta_op_t::ERASE: { - DEBUG("decoding ERASE ..."); + SUBDEBUG(seastore_onode, "decoding ERASE ..."); auto erase_pos = position_t::decode(delta); - DEBUG("apply erase_pos({}) ...", erase_pos); + SUBDEBUG(seastore_onode, "apply erase_pos({}) ...", erase_pos); layout_t::erase(mut, stage, erase_pos); break; } case node_delta_op_t::MAKE_TAIL: { - DEBUG("decoded MAKE_TAIL, apply ..."); + SUBDEBUG(seastore_onode, "decoded MAKE_TAIL, apply ..."); layout_t::make_tail(mut, stage); break; } case node_delta_op_t::SUBOP_UPDATE_VALUE: { - DEBUG("decoding SUBOP_UPDATE_VALUE ..."); + SUBDEBUG(seastore_onode, "decoding SUBOP_UPDATE_VALUE ..."); node_offset_t value_header_offset; ceph::decode(value_header_offset, delta); auto p_header = mut.get_read() + value_header_offset; auto p_header_ = reinterpret_cast(p_header); - DEBUG("update {} at {:#x} ...", *p_header_, value_header_offset); + SUBDEBUG(seastore_onode, "update {} at {:#x} ...", *p_header_, value_header_offset); auto payload_mut = p_header_->get_payload_mutable(mut); auto value_addr = node.get_laddr() + payload_mut.get_node_offset(); get_value_replayer(p_header_->magic)->apply_value_delta( @@ -201,13 +204,15 @@ class DeltaRecorderT final: public DeltaRecorder { break; } default: - ERROR("got unknown op {} when replay {}", - op, node); + SUBERROR(seastore_onode, + "got unknown op {} when replay {}", + op, node); ceph_abort("fatal error"); } } catch (buffer::error& e) { - ERROR("got decode error {} when replay {}", - e, node); + SUBERROR(seastore_onode, + "got decode error {} when replay {}", + e, node); ceph_abort("fatal error"); } } @@ -520,13 +525,15 @@ class NodeExtentAccessorT { eagain_iertr::pass_further{}, crimson::ct_error::input_output_error::handle( [FNAME, c, alloc_size, l_to_discard = extent->get_laddr()] { - ERRORT("EIO during allocate -- node_size={}, to_discard={:x}", - c.t, alloc_size, l_to_discard); + SUBERRORT(seastore_onode, + "EIO during allocate -- node_size={}, to_discard={:x}", + c.t, alloc_size, l_to_discard); ceph_abort("fatal error"); }) ).si_then([this, c, FNAME] (auto fresh_extent) { - DEBUGT("update addr from {:#x} to {:#x} ...", - c.t, extent->get_laddr(), fresh_extent->get_laddr()); + SUBDEBUGT(seastore_onode, + "update addr from {:#x} to {:#x} ...", + c.t, extent->get_laddr(), fresh_extent->get_laddr()); assert(fresh_extent); assert(fresh_extent->is_initial_pending()); assert(fresh_extent->get_recorder() == nullptr); @@ -548,15 +555,17 @@ class NodeExtentAccessorT { crimson::ct_error::input_output_error::handle( [FNAME, c, l_to_discard = to_discard->get_laddr(), l_fresh = fresh_extent->get_laddr()] { - ERRORT("EIO during retire -- to_disgard={:x}, fresh={:x}", - c.t, l_to_discard, l_fresh); + SUBERRORT(seastore_onode, + "EIO during retire -- to_disgard={:x}, fresh={:x}", + c.t, l_to_discard, l_fresh); ceph_abort("fatal error"); }), crimson::ct_error::enoent::handle( [FNAME, c, l_to_discard = to_discard->get_laddr(), l_fresh = fresh_extent->get_laddr()] { - ERRORT("ENOENT during retire -- to_disgard={:x}, fresh={:x}", - c.t, l_to_discard, l_fresh); + SUBERRORT(seastore_onode, + "ENOENT during retire -- to_disgard={:x}, fresh={:x}", + c.t, l_to_discard, l_fresh); ceph_abort("fatal error"); }) ); @@ -575,12 +584,12 @@ class NodeExtentAccessorT { eagain_iertr::pass_further{}, crimson::ct_error::input_output_error::handle( [FNAME, c, addr] { - ERRORT("EIO -- addr={:x}", c.t, addr); + SUBERRORT(seastore_onode, "EIO -- addr={:x}", c.t, addr); ceph_abort("fatal error"); }), crimson::ct_error::enoent::handle( [FNAME, c, addr] { - ERRORT("ENOENT -- addr={:x}", c.t, addr); + SUBERRORT(seastore_onode, "ENOENT -- addr={:x}", c.t, addr); ceph_abort("fatal error"); }) #ifndef NDEBUG diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/dummy.h b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/dummy.h index 272e0dbb369..52aee6a75fc 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/dummy.h +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/dummy.h @@ -28,7 +28,7 @@ class DummySuper final: public Super { laddr_t get_root_laddr() const override { return *p_root_laddr; } void write_root_laddr(context_t c, laddr_t addr) override { LOG_PREFIX(OTree::Dummy); - DEBUGT("update root {:#x} ...", c.t, addr); + SUBDEBUGT(seastore_onode, "update root {:#x} ...", c.t, addr); *p_root_laddr = addr; } private: @@ -77,7 +77,7 @@ class DummyNodeExtentManager final: public NodeExtentManager { read_iertr::future read_extent( Transaction& t, laddr_t addr) override { - TRACET("reading at {:#x} ...", t, addr); + SUBTRACET(seastore_onode, "reading at {:#x} ...", t, addr); if constexpr (SYNC) { return read_extent_sync(t, addr); } else { @@ -90,7 +90,7 @@ class DummyNodeExtentManager final: public NodeExtentManager { alloc_iertr::future alloc_extent( Transaction& t, laddr_t hint, extent_len_t len) override { - TRACET("allocating {}B with hint {:#x} ...", t, len, hint); + SUBTRACET(seastore_onode, "allocating {}B with hint {:#x} ...", t, len, hint); if constexpr (SYNC) { return alloc_extent_sync(t, len); } else { @@ -103,8 +103,9 @@ class DummyNodeExtentManager final: public NodeExtentManager { retire_iertr::future<> retire_extent( Transaction& t, NodeExtentRef extent) override { - TRACET("retiring {}B at {:#x} -- {} ...", - t, extent->get_length(), extent->get_laddr(), *extent); + SUBTRACET(seastore_onode, + "retiring {}B at {:#x} -- {} ...", + t, extent->get_length(), extent->get_laddr(), *extent); if constexpr (SYNC) { return retire_extent_sync(t, extent); } else { @@ -117,7 +118,7 @@ class DummyNodeExtentManager final: public NodeExtentManager { getsuper_iertr::future get_super( Transaction& t, RootNodeTracker& tracker) override { - TRACET("get root ...", t); + SUBTRACET(seastore_onode, "get root ...", t); if constexpr (SYNC) { return get_super_sync(t, tracker); } else { @@ -138,8 +139,9 @@ class DummyNodeExtentManager final: public NodeExtentManager { auto iter = allocate_map.find(addr); assert(iter != allocate_map.end()); auto extent = iter->second; - TRACET("read {}B at {:#x} -- {}", - t, extent->get_length(), extent->get_laddr(), *extent); + SUBTRACET(seastore_onode, + "read {}B at {:#x} -- {}", + t, extent->get_length(), extent->get_laddr(), *extent); assert(extent->get_laddr() == addr); return read_iertr::make_ready_future(extent); } @@ -154,8 +156,9 @@ class DummyNodeExtentManager final: public NodeExtentManager { extent->set_laddr(addr); assert(allocate_map.find(extent->get_laddr()) == allocate_map.end()); allocate_map.insert({extent->get_laddr(), extent}); - DEBUGT("allocated {}B at {:#x} -- {}", - t, extent->get_length(), extent->get_laddr(), *extent); + SUBDEBUGT(seastore_onode, + "allocated {}B at {:#x} -- {}", + t, extent->get_length(), extent->get_laddr(), *extent); assert(extent->get_length() == len); return alloc_iertr::make_ready_future(extent); } @@ -169,13 +172,13 @@ class DummyNodeExtentManager final: public NodeExtentManager { auto iter = allocate_map.find(addr); assert(iter != allocate_map.end()); allocate_map.erase(iter); - DEBUGT("retired {}B at {:#x}", t, len, addr); + SUBDEBUGT(seastore_onode, "retired {}B at {:#x}", t, len, addr); return retire_iertr::now(); } getsuper_iertr::future get_super_sync( Transaction& t, RootNodeTracker& tracker) { - TRACET("got root {:#x}", t, root_laddr); + SUBTRACET(seastore_onode, "got root {:#x}", t, root_laddr); return getsuper_iertr::make_ready_future( Super::URef(new DummySuper(t, tracker, &root_laddr))); } diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.cc b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.cc index 208c9174b4d..3b52c5dc069 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.cc +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.cc @@ -10,6 +10,8 @@ namespace { LOG_PREFIX(OTree::Seastore); } +SET_SUBSYS(seastore_onode); + namespace crimson::os::seastore::onode { static DeltaRecorderURef create_replay_recorder( diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h index 432890922f8..1e151118fe7 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h @@ -30,7 +30,7 @@ class SeastoreSuper final: public Super { } void write_root_laddr(context_t c, laddr_t addr) override { LOG_PREFIX(OTree::Seastore); - DEBUGT("update root {:#x} ...", c.t, addr); + SUBDEBUGT(seastore_onode, "update root {:#x} ...", c.t, addr); root_addr = addr; tm.write_onode_root(c.t, addr); } @@ -102,18 +102,19 @@ class SeastoreNodeExtentManager final: public TransactionManagerHandle { read_iertr::future read_extent( Transaction& t, laddr_t addr) override { - TRACET("reading at {:#x} ...", t, addr); + SUBTRACET(seastore_onode, "reading at {:#x} ...", t, addr); if constexpr (INJECT_EAGAIN) { if (trigger_eagain()) { - DEBUGT("reading at {:#x}: trigger eagain", t, addr); + SUBDEBUGT(seastore_onode, "reading at {:#x}: trigger eagain", t, addr); t.test_set_conflict(); return read_iertr::make_ready_future(); } } return tm.read_extent(t, addr ).si_then([addr, &t](auto&& e) -> read_iertr::future { - TRACET("read {}B at {:#x} -- {}", - t, e->get_length(), e->get_laddr(), *e); + SUBTRACET(seastore_onode, + "read {}B at {:#x} -- {}", + t, e->get_length(), e->get_laddr(), *e); assert(e->get_laddr() == addr); std::ignore = addr; return read_iertr::make_ready_future(e); @@ -122,21 +123,23 @@ class SeastoreNodeExtentManager final: public TransactionManagerHandle { alloc_iertr::future alloc_extent( Transaction& t, laddr_t hint, extent_len_t len) override { - TRACET("allocating {}B with hint {:#x} ...", t, len, hint); + SUBTRACET(seastore_onode, "allocating {}B with hint {:#x} ...", t, len, hint); if constexpr (INJECT_EAGAIN) { if (trigger_eagain()) { - DEBUGT("allocating {}B: trigger eagain", t, len); + SUBDEBUGT(seastore_onode, "allocating {}B: trigger eagain", t, len); t.test_set_conflict(); return alloc_iertr::make_ready_future(); } } return tm.alloc_extent(t, hint, len ).si_then([len, &t](auto extent) { - DEBUGT("allocated {}B at {:#x} -- {}", - t, extent->get_length(), extent->get_laddr(), *extent); + SUBDEBUGT(seastore_onode, + "allocated {}B at {:#x} -- {}", + t, extent->get_length(), extent->get_laddr(), *extent); if (!extent->is_initial_pending()) { - ERRORT("allocated {}B but got invalid extent: {}", - t, len, *extent); + SUBERRORT(seastore_onode, + "allocated {}B but got invalid extent: {}", + t, len, *extent); ceph_abort("fatal error"); } assert(extent->get_length() == len); @@ -150,34 +153,36 @@ class SeastoreNodeExtentManager final: public TransactionManagerHandle { LogicalCachedExtentRef extent = _extent; auto addr = extent->get_laddr(); auto len = extent->get_length(); - DEBUGT("retiring {}B at {:#x} -- {} ...", - t, len, addr, *extent); + SUBDEBUGT(seastore_onode, + "retiring {}B at {:#x} -- {} ...", + t, len, addr, *extent); if constexpr (INJECT_EAGAIN) { if (trigger_eagain()) { - DEBUGT("retiring {}B at {:#x} -- {} : trigger eagain", - t, len, addr, *extent); + SUBDEBUGT(seastore_onode, + "retiring {}B at {:#x} -- {} : trigger eagain", + t, len, addr, *extent); t.test_set_conflict(); return retire_iertr::now(); } } return tm.dec_ref(t, extent).si_then([addr, len, &t] (unsigned cnt) { assert(cnt == 0); - TRACET("retired {}B at {:#x} ...", t, len, addr); + SUBTRACET(seastore_onode, "retired {}B at {:#x} ...", t, len, addr); }); } getsuper_iertr::future get_super( Transaction& t, RootNodeTracker& tracker) override { - TRACET("get root ...", t); + SUBTRACET(seastore_onode, "get root ...", t); if constexpr (INJECT_EAGAIN) { if (trigger_eagain()) { - DEBUGT("get root: trigger eagain", t); + SUBDEBUGT(seastore_onode, "get root: trigger eagain", t); t.test_set_conflict(); return getsuper_iertr::make_ready_future(); } } return tm.read_onode_root(t).si_then([this, &t, &tracker](auto root_addr) { - TRACET("got root {:#x}", t, root_addr); + SUBTRACET(seastore_onode, "got root {:#x}", t, root_addr); return Super::URef(new SeastoreSuper(t, tracker, root_addr, tm)); }); } diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout.h b/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout.h index 436f883700a..ffc668e2ccf 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout.h +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout.h @@ -79,8 +79,9 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { eagain_iertr::pass_further{}, crimson::ct_error::input_output_error::handle( [FNAME, c, extent_size, is_level_tail, level] { - ERRORT("EIO -- extent_size={}, is_level_tail={}, level={}", - c.t, extent_size, is_level_tail, level); + SUBERRORT(seastore_onode, + "EIO -- extent_size={}, is_level_tail={}, level={}", + c.t, extent_size, is_level_tail, level); ceph_abort("fatal error"); }) ).si_then([is_level_tail, level](auto extent) { @@ -181,18 +182,18 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { std::tuple erase(const search_position_t& pos) override { LOG_PREFIX(OTree::Layout::erase); - DEBUG("begin at erase_pos({}) ...", pos); - if (unlikely(LOGGER.is_enabled(seastar::log_level::trace))) { + SUBDEBUG(seastore_onode, "begin at erase_pos({}) ...", pos); + if (unlikely(LOGGER(seastore_onode).is_enabled(seastar::log_level::trace))) { std::ostringstream sos; dump(sos); - TRACE("-- dump\n{}", sos.str()); + SUBTRACE(seastore_onode, "-- dump\n{}", sos.str()); } auto [stage, next_or_last_pos] = extent.erase_replayable(cast_down(pos)); - DEBUG("done at erase_stage={}, n/l_pos({})", stage, next_or_last_pos); - if (unlikely(LOGGER.is_enabled(seastar::log_level::trace))) { + SUBDEBUG(seastore_onode, "done at erase_stage={}, n/l_pos({})", stage, next_or_last_pos); + if (unlikely(LOGGER(seastore_onode).is_enabled(seastar::log_level::trace))) { std::ostringstream sos; dump(sos); - TRACE("-- dump\n{}", sos.str()); + SUBTRACE(seastore_onode, "-- dump\n{}", sos.str()); } #ifndef NDEBUG if (!is_keys_empty()) { @@ -247,16 +248,16 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { auto& left_node_stage = extent.read(); auto& right_node = dynamic_cast(_right_node); auto& right_node_stage = right_node.extent.read(); - if (unlikely(LOGGER.is_enabled(seastar::log_level::debug))) { + if (unlikely(LOGGER(seastore_onode).is_enabled(seastar::log_level::debug))) { { std::ostringstream sos; dump(sos); - DEBUG("-- left node dump\n{}", sos.str()); + SUBDEBUG(seastore_onode, "-- left node dump\n{}", sos.str()); } { std::ostringstream sos; right_node.dump(sos); - DEBUG("-- right node dump\n{}", sos.str()); + SUBDEBUG(seastore_onode, "-- right node dump\n{}", sos.str()); } } @@ -296,10 +297,10 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { left_appender.wrap(); } - if (unlikely(LOGGER.is_enabled(seastar::log_level::debug))) { + if (unlikely(LOGGER(seastore_onode).is_enabled(seastar::log_level::debug))) { std::ostringstream sos; dump(sos); - DEBUG("-- merged node dump\n{}", sos.str()); + SUBDEBUG(seastore_onode, "-- merged node dump\n{}", sos.str()); } assert(merge_size == filled_size()); return normalize(std::move(left_last_pos)); @@ -571,21 +572,23 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { search_position_t& insert_pos, match_stage_t& insert_stage, node_offset_t& insert_size) override { LOG_PREFIX(OTree::Layout::insert); - DEBUG("begin at insert_pos({}), insert_stage={}, insert_size={}B ...", - insert_pos, insert_stage, insert_size); - if (unlikely(LOGGER.is_enabled(seastar::log_level::trace))) { + SUBDEBUG(seastore_onode, + "begin at insert_pos({}), insert_stage={}, insert_size={}B ...", + insert_pos, insert_stage, insert_size); + if (unlikely(LOGGER(seastore_onode).is_enabled(seastar::log_level::trace))) { std::ostringstream sos; dump(sos); - TRACE("-- dump\n{}", sos.str()); + SUBTRACE(seastore_onode, "-- dump\n{}", sos.str()); } auto ret = extent.template insert_replayable( key, value, cast_down(insert_pos), insert_stage, insert_size); - DEBUG("done at insert_pos({}), insert_stage={}, insert_size={}B", - insert_pos, insert_stage, insert_size); - if (unlikely(LOGGER.is_enabled(seastar::log_level::trace))) { + SUBDEBUG(seastore_onode, + "done at insert_pos({}), insert_stage={}, insert_size={}B", + insert_pos, insert_stage, insert_size); + if (unlikely(LOGGER(seastore_onode).is_enabled(seastar::log_level::trace))) { std::ostringstream sos; dump(sos); - TRACE("-- dump\n{}", sos.str()); + SUBTRACE(seastore_onode, "-- dump\n{}", sos.str()); } validate_layout(); #ifndef NDEBUG @@ -605,12 +608,13 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { assert(_right_impl.node_type() == NODE_TYPE); assert(_right_impl.field_type() == FIELD_TYPE); auto& right_impl = dynamic_cast(_right_impl); - INFO("begin at insert_pos({}), insert_stage={}, insert_size={}B ...", - _insert_pos, insert_stage, insert_size); - if (unlikely(LOGGER.is_enabled(seastar::log_level::debug))) { + SUBINFO(seastore_onode, + "begin at insert_pos({}), insert_stage={}, insert_size={}B ...", + _insert_pos, insert_stage, insert_size); + if (unlikely(LOGGER(seastore_onode).is_enabled(seastar::log_level::debug))) { std::ostringstream sos; dump(sos); - DEBUG("-- dump\n{}", sos.str()); + SUBDEBUG(seastore_onode, "-- dump\n{}", sos.str()); } #ifdef UNIT_TESTS_BUILT auto insert_stage_pre = insert_stage; @@ -709,10 +713,11 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { split_size, 0, target_split_size, insert_pos, insert_stage, insert_size, _is_insert_left, split_at); is_insert_left = *_is_insert_left; - DEBUG("-- located split_at({}), insert_pos({}), is_insert_left={}, " - "split_size={}B(target={}B, current={}B)", - split_at, insert_pos, is_insert_left, - split_size, target_split_size, filled_size()); + SUBDEBUG(seastore_onode, + "-- located split_at({}), insert_pos({}), is_insert_left={}, " + "split_size={}B(target={}B, current={}B)", + split_at, insert_pos, is_insert_left, + split_size, target_split_size, filled_size()); // split_size can be larger than target_split_size in strategy B // assert(split_size <= target_split_size); if (locate_nxt) { @@ -732,9 +737,10 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { // right node: append [start(append_at), insert_pos) STAGE_T::template append_until( append_at, right_appender, insert_pos, insert_stage); - DEBUG("-- right appended until " - "insert_pos({}), insert_stage={}, insert/append the rest ...", - insert_pos, insert_stage); + SUBDEBUG(seastore_onode, + "-- right appended until " + "insert_pos({}), insert_stage={}, insert/append the rest ...", + insert_pos, insert_stage); // right node: append [insert_pos(key, value)] bool is_front_insert = (insert_pos == position_t::begin()); [[maybe_unused]] bool is_end = STAGE_T::template append_insert( @@ -742,7 +748,7 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { is_front_insert, insert_stage, p_value); assert(append_at.is_end() == is_end); } else { - DEBUG("-- right appending ..."); + SUBDEBUG(seastore_onode, "-- right appending ..."); } // right node: append (insert_pos, end) @@ -751,17 +757,18 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { append_at, right_appender, pos_end, STAGE); assert(append_at.is_end()); right_appender.wrap(); - if (unlikely(LOGGER.is_enabled(seastar::log_level::debug))) { + if (unlikely(LOGGER(seastore_onode).is_enabled(seastar::log_level::debug))) { std::ostringstream sos; right_impl.dump(sos); - DEBUG("-- right node dump\n{}", sos.str()); + SUBDEBUG(seastore_onode, "-- right node dump\n{}", sos.str()); } right_impl.validate_layout(); // mutate left node if (is_insert_left) { - DEBUG("-- left trim/insert at insert_pos({}), insert_stage={} ...", - insert_pos, insert_stage); + SUBDEBUG(seastore_onode, + "-- left trim/insert at insert_pos({}), insert_stage={} ...", + insert_pos, insert_stage); p_value = extent.template split_insert_replayable( split_at, key, value, insert_pos, insert_stage, insert_size); #ifndef NDEBUG @@ -770,7 +777,7 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { assert(index.compare_to(key) == MatchKindCMP::EQ); #endif } else { - DEBUG("-- left trim ..."); + SUBDEBUG(seastore_onode, "-- left trim ..."); #ifndef NDEBUG full_key_t index; right_impl.get_slot(_insert_pos, &index, nullptr); @@ -782,19 +789,20 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { // is_level_tail of left is changed by split/split_insert build_name(); } - if (unlikely(LOGGER.is_enabled(seastar::log_level::debug))) { + if (unlikely(LOGGER(seastore_onode).is_enabled(seastar::log_level::debug))) { std::ostringstream sos; dump(sos); - DEBUG("-- left node dump\n{}", sos.str()); + SUBDEBUG(seastore_onode, "-- left node dump\n{}", sos.str()); } validate_layout(); assert(p_value); auto split_pos = normalize(split_at.get_pos()); - INFO("done at insert_pos({}), insert_stage={}, insert_size={}B, " - "split_at({}), is_insert_left={}, split_size={}B(target={}B)", - _insert_pos, insert_stage, insert_size, split_pos, - is_insert_left, split_size, target_split_size); + SUBINFO(seastore_onode, + "done at insert_pos({}), insert_stage={}, insert_size={}B, " + "split_at({}), is_insert_left={}, split_size={}B(target={}B)", + _insert_pos, insert_stage, insert_size, split_pos, + is_insert_left, split_size, target_split_size); assert(split_size == filled_size()); #ifdef UNIT_TESTS_BUILT @@ -837,7 +845,7 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { const search_position_t& pos, laddr_t dst, laddr_t src) override { if constexpr (NODE_TYPE == node_type_t::INTERNAL) { LOG_PREFIX(OTree::Layout::replace_child_addr); - DEBUG("update from {:#x} to {:#x} at pos({}) ...", src, dst, pos); + SUBDEBUG(seastore_onode, "update from {:#x} to {:#x} at pos({}) ...", src, dst, pos); const laddr_packed_t* p_value; if (pos.is_end()) { assert(is_level_tail()); diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/tree.h b/src/crimson/os/seastore/onode_manager/staged-fltree/tree.h index 656f216bf38..8c13f4fe1bc 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/tree.h +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/tree.h @@ -248,18 +248,18 @@ class Btree { insert(Transaction& t, const ghobject_t& obj, tree_value_config_t _vconf) { LOG_PREFIX(OTree::insert); if (_vconf.payload_size > value_builder.get_max_value_payload_size()) { - ERRORT("value payload size {} too large to insert {}", - t, _vconf.payload_size, key_hobj_t{obj}); + SUBERRORT(seastore_onode, "value payload size {} too large to insert {}", + t, _vconf.payload_size, key_hobj_t{obj}); return crimson::ct_error::value_too_large::make(); } if (obj.hobj.nspace.size() > value_builder.get_max_ns_size()) { - ERRORT("namespace size {} too large to insert {}", - t, obj.hobj.nspace.size(), key_hobj_t{obj}); + SUBERRORT(seastore_onode, "namespace size {} too large to insert {}", + t, obj.hobj.nspace.size(), key_hobj_t{obj}); return crimson::ct_error::value_too_large::make(); } if (obj.hobj.oid.name.size() > value_builder.get_max_oid_size()) { - ERRORT("oid size {} too large to insert {}", - t, obj.hobj.oid.name.size(), key_hobj_t{obj}); + SUBERRORT(seastore_onode, "oid size {} too large to insert {}", + t, obj.hobj.oid.name.size(), key_hobj_t{obj}); return crimson::ct_error::value_too_large::make(); } value_config_t vconf{value_builder.get_header_magic(), _vconf.payload_size}; diff --git a/src/crimson/os/seastore/random_block_manager/nvme_manager.cc b/src/crimson/os/seastore/random_block_manager/nvme_manager.cc index 90103d37d8f..4906cad30bc 100644 --- a/src/crimson/os/seastore/random_block_manager/nvme_manager.cc +++ b/src/crimson/os/seastore/random_block_manager/nvme_manager.cc @@ -14,7 +14,7 @@ namespace { seastar::logger& logger() { - return crimson::get_logger(ceph_subsys_filestore); + return crimson::get_logger(ceph_subsys_seastore_tm); } } diff --git a/src/crimson/os/seastore/random_block_manager/nvmedevice.cc b/src/crimson/os/seastore/random_block_manager/nvmedevice.cc index 84b1353d4b9..ca829e6e575 100644 --- a/src/crimson/os/seastore/random_block_manager/nvmedevice.cc +++ b/src/crimson/os/seastore/random_block_manager/nvmedevice.cc @@ -13,7 +13,7 @@ namespace { seastar::logger& logger() { - return crimson::get_logger(ceph_subsys_filestore); + return crimson::get_logger(ceph_subsys_seastore_tm); } } diff --git a/src/crimson/os/seastore/seastore.cc b/src/crimson/os/seastore/seastore.cc index 3b31a694f75..954e0ad02de 100644 --- a/src/crimson/os/seastore/seastore.cc +++ b/src/crimson/os/seastore/seastore.cc @@ -35,6 +35,8 @@ using std::string; using crimson::common::local_conf; +SET_SUBSYS(seastore); + namespace crimson::os::seastore { class FileMDStore final : public SeaStore::MDStore { diff --git a/src/crimson/os/seastore/seastore_types.cc b/src/crimson/os/seastore/seastore_types.cc index d4adada28ab..aaa215a45c0 100644 --- a/src/crimson/os/seastore/seastore_types.cc +++ b/src/crimson/os/seastore/seastore_types.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/segment_cleaner.cc b/src/crimson/os/seastore/segment_cleaner.cc index 10c15849918..d296a958562 100644 --- a/src/crimson/os/seastore/segment_cleaner.cc +++ b/src/crimson/os/seastore/segment_cleaner.cc @@ -9,10 +9,12 @@ namespace { seastar::logger& logger() { - return crimson::get_logger(ceph_subsys_seastore); + return crimson::get_logger(ceph_subsys_seastore_cleaner); } } +SET_SUBSYS(seastore_cleaner); + namespace crimson::os::seastore { void segment_info_set_t::segment_info_t::set_open() { diff --git a/src/crimson/os/seastore/segment_cleaner.h b/src/crimson/os/seastore/segment_cleaner.h index 57cc54859e3..f958cd31826 100644 --- a/src/crimson/os/seastore/segment_cleaner.h +++ b/src/crimson/os/seastore/segment_cleaner.h @@ -205,7 +205,7 @@ public: auto& sm_info = sm_infos[segment_id.device_id()]; auto iter = sm_info->open_segment_avails.find(segment_id); if (iter == sm_info->open_segment_avails.end()) { - crimson::get_logger(ceph_subsys_seastore).error( + crimson::get_logger(ceph_subsys_seastore_cleaner).error( "SegmentCleaner::update_segment_avail_bytes:" ":segment closed {}, not updating", offset); @@ -213,7 +213,7 @@ public: } auto new_avail_bytes = sm_info->segment_size - offset.as_seg_paddr().get_segment_off(); if (iter->second < new_avail_bytes) { - crimson::get_logger(ceph_subsys_seastore).error( + crimson::get_logger(ceph_subsys_seastore_cleaner).error( "SegmentCleaner::update_segment_avail_bytes:" " avail_bytes increased? , {}, {}", iter->second, @@ -685,7 +685,7 @@ public: bool detailed = false); void mount(device_id_t pdevice_id, std::vector& sms) { - crimson::get_logger(ceph_subsys_seastore).debug( + crimson::get_logger(ceph_subsys_seastore_cleaner).debug( "SegmentCleaner::mount: {} segment managers", sms.size()); init_complete = false; stats = {}; @@ -778,7 +778,7 @@ public: segment_seq_t seq, bool out_of_line) final { - crimson::get_logger(ceph_subsys_seastore).debug( + crimson::get_logger(ceph_subsys_seastore_cleaner).debug( "SegmentCleaner::init_mark_segment_closed: segment {}, seq {}", segment, seq); @@ -862,7 +862,7 @@ public: } } if (id != NULL_SEG_ID) { - crimson::get_logger(ceph_subsys_seastore).debug( + crimson::get_logger(ceph_subsys_seastore_cleaner).debug( "SegmentCleaner::get_next_gc_target: segment {} seq {}", id, seq); @@ -1181,7 +1181,7 @@ private: } void log_gc_state(const char *caller) const { - auto &logger = crimson::get_logger(ceph_subsys_seastore); + auto &logger = crimson::get_logger(ceph_subsys_seastore_cleaner); if (logger.is_enabled(seastar::log_level::debug)) { logger.debug( "SegmentCleaner::log_gc_state({}): " @@ -1304,7 +1304,7 @@ private: stats.empty_segments--; } segments.segment_closed(segment); - crimson::get_logger(ceph_subsys_seastore).info( + crimson::get_logger(ceph_subsys_seastore_cleaner).info( "mark closed: {} empty_segments: {}" ", opened_segments {}, should_block_on_gc {}" ", projected_avail_ratio {}, projected_reclaim_ratio {}", @@ -1330,7 +1330,7 @@ private: } segment_info.set_empty(); stats.empty_segments++; - crimson::get_logger(ceph_subsys_seastore + crimson::get_logger(ceph_subsys_seastore_cleaner ).info("mark empty: {}, empty_segments {}" ", opened_segments {}, should_block_on_gc {}" ", projected_avail_ratio {}, projected_reclaim_ratio {}", @@ -1357,7 +1357,7 @@ private: segments[segment].set_open(); assert(stats.empty_segments > 0); stats.empty_segments--; - crimson::get_logger(ceph_subsys_seastore + crimson::get_logger(ceph_subsys_seastore_cleaner ).info("mark open: {}, empty_segments {}" ", opened_segments {}, should_block_on_gc {}" ", projected_avail_ratio {}, projected_reclaim_ratio {}", diff --git a/src/crimson/os/seastore/segment_manager.cc b/src/crimson/os/seastore/segment_manager.cc index 012990d8ac9..8ba186948d2 100644 --- a/src/crimson/os/seastore/segment_manager.cc +++ b/src/crimson/os/seastore/segment_manager.cc @@ -12,7 +12,7 @@ namespace{ seastar::logger &logger(){ - return crimson::get_logger(ceph_subsys_seastore); + return crimson::get_logger(ceph_subsys_seastore_device); } } diff --git a/src/crimson/os/seastore/segment_manager/block.cc b/src/crimson/os/seastore/segment_manager/block.cc index 61b67790054..6c3a79cf822 100644 --- a/src/crimson/os/seastore/segment_manager/block.cc +++ b/src/crimson/os/seastore/segment_manager/block.cc @@ -13,7 +13,7 @@ namespace { seastar::logger& logger() { - return crimson::get_logger(ceph_subsys_seastore); + return crimson::get_logger(ceph_subsys_seastore_device); } } diff --git a/src/crimson/os/seastore/segment_manager/ephemeral.cc b/src/crimson/os/seastore/segment_manager/ephemeral.cc index ea24699a762..4aff7a3e34c 100644 --- a/src/crimson/os/seastore/segment_manager/ephemeral.cc +++ b/src/crimson/os/seastore/segment_manager/ephemeral.cc @@ -13,7 +13,7 @@ namespace { seastar::logger& logger() { - return crimson::get_logger(ceph_subsys_seastore); + return crimson::get_logger(ceph_subsys_seastore_device); } } diff --git a/src/crimson/os/seastore/segment_manager/zns.cc b/src/crimson/os/seastore/segment_manager/zns.cc index bc9752b87e7..a9a4ef00d1a 100644 --- a/src/crimson/os/seastore/segment_manager/zns.cc +++ b/src/crimson/os/seastore/segment_manager/zns.cc @@ -12,7 +12,7 @@ namespace { seastar::logger &logger(){ - return crimson::get_logger(ceph_subsys_seastore); + return crimson::get_logger(ceph_subsys_seastore_device); } } diff --git a/src/crimson/os/seastore/transaction.h b/src/crimson/os/seastore/transaction.h index a3789cb9374..fd14acbd515 100644 --- a/src/crimson/os/seastore/transaction.h +++ b/src/crimson/os/seastore/transaction.h @@ -41,7 +41,7 @@ public: iter != write_set.end()) { if (out) *out = CachedExtentRef(&*iter); - TRACET("Found offset {} in write_set: {}", *this, addr, *iter); + SUBTRACET(seastore_tm, "Found offset {} in write_set: {}", *this, addr, *iter); return get_extent_ret::PRESENT; } else if ( auto iter = read_set.find(addr); @@ -51,7 +51,7 @@ public: assert(iter->ref->get_type() != extent_types_t::RETIRED_PLACEHOLDER); if (out) *out = iter->ref; - TRACET("Found offset {} in read_set: {}", *this, addr, *(iter->ref)); + SUBTRACET(seastore_tm, "Found offset {} in read_set: {}", *this, addr, *(iter->ref)); return get_extent_ret::PRESENT; } else { return get_extent_ret::ABSENT; @@ -102,30 +102,30 @@ public: } ++fresh_block_stats.num; fresh_block_stats.bytes += ref->get_length(); - TRACET("adding {} to write_set", *this, *ref); + SUBTRACET(seastore_tm, "adding {} to write_set", *this, *ref); write_set.insert(*ref); } void mark_delayed_extent_inline(LogicalCachedExtentRef& ref) { LOG_PREFIX(Transaction::mark_delayed_extent_inline); - TRACET("removing {} from write_set", *this, *ref); + SUBTRACET(seastore_tm, "removing {} from write_set", *this, *ref); write_set.erase(*ref); ref->set_paddr(make_record_relative_paddr(offset)); offset += ref->get_length(); inline_block_list.push_back(ref); - TRACET("adding {} to write_set", *this, *ref); + SUBTRACET(seastore_tm, "adding {} to write_set", *this, *ref); write_set.insert(*ref); } void mark_delayed_extent_ool(LogicalCachedExtentRef& ref, paddr_t final_addr) { LOG_PREFIX(Transaction::mark_delayed_extent_ool); - TRACET("removing {} from write_set", *this, *ref); + SUBTRACET(seastore_tm, "removing {} from write_set", *this, *ref); write_set.erase(*ref); ref->set_paddr(final_addr); assert(!ref->get_paddr().is_null()); assert(!ref->is_inline()); ool_block_list.push_back(ref); - TRACET("adding {} to write_set", *this, *ref); + SUBTRACET(seastore_tm, "adding {} to write_set", *this, *ref); write_set.insert(*ref); } @@ -134,7 +134,7 @@ public: ceph_assert(!is_weak()); assert(read_set.count(ref->prior_instance->get_paddr())); mutated_block_list.push_back(ref); - TRACET("adding {} to write_set", *this, *ref); + SUBTRACET(seastore_tm, "adding {} to write_set", *this, *ref); write_set.insert(*ref); } diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc index a04c45ef17b..624ae4c0d5f 100644 --- a/src/crimson/os/seastore/transaction_manager.cc +++ b/src/crimson/os/seastore/transaction_manager.cc @@ -9,6 +9,8 @@ #include "crimson/os/seastore/segment_manager.h" #include "crimson/os/seastore/journal.h" +SET_SUBSYS(seastore_tm); + namespace crimson::os::seastore { TransactionManager::TransactionManager( diff --git a/src/crimson/os/seastore/transaction_manager.h b/src/crimson/os/seastore/transaction_manager.h index 5a7226a7c8f..cb3cdec8d19 100644 --- a/src/crimson/os/seastore/transaction_manager.h +++ b/src/crimson/os/seastore/transaction_manager.h @@ -45,7 +45,7 @@ auto repeat_eagain(F &&f) { return seastar::stop_iteration::yes; }).handle_error( [FNAME](const crimson::ct_error::eagain &e) { - DEBUG("hit eagain, restarting"); + SUBDEBUG(seastore_tm, "hit eagain, restarting"); return seastar::stop_iteration::no; }, crimson::ct_error::pass_further_all{} @@ -149,7 +149,7 @@ public: LBAPinRef pin) { LOG_PREFIX(TransactionManager::pin_to_extent); using ret = pin_to_extent_ret; - DEBUGT("getting extent {}", t, *pin); + SUBDEBUGT(seastore_tm, "getting extent {}", t, *pin); auto &pref = *pin; return cache->get_extent( t, @@ -163,7 +163,7 @@ public: lba_manager->add_pin(extent.get_pin()); } ).si_then([FNAME, &t](auto ref) mutable -> ret { - DEBUGT("got extent {}", t, *ref); + SUBDEBUGT(seastore_tm, "got extent {}", t, *ref); return pin_to_extent_ret( interruptible::ready_future_marker{}, std::move(ref)); @@ -190,8 +190,9 @@ public: t, offset ).si_then([this, FNAME, &t, offset, length] (auto pin) { if (length != pin->get_length() || !pin->get_paddr().is_real()) { - ERRORT("offset {} len {} got wrong pin {}", - t, offset, length, *pin); + SUBERRORT(seastore_tm, + "offset {} len {} got wrong pin {}", + t, offset, length, *pin); ceph_assert(0 == "Should be impossible"); } return this->pin_to_extent(t, std::move(pin)); @@ -212,8 +213,9 @@ public: t, offset ).si_then([this, FNAME, &t, offset] (auto pin) { if (!pin->get_paddr().is_real()) { - ERRORT("offset {} got wrong pin {}", - t, offset, *pin); + SUBERRORT(seastore_tm, + "offset {} got wrong pin {}", + t, offset, *pin); ceph_assert(0 == "Should be impossible"); } return this->pin_to_extent(t, std::move(pin)); @@ -229,14 +231,14 @@ public: stats.extents_mutated_total++; stats.extents_mutated_bytes += ret->get_length(); if (!ret->has_pin()) { - DEBUGT( + SUBDEBUGT(seastore_tm, "duplicating {} for write: {}", t, *ref, *ret); ret->set_pin(ref->get_pin().duplicate()); } else { - DEBUGT( + SUBDEBUGT(seastore_tm, "{} already pending", t, *ref); @@ -311,7 +313,7 @@ public: ext->set_pin(std::move(ref)); stats.extents_allocated_total++; stats.extents_allocated_bytes += len; - DEBUGT("new extent: {}, laddr_hint: {}", t, *ext, laddr_hint); + SUBDEBUGT(seastore_tm, "new extent: {}, laddr_hint: {}", t, *ext, laddr_hint); return alloc_extent_iertr::make_ready_future>( std::move(ext)); }); @@ -507,7 +509,7 @@ public: void add_segment_manager(SegmentManager* sm) { LOG_PREFIX(TransactionManager::add_segment_manager); - DEBUG("adding segment manager {}", sm->get_device_id()); + SUBDEBUG(seastore_tm, "adding segment manager {}", sm->get_device_id()); scanner.add_segment_manager(sm); epm->add_allocator( device_type_t::SEGMENTED, -- 2.39.5