From 12ed1965684f96641cd7fcde3a9e90e3c9c439cc Mon Sep 17 00:00:00 2001 From: Xuehan Xu Date: Sun, 26 Jun 2022 18:44:20 +0800 Subject: [PATCH] crimson/os/seastore/omap_manager: better debug outputs Signed-off-by: Xuehan Xu --- .../omap_manager/btree/btree_omap_manager.cc | 33 ++++--- .../btree/omap_btree_node_impl.cc | 91 ++++++++++++------- src/crimson/os/seastore/seastore_types.cc | 9 ++ src/crimson/os/seastore/seastore_types.h | 1 + 4 files changed, 88 insertions(+), 46 deletions(-) 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 df2ed29d6abf4..e6d25fbda9b9f 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 @@ -9,11 +9,7 @@ #include "crimson/os/seastore/omap_manager/btree/btree_omap_manager.h" #include "crimson/os/seastore/omap_manager/btree/omap_btree_node_impl.h" -namespace { - seastar::logger& logger() { - return crimson::get_logger(ceph_subsys_seastore_omap); - } -} +SET_SUBSYS(seastore_omap); namespace crimson::os::seastore::omap_manager { @@ -24,8 +20,8 @@ BtreeOMapManager::BtreeOMapManager( BtreeOMapManager::initialize_omap_ret BtreeOMapManager::initialize_omap(Transaction &t, laddr_t hint) { - - logger().debug("{}", __func__); + LOG_PREFIX(BtreeOMapManager::initialize_omap); + DEBUGT("hint: {}", t, hint); return tm.alloc_extent(t, hint, OMAP_LEAF_BLOCK_SIZE) .si_then([hint, &t](auto&& root_extent) { root_extent->set_size(0); @@ -53,6 +49,8 @@ BtreeOMapManager::handle_root_split( omap_root_t &omap_root, const OMapNode::mutation_result_t& mresult) { + LOG_PREFIX(BtreeOMapManager::handle_root_split); + DEBUGT("{}", oc.t, omap_root); return oc.tm.alloc_extent(oc.t, omap_root.hint, OMAP_INNER_BLOCK_SIZE) .si_then([&omap_root, mresult, oc](auto&& nroot) -> handle_root_split_ret { @@ -76,6 +74,8 @@ BtreeOMapManager::handle_root_merge( omap_root_t &omap_root, OMapNode::mutation_result_t mresult) { + LOG_PREFIX(BtreeOMapManager::handle_root_merge); + DEBUGT("{}", oc.t, omap_root); auto root = *(mresult.need_merge); auto iter = root->cast()->iter_begin(); omap_root.update( @@ -101,7 +101,8 @@ BtreeOMapManager::omap_get_value( Transaction &t, const std::string &key) { - logger().debug("{}: {}", __func__, key); + LOG_PREFIX(BtreeOMapManager::omap_get_value); + DEBUGT("key={}", t, key); return get_omap_root( get_omap_context(t, omap_root.hint), omap_root @@ -137,7 +138,8 @@ BtreeOMapManager::omap_set_key( const std::string &key, const ceph::bufferlist &value) { - logger().debug("{}: {} -> {}", __func__, key, value); + LOG_PREFIX(BtreeOMapManager::omap_set_key); + DEBUGT("{} -> {}", t, key, value); return get_omap_root( get_omap_context(t, omap_root.hint), omap_root @@ -159,7 +161,8 @@ BtreeOMapManager::omap_rm_key( Transaction &t, const std::string &key) { - logger().debug("{}: {}", __func__, key); + LOG_PREFIX(BtreeOMapManager::omap_rm_key); + DEBUGT("{}", t, key); return get_omap_root( get_omap_context(t, omap_root.hint), omap_root @@ -191,7 +194,12 @@ BtreeOMapManager::omap_list( const std::optional &start, omap_list_config_t config) { - logger().debug("{}", __func__); + LOG_PREFIX(BtreeOMapManager::omap_list); + if (start) { + DEBUGT("{}, start: {}", t, omap_root, *start); + } else { + DEBUGT("{}", t, omap_root); + } return get_omap_root( get_omap_context(t, omap_root.hint), omap_root @@ -208,7 +216,8 @@ BtreeOMapManager::omap_clear( omap_root_t &omap_root, Transaction &t) { - logger().debug("{}", __func__); + LOG_PREFIX(BtreeOMapManager::omap_clear); + DEBUGT("{}", t, omap_root); return get_omap_root( get_omap_context(t, omap_root.hint), omap_root 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 5091935477b89..e23c183738a0c 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 @@ -10,11 +10,7 @@ #include "crimson/os/seastore/omap_manager/btree/omap_btree_node_impl.h" #include "seastar/core/thread.hh" -namespace { - seastar::logger& logger() { - return crimson::get_logger(ceph_subsys_seastore_omap); - } -} +SET_SUBSYS(seastore_omap); namespace crimson::os::seastore::omap_manager { @@ -61,6 +57,8 @@ OMapInnerNode::make_split_insert( std::string key, laddr_t laddr) { + LOG_PREFIX(OMapInnerNode::make_split_insert); + DEBUGT("this: {}, key: {}", oc.t, *this, key); return make_split_children(oc).si_then([=] (auto tuple) { auto [left, right, pivot] = tuple; if (pivot > key) { @@ -87,7 +85,8 @@ OMapInnerNode::handle_split( internal_iterator_t iter, mutation_result_t mresult) { - logger().debug("OMapInnerNode: {}", __func__); + LOG_PREFIX(OMapInnerNode::handle_split); + DEBUGT("this: {}", oc.t, *this); if (!is_pending()) { auto mut = oc.tm.get_mutable_extent(oc.t, this)->cast(); auto mut_iter = mut->iter_idx(iter.get_index()); @@ -121,7 +120,8 @@ OMapInnerNode::get_value( omap_context_t oc, const std::string &key) { - logger().debug("OMapInnerNode: {} key = {}", __func__, key); + LOG_PREFIX(OMapInnerNode::get_value); + DEBUGT("key = {}, this: {}", oc.t, key, *this); auto child_pt = get_containing_child(key); assert(child_pt != iter_cend()); auto laddr = child_pt->get_val(); @@ -137,7 +137,8 @@ OMapInnerNode::insert( const std::string &key, const ceph::bufferlist &value) { - logger().debug("OMapInnerNode: {} {}->{}", __func__, key, value); + LOG_PREFIX(OMapInnerNode::insert); + DEBUGT("{}->{}, this: {}", oc.t, key, value, *this); auto child_pt = get_containing_child(key); assert(child_pt != iter_cend()); auto laddr = child_pt->get_val(); @@ -160,7 +161,8 @@ OMapInnerNode::insert( OMapInnerNode::rm_key_ret OMapInnerNode::rm_key(omap_context_t oc, const std::string &key) { - logger().debug("OMapInnerNode: {}", __func__); + LOG_PREFIX(OMapInnerNode::rm_key); + DEBUGT("key={}, this: {}", oc.t, key, *this); auto child_pt = get_containing_child(key); assert(child_pt != iter_cend()); auto laddr = child_pt->get_val(); @@ -196,7 +198,12 @@ OMapInnerNode::list( const std::optional &start, omap_list_config_t config) { - logger().debug("OMapInnerNode: {}", __func__); + LOG_PREFIX(OMapInnerNode::list); + if (start) { + DEBUGT("start={}, this: {}", oc.t, start, *this); + } else { + DEBUGT("this: {}", oc.t, *this); + } auto child_iter = start ? get_containing_child(*start) : @@ -251,7 +258,8 @@ OMapInnerNode::list( OMapInnerNode::clear_ret OMapInnerNode::clear(omap_context_t oc) { - logger().debug("OMapInnerNode: {}", __func__); + LOG_PREFIX(OMapInnerNode::clear); + DEBUGT("this: {}", oc.t, *this); return trans_intr::do_for_each(iter_begin(), iter_end(), [this, oc] (auto iter) { auto laddr = iter->get_val(); return omap_load_extent(oc, laddr, get_meta().depth - 1).si_then( @@ -268,12 +276,15 @@ OMapInnerNode::clear(omap_context_t oc) OMapInnerNode::split_children_ret OMapInnerNode:: make_split_children(omap_context_t oc) { - logger().debug("OMapInnerNode: {}", __func__); + LOG_PREFIX(OMapInnerNode::make_split_children); + DEBUGT("this: {}", oc.t, *this); return oc.tm.alloc_extents(oc.t, oc.hint, OMAP_INNER_BLOCK_SIZE, 2) - .si_then([this] (auto &&ext_pair) { + .si_then([this, oc] (auto &&ext_pair) { + LOG_PREFIX(OMapInnerNode::make_split_children); auto left = ext_pair.front(); auto right = ext_pair.back(); + DEBUGT("this: {}, split into: l {} r {}", oc.t, *this, *left, *right); return split_children_ret( interruptible::ready_future_marker{}, std::make_tuple(left, right, split_into(*left, *right))); @@ -283,7 +294,8 @@ OMapInnerNode:: make_split_children(omap_context_t oc) OMapInnerNode::full_merge_ret OMapInnerNode::make_full_merge(omap_context_t oc, OMapNodeRef right) { - logger().debug("OMapInnerNode: {}", __func__); + LOG_PREFIX(OMapInnerNode::make_full_merge); + DEBUGT("", oc.t); return oc.tm.alloc_extent(oc.t, oc.hint, OMAP_INNER_BLOCK_SIZE) .si_then([this, right] (auto &&replacement) { @@ -297,7 +309,8 @@ OMapInnerNode::make_full_merge(omap_context_t oc, OMapNodeRef right) OMapInnerNode::make_balanced_ret OMapInnerNode::make_balanced(omap_context_t oc, OMapNodeRef _right) { - logger().debug("OMapInnerNode: {}", __func__); + LOG_PREFIX(OMapInnerNode::make_balanced); + DEBUGT("l: {}, r: {}", oc.t, *this, *_right); ceph_assert(_right->get_type() == TYPE); return oc.tm.alloc_extents(oc.t, oc.hint, OMAP_INNER_BLOCK_SIZE, 2) @@ -319,7 +332,8 @@ OMapInnerNode::merge_entry( internal_iterator_t iter, OMapNodeRef entry) { - logger().debug("OMapInnerNode: {}", __func__); + LOG_PREFIX(OMapInnerNode::merge_entry); + DEBUGT("{}, parent: {}", oc.t, *entry, *this); if (!is_pending()) { auto mut = oc.tm.get_mutable_extent(oc.t, this)->cast(); auto mut_iter = mut->iter_idx(iter->get_index()); @@ -329,16 +343,18 @@ OMapInnerNode::merge_entry( auto donor_iter = is_left ? iter - 1 : iter + 1; return omap_load_extent(oc, donor_iter->get_val(), get_meta().depth - 1) .si_then([=] (auto &&donor) mutable { + LOG_PREFIX(OMapInnerNode::merge_entry); auto [l, r] = is_left ? std::make_pair(donor, entry) : std::make_pair(entry, donor); auto [liter, riter] = is_left ? std::make_pair(donor_iter, iter) : std::make_pair(iter, donor_iter); if (donor->extent_is_below_min()) { - logger().debug("{}::merge_entry make_full_merge l {} r {}", __func__, *l, *r); + DEBUGT("make_full_merge l {} r {}", oc.t, *l, *r); assert(entry->extent_is_below_min()); return l->make_full_merge(oc, r).si_then([liter=liter, riter=riter, l=l, r=r, oc, this] (auto &&replacement){ - logger().debug("OMapInnerNode::merge_entry to update parent: {}", *this); + LOG_PREFIX(OMapInnerNode::merge_entry); + DEBUGT("to update parent: {}", oc.t, *this); journal_inner_update(liter, replacement->get_laddr(), maybe_get_delta_buffer()); journal_inner_remove(riter, maybe_get_delta_buffer()); //retire extent @@ -358,10 +374,11 @@ OMapInnerNode::merge_entry( }); }); } else { - logger().debug("{}::merge_entry balanced l {} r {}", __func__, *l, *r); + DEBUGT("balanced l {} r {}", oc.t, *l, *r); return l->make_balanced(oc, r).si_then([liter=liter, riter=riter, l=l, r=r, oc, this] (auto tuple) { - logger().debug("OMapInnerNode::merge_entry to update parent: {}", *this); + LOG_PREFIX(OMapInnerNode::merge_entry); + DEBUGT("to update parent: {}", oc.t, *this); auto [replacement_l, replacement_r, replacement_pivot] = tuple; //update operation will not cuase node overflow, so we can do it first journal_inner_update(liter, replacement_l->get_laddr(), maybe_get_delta_buffer()); @@ -380,7 +397,7 @@ OMapInnerNode::merge_entry( mutation_result_t(mutation_status_t::SUCCESS, std::nullopt, std::nullopt)); }); } else { - logger().debug("{}::merge_entry balanced and split {} r {}", __func__, *l, *r); + DEBUGT("balanced and split {} r {}", oc.t, *l, *r); //use remove and insert to instead of replace, //remove operation will not cause node split, so we can do it first journal_inner_remove(riter, maybe_get_delta_buffer()); @@ -418,7 +435,8 @@ std::ostream &OMapLeafNode::print_detail_l(std::ostream &out) const OMapLeafNode::get_value_ret OMapLeafNode::get_value(omap_context_t oc, const std::string &key) { - logger().debug("OMapLeafNode: {} key = {}", __func__, key); + LOG_PREFIX(OMapLeafNode::get_value); + DEBUGT("key = {}, this: {}", oc.t, *this, key); auto ite = find_string_key(key); if (ite != iter_end()) { auto value = ite->get_val(); @@ -438,7 +456,8 @@ OMapLeafNode::insert( const std::string &key, const ceph::bufferlist &value) { - logger().debug("OMapLeafNode: {}, {} -> {}", __func__, key, value); + LOG_PREFIX(OMapLeafNode::insert); + DEBUGT("{} -> {}, this: {}", oc.t, key, value, *this); bool overflow = extent_will_overflow(key.size(), value.length()); if (!overflow) { if (!is_pending()) { @@ -454,9 +473,7 @@ OMapLeafNode::insert( auto insert_pt = string_lower_bound(key); journal_leaf_insert(insert_pt, key, value, maybe_get_delta_buffer()); - logger().debug( - "{}: {} inserted {}"," OMapLeafNode", __func__, - insert_pt.get_key()); + DEBUGT("inserted {}, this: {}", oc.t, insert_pt.get_key(), *this); } return insert_ret( interruptible::ready_future_marker{}, @@ -499,7 +516,8 @@ OMapLeafNode::insert( OMapLeafNode::rm_key_ret OMapLeafNode::rm_key(omap_context_t oc, const std::string &key) { - logger().debug("OMapLeafNode: {} : {}", __func__, key); + LOG_PREFIX(OMapLeafNode::rm_key); + DEBUGT("{}, this: {}", oc.t, key, *this); if(!is_pending()) { auto mut = oc.tm.get_mutable_extent(oc.t, this)->cast(); return mut->rm_key(oc, key); @@ -533,12 +551,14 @@ OMapLeafNode::list( const std::optional &start, omap_list_config_t config) { - logger().debug( - "OMapLeafNode::{} start {} max_result_size {} inclusive {}", - __func__, + LOG_PREFIX(OMapLeafNode::list); + DEBUGT( + "start {} max_result_size {} inclusive {}, this: {}", + oc.t, start ? start->c_str() : "", config.max_result_size, - config.inclusive + config.inclusive, + *this ); auto ret = list_bare_ret(false, {}); auto &[complete, result] = ret; @@ -567,7 +587,8 @@ OMapLeafNode::clear(omap_context_t oc) OMapLeafNode::split_children_ret OMapLeafNode::make_split_children(omap_context_t oc) { - logger().debug("OMapLeafNode: {}", __func__); + LOG_PREFIX(OMapLeafNode::make_split_children); + DEBUGT("this: {}", oc.t, *this); return oc.tm.alloc_extents(oc.t, oc.hint, OMAP_LEAF_BLOCK_SIZE, 2) .si_then([this] (auto &&ext_pair) { auto left = ext_pair.front(); @@ -582,7 +603,8 @@ OMapLeafNode::full_merge_ret OMapLeafNode::make_full_merge(omap_context_t oc, OMapNodeRef right) { ceph_assert(right->get_type() == TYPE); - logger().debug("OMapLeafNode: {}", __func__); + LOG_PREFIX(OMapLeafNode::make_full_merge); + DEBUGT("this: {}", oc.t, *this); return oc.tm.alloc_extent(oc.t, oc.hint, OMAP_LEAF_BLOCK_SIZE) .si_then([this, right] (auto &&replacement) { replacement->merge_from(*this, *right->cast()); @@ -596,7 +618,8 @@ OMapLeafNode::make_balanced_ret OMapLeafNode::make_balanced(omap_context_t oc, OMapNodeRef _right) { ceph_assert(_right->get_type() == TYPE); - logger().debug("OMapLeafNode: {}", __func__); + LOG_PREFIX(OMapLeafNode::make_balanced); + DEBUGT("this: {}", oc.t, *this); return oc.tm.alloc_extents(oc.t, oc.hint, OMAP_LEAF_BLOCK_SIZE, 2) .si_then([this, _right] (auto &&replacement_pair) { auto replacement_left = replacement_pair.front(); diff --git a/src/crimson/os/seastore/seastore_types.cc b/src/crimson/os/seastore/seastore_types.cc index 52e8a0b6e96c6..086117c249688 100644 --- a/src/crimson/os/seastore/seastore_types.cc +++ b/src/crimson/os/seastore/seastore_types.cc @@ -19,6 +19,15 @@ bool is_aligned(uint64_t offset, uint64_t alignment) return (offset % alignment) == 0; } +std::ostream& operator<<(std::ostream &out, const omap_root_t &root) +{ + return out << "omap_root{addr=" << root.addr + << ", depth=" << root.depth + << ", hint=" << root.hint + << ", mutated=" << root.mutated + << "}"; +} + std::ostream& operator<<(std::ostream& out, const seastore_meta_t& meta) { return out << meta.seastore_id; diff --git a/src/crimson/os/seastore/seastore_types.h b/src/crimson/os/seastore/seastore_types.h index f7f2e97de64bd..fdd00320fe2a9 100644 --- a/src/crimson/os/seastore/seastore_types.h +++ b/src/crimson/os/seastore/seastore_types.h @@ -1146,6 +1146,7 @@ struct omap_root_t { return hint; } }; +std::ostream &operator<<(std::ostream &out, const omap_root_t &root); class __attribute__((packed)) omap_root_le_t { laddr_le_t addr = laddr_le_t(L_ADDR_NULL); -- 2.39.5