From 798f00e7b4666b1807410c579a88a98aa43852ba Mon Sep 17 00:00:00 2001 From: Yingxin Cheng Date: Mon, 7 Feb 2022 18:50:47 +0800 Subject: [PATCH] crimson/os/seastore/lba_manager: consolidate logs Signed-off-by: Yingxin Cheng --- .../lba_manager/btree/btree_lba_manager.cc | 143 +++++++++++------- .../lba_manager/btree/btree_range_pin.cc | 12 +- .../lba_manager/btree/lba_btree_node.cc | 14 +- .../lba_manager/btree/lba_btree_node.h | 2 + 4 files changed, 112 insertions(+), 59 deletions(-) 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 09cb7fe9be5..dec4254344a 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 @@ -11,12 +11,20 @@ #include "crimson/os/seastore/logging.h" SET_SUBSYS(seastore_lba); +/* + * levels: + * - INFO: mkfs + * - DEBUG: modification operations + * - TRACE: read operations, DEBUG details + */ namespace crimson::os::seastore::lba_manager::btree { BtreeLBAManager::mkfs_ret BtreeLBAManager::mkfs( Transaction &t) { + LOG_PREFIX(BtreeLBAManager::mkfs); + INFOT("start", t); return cache.get_root(t).si_then([this, &t](auto croot) { croot->get_root().lba_root = LBABtree::mkfs(get_context(t)); return mkfs_iertr::now(); @@ -34,20 +42,24 @@ BtreeLBAManager::get_mappings( laddr_t offset, extent_len_t length) { LOG_PREFIX(BtreeLBAManager::get_mappings); - DEBUGT("offset: {}, length{}", t, offset, length); + TRACET("{}~{}", t, offset, length); auto c = get_context(t); return with_btree_state( c, - [c, offset, length](auto &btree, auto &ret) { + [c, offset, length, FNAME](auto &btree, auto &ret) { return LBABtree::iterate_repeat( c, btree.upper_bound_right(c, offset), - [&ret, offset, length](auto &pos) { + [&ret, offset, length, c, FNAME](auto &pos) { if (pos.is_end() || pos.get_key() >= (offset + length)) { + TRACET("{}~{} done with {} results", + c.trans, offset, length, ret.size()); return LBABtree::iterate_repeat_ret_inner( interruptible::ready_future_marker{}, seastar::stop_iteration::yes); } + TRACET("{}~{} got {}, {}, repeat ...", + c.trans, offset, length, pos.get_key(), pos.get_val()); ceph_assert((pos.get_key() + pos.get_val().len) > offset); ret.push_back(pos.get_pin()); return LBABtree::iterate_repeat_ret_inner( @@ -64,7 +76,7 @@ BtreeLBAManager::get_mappings( laddr_list_t &&list) { LOG_PREFIX(BtreeLBAManager::get_mappings); - DEBUGT("{}", t, list); + TRACET("{}", t, list); auto l = std::make_unique(std::move(list)); auto retptr = std::make_unique(); auto &ret = *retptr; @@ -88,7 +100,7 @@ BtreeLBAManager::get_mapping( laddr_t offset) { LOG_PREFIX(BtreeLBAManager::get_mapping); - DEBUGT("{}", t, offset); + TRACET("{}", t, offset); auto c = get_context(t); return with_btree_ret( c, @@ -97,10 +109,12 @@ BtreeLBAManager::get_mapping( c, offset ).si_then([FNAME, offset, c](auto iter) -> get_mapping_ret { if (iter.is_end() || iter.get_key() != offset) { + DEBUGT("{} doesn't exist", c.trans, offset); return crimson::ct_error::enoent::make(); } else { + TRACET("{} got {}, {}", + c.trans, offset, iter.get_key(), iter.get_val()); auto e = iter.get_pin(); - DEBUGT("got mapping {}", c.trans, *e); return get_mapping_ret( interruptible::ready_future_marker{}, std::move(e)); @@ -127,47 +141,59 @@ BtreeLBAManager::alloc_extent( }; LOG_PREFIX(BtreeLBAManager::alloc_extent); - DEBUGT("hint: {}, length: {}", t, hint, len); + TRACET("{}~{}, hint={}", t, addr, len, hint); auto c = get_context(t); ++stats.num_alloc_extents; + auto lookup_attempts = stats.num_alloc_extents_iter_nexts; return with_btree_state( c, hint, - [this, FNAME, c, hint, len, addr, &t](auto &btree, auto &state) { + [this, FNAME, c, hint, len, addr, lookup_attempts, &t](auto &btree, auto &state) { return LBABtree::iterate_repeat( c, btree.upper_bound_right(c, hint), - [this, &state, len, &t, hint, FNAME](auto &pos) { + [this, &state, len, addr, &t, hint, FNAME, lookup_attempts](auto &pos) { ++stats.num_alloc_extents_iter_nexts; - if (!pos.is_end()) { - DEBUGT("iterate_repeat: pos: {}~{}, state: {}~{}, hint: {}", - t, - pos.get_key(), - pos.get_val().len, + if (pos.is_end()) { + DEBUGT("{}~{}, hint={}, state: end, done with {} attempts, insert at {}", + t, addr, len, hint, + stats.num_alloc_extents_iter_nexts - lookup_attempts, + state.last_end); + state.insert_iter = pos; + return LBABtree::iterate_repeat_ret_inner( + interruptible::ready_future_marker{}, + seastar::stop_iteration::yes); + } else if (pos.get_key() >= (state.last_end + len)) { + DEBUGT("{}~{}, hint={}, state: {}~{}, done with {} attempts, insert at {} -- {}", + t, addr, len, hint, + pos.get_key(), pos.get_val().len, + stats.num_alloc_extents_iter_nexts - lookup_attempts, state.last_end, - len, - hint); - } - if (pos.is_end() || pos.get_key() >= (state.last_end + len)) { + pos.get_val()); state.insert_iter = pos; return LBABtree::iterate_repeat_ret_inner( interruptible::ready_future_marker{}, seastar::stop_iteration::yes); } else { state.last_end = pos.get_key() + pos.get_val().len; + TRACET("{}~{}, hint={}, state: {}~{}, repeat ... -- {}", + t, addr, len, hint, + pos.get_key(), pos.get_val().len, + pos.get_val()); return LBABtree::iterate_repeat_ret_inner( interruptible::ready_future_marker{}, seastar::stop_iteration::no); } - }).si_then([FNAME, c, addr, len, &btree, &state] { - DEBUGT("about to insert at addr {}~{}", c.trans, state.last_end, len); + }).si_then([FNAME, c, addr, len, hint, &btree, &state] { return btree.insert( c, *state.insert_iter, state.last_end, lba_map_val_t{len, addr, 1, 0} - ).si_then([&state](auto &&p) { + ).si_then([&state, FNAME, c, addr, len, hint](auto &&p) { auto [iter, inserted] = std::move(p); + TRACET("{}~{}, hint={}, inserted at {}", + c.trans, addr, len, hint, state.last_end); ceph_assert(inserted); state.ret = iter; }); @@ -210,6 +236,7 @@ void BtreeLBAManager::complete_transaction( Transaction &t) { LOG_PREFIX(BtreeLBAManager::complete_transaction); + DEBUGT("start", t); std::vector to_clear; to_clear.reserve(t.get_retired_set().size()); for (auto &e: t.get_retired_set()) { @@ -223,7 +250,7 @@ void BtreeLBAManager::complete_transaction( for (auto &e: to_clear) { auto &pin = get_pin(*e); - DEBUGT("retiring {}, {}", t, *e, pin); + DEBUGT("retiring extent {} -- {}", t, pin, *e); pin_set.retire(pin); } @@ -240,13 +267,13 @@ void BtreeLBAManager::complete_transaction( [](auto &l, auto &r) -> bool { return get_depth(*l) > get_depth(*r); }); for (auto &e : to_link) { - DEBUGT("linking {}", t, *e); + DEBUGT("linking extent -- {}", t, *e); pin_set.add_pin(get_pin(*e)); } for (auto &e: to_clear) { auto &pin = get_pin(*e); - DEBUGT("checking {}, {}", t, *e, pin); + TRACET("checking extent {} -- {}", t, pin, *e); pin_set.check_parent(pin); } } @@ -256,15 +283,16 @@ BtreeLBAManager::init_cached_extent_ret BtreeLBAManager::init_cached_extent( CachedExtentRef e) { LOG_PREFIX(BtreeLBAManager::init_cached_extent); - DEBUGT("extent {}", t, *e); - return seastar::do_with(bool(), [this, e, &t](bool& ret) { + TRACET("{}", t, *e); + return seastar::do_with(bool(), [this, e, FNAME, &t](bool& ret) { auto c = get_context(t); return with_btree(c, [c, e, &ret](auto &btree) { return btree.init_cached_extent(c, e ).si_then([&ret](bool is_alive) { ret = is_alive; }); - }).si_then([&ret] { + }).si_then([&ret, e, FNAME, c] { + DEBUGT("is_alive={} -- {}", c.trans, ret, *e); return ret; }); }); @@ -306,7 +334,7 @@ BtreeLBAManager::scan_mapped_space_ret BtreeLBAManager::scan_mapped_space( scan_mapped_space_func_t &&f) { LOG_PREFIX(BtreeLBAManager::scan_mapped_space); - DEBUGT("", t); + DEBUGT("start", t); auto c = get_context(t); return seastar::do_with( std::move(f), @@ -339,14 +367,13 @@ BtreeLBAManager::rewrite_extent_ret BtreeLBAManager::rewrite_extent( { LOG_PREFIX(BtreeLBAManager::rewrite_extent); if (extent->has_been_invalidated()) { - ERRORT("{} has been invalidated", t, *extent); + ERRORT("extent has been invalidated -- {}", t, *extent); + ceph_abort(); } - assert(!extent->has_been_invalidated()); assert(!extent->is_logical()); - DEBUGT("rewriting {}", t, *extent); - if (is_lba_node(*extent)) { + DEBUGT("rewriting lba extent -- {}", t, *extent); auto c = get_context(t); return with_btree( c, @@ -354,6 +381,7 @@ BtreeLBAManager::rewrite_extent_ret BtreeLBAManager::rewrite_extent( return btree.rewrite_lba_extent(c, extent); }); } else { + DEBUGT("skip non lba extent -- {}", t, *extent); return rewrite_extent_iertr::now(); } } @@ -365,6 +393,8 @@ BtreeLBAManager::update_mapping( paddr_t prev_addr, paddr_t addr) { + LOG_PREFIX(BtreeLBAManager::update_mapping); + TRACET("laddr={}, paddr {} => {}", t, laddr, prev_addr, addr); return update_mapping( t, laddr, @@ -375,14 +405,17 @@ BtreeLBAManager::update_mapping( ceph_assert(in.paddr == prev_addr); ret.paddr = addr; return ret; - }).si_then( - [](auto) {}, - update_le_mapping_iertr::pass_further{}, - /* ENOENT in particular should be impossible */ - crimson::ct_error::assert_all{ - "Invalid error in BtreeLBAManager::rewrite_extent after update_mapping" - } - ); + } + ).si_then([&t, laddr, prev_addr, addr, FNAME](auto result) { + DEBUGT("laddr={}, paddr {} => {} done -- {}", + t, laddr, prev_addr, addr, result); + }, + update_le_mapping_iertr::pass_further{}, + /* ENOENT in particular should be impossible */ + crimson::ct_error::assert_all{ + "Invalid error in BtreeLBAManager::rewrite_extent after update_mapping" + } + ); } BtreeLBAManager::get_physical_extent_if_live_ret @@ -393,6 +426,9 @@ BtreeLBAManager::get_physical_extent_if_live( laddr_t laddr, seastore_off_t len) { + LOG_PREFIX(BtreeLBAManager::get_physical_extent_if_live); + DEBUGT("{}, laddr={}, paddr={}, length={}", + t, type, laddr, addr, len); ceph_assert(is_lba_node(type)); auto c = get_context(t); return with_btree_ret( @@ -418,6 +454,8 @@ BtreeLBAManager::BtreeLBAManager( void BtreeLBAManager::register_metrics() { + LOG_PREFIX(BtreeLBAManager::register_metrics); + DEBUG("start"); stats = {}; namespace sm = seastar::metrics; metrics.add_group( @@ -443,7 +481,7 @@ BtreeLBAManager::update_refcount_ret BtreeLBAManager::update_refcount( int delta) { LOG_PREFIX(BtreeLBAManager::update_refcount); - DEBUGT("addr {}, delta {}", t, addr, delta); + TRACET("laddr={}, delta={}", t, addr, delta); return update_mapping( t, addr, @@ -452,13 +490,15 @@ BtreeLBAManager::update_refcount_ret BtreeLBAManager::update_refcount( ceph_assert((int)out.refcount + delta >= 0); out.refcount += delta; return out; - }).si_then([](auto result) { - return ref_update_result_t{ - result.refcount, - result.paddr, - result.len - }; - }); + } + ).si_then([&t, addr, delta, FNAME](auto result) { + DEBUGT("laddr={}, delta={} done -- {}", t, addr, delta, result); + return ref_update_result_t{ + result.refcount, + result.paddr, + result.len + }; + }); } BtreeLBAManager::update_mapping_ret BtreeLBAManager::update_mapping( @@ -466,8 +506,6 @@ BtreeLBAManager::update_mapping_ret BtreeLBAManager::update_mapping( laddr_t addr, update_func_t &&f) { - LOG_PREFIX(BtreeLBAManager::update_mapping); - DEBUGT("addr {}", t, addr); auto c = get_context(t); return with_btree_ret( c, @@ -477,6 +515,8 @@ BtreeLBAManager::update_mapping_ret BtreeLBAManager::update_mapping( ).si_then([&btree, f=std::move(f), c, addr](auto iter) -> update_mapping_ret { if (iter.is_end() || iter.get_key() != addr) { + LOG_PREFIX(BtreeLBAManager::update_mapping); + DEBUGT("laddr={} doesn't exist", c.trans, addr); return crimson::ct_error::enoent::make(); } @@ -505,7 +545,8 @@ BtreeLBAManager::~BtreeLBAManager() { pin_set.scan([](auto &i) { LOG_PREFIX(BtreeLBAManager::~BtreeLBAManager); - ERROR("Found {} {} has_ref={}", i, i.get_extent(), i.has_ref()); + ERROR("Found {}, has_ref={} -- {}", + i, i.has_ref(), i.get_extent()); }); } 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 694c7022835..21c4279edc8 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 @@ -29,7 +29,7 @@ btree_range_pin_t::~btree_range_pin_t() ceph_assert(!pins == !is_linked()); ceph_assert(!ref); if (pins) { - DEBUG("removing {}", *this); + TRACE("removing {}", *this); pins->remove_pin(*this, true); } extent = nullptr; @@ -43,7 +43,7 @@ void btree_pin_set_t::replace_pin(btree_range_pin_t &to, btree_range_pin_t &from void btree_pin_set_t::remove_pin(btree_range_pin_t &pin, bool do_check_parent) { LOG_PREFIX(btree_pin_set_t::remove_pin); - DEBUG("{}", pin); + TRACE("{}", pin); ceph_assert(pin.is_linked()); ceph_assert(pin.pins); ceph_assert(!pin.ref); @@ -124,14 +124,14 @@ void btree_pin_set_t::add_pin(btree_range_pin_t &pin) auto *parent = maybe_get_parent(pin.range); ceph_assert(parent); if (!parent->has_ref()) { - DEBUG("acquiring parent {}", static_cast(parent)); + TRACE("acquiring parent {}", static_cast(parent)); parent->acquire_ref(); } else { - DEBUG("parent has ref {}", static_cast(parent)); + TRACE("parent has ref {}", static_cast(parent)); } } if (maybe_get_first_child(pin.range) != nullptr) { - DEBUG("acquiring self {}", pin); + TRACE("acquiring self {}", pin); pin.acquire_ref(); } } @@ -147,7 +147,7 @@ void btree_pin_set_t::check_parent(btree_range_pin_t &pin) LOG_PREFIX(btree_pin_set_t::check_parent); auto parent = maybe_get_parent(pin.range); if (parent) { - DEBUG("releasing parent {}", *parent); + TRACE("releasing parent {}", *parent); release_if_no_children(*parent); } } 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 f83730b90b1..a6ee25e9170 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 @@ -17,6 +17,16 @@ SET_SUBSYS(seastore_lba); namespace crimson::os::seastore::lba_manager::btree { +std::ostream& operator<<(std::ostream& out, const lba_map_val_t& v) +{ + return out << "lba_map_val_t(" + << v.paddr + << "~" << v.len + << ", refcount=" << v.refcount + << ", checksum=" << v.checksum + << ")"; +} + std::ostream &LBAInternalNode::print_detail(std::ostream &out) const { return out << ", size=" << get_size() @@ -29,7 +39,7 @@ void LBAInternalNode::resolve_relative_addrs(paddr_t base) for (auto i: *this) { if (i->get_val().is_relative()) { auto updated = base.add_relative(i->get_val()); - DEBUG("{} -> {}", i->get_val(), updated); + TRACE("{} -> {}", i->get_val(), updated); i->set_val(updated); } } @@ -48,7 +58,7 @@ void LBALeafNode::resolve_relative_addrs(paddr_t base) if (i->get_val().paddr.is_relative()) { auto val = i->get_val(); val.paddr = base.add_relative(val.paddr); - DEBUG("{} -> {}", i->get_val().paddr, val.paddr); + TRACE("{} -> {}", i->get_val().paddr, val.paddr); i->set_val(val); } } diff --git a/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.h b/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.h index 7f5c97c8893..683efbed46a 100644 --- a/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.h +++ b/src/crimson/os/seastore/lba_manager/btree/lba_btree_node.h @@ -55,6 +55,8 @@ WRITE_EQ_OPERATORS_4( refcount, checksum); +std::ostream& operator<<(std::ostream& out, const lba_map_val_t&); + class BtreeLBAPin; using BtreeLBAPinRef = std::unique_ptr; -- 2.39.5