From: Yingxin Cheng Date: Tue, 10 Sep 2024 03:55:05 +0000 (+0800) Subject: crimson/os/seastore/transaction_manager: refine logs X-Git-Tag: testing/wip-vshankar-testing-20241016.135728-debug~47^2 X-Git-Url: http://git.apps.os.sepia.ceph.com/?a=commitdiff_plain;h=ec5c6c5761ed1124d12c2e036262e6135fc99a9b;p=ceph-ci.git crimson/os/seastore/transaction_manager: refine logs Signed-off-by: Yingxin Cheng --- 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 index 5d6fa3cb1b1..ef10ff9623b 100644 --- a/src/crimson/os/seastore/lba_manager/btree/btree_lba_manager.h +++ b/src/crimson/os/seastore/lba_manager/btree/btree_lba_manager.h @@ -173,16 +173,22 @@ public: if (!parent_modified()) { return; } + LOG_PREFIX(BtreeLBAMapping::maybe_fix_pos); auto &p = static_cast(*parent); p.maybe_fix_mapping_pos(*this); + SUBDEBUGT(seastore_lba, "fixed pin {}", + ctx.trans, static_cast(*this)); } LBAMappingRef refresh_with_pending_parent() final { + LOG_PREFIX(BtreeLBAMapping::refresh_with_pending_parent); assert(is_parent_valid() && !is_parent_viewable()); auto &p = static_cast(*parent); auto &viewable_p = static_cast( *p.find_pending_version(ctx.trans, get_key())); - return viewable_p.get_mapping(ctx, get_key()); + auto new_pin = viewable_p.get_mapping(ctx, get_key()); + SUBDEBUGT(seastore_lba, "new pin {}", ctx.trans, static_cast(*new_pin)); + return new_pin; } protected: std::unique_ptr> _duplicate( diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc index 0fd23ef6afb..f4e3b0858f2 100644 --- a/src/crimson/os/seastore/transaction_manager.cc +++ b/src/crimson/os/seastore/transaction_manager.cc @@ -48,7 +48,7 @@ TransactionManager::TransactionManager( TransactionManager::mkfs_ertr::future<> TransactionManager::mkfs() { LOG_PREFIX(TransactionManager::mkfs); - INFO("enter"); + INFO("..."); return epm->mount( ).safe_then([this] { return journal->open_for_mkfs(); @@ -94,7 +94,7 @@ TransactionManager::mkfs_ertr::future<> TransactionManager::mkfs() }).safe_then([this] { return close(); }).safe_then([FNAME] { - INFO("completed"); + INFO("done"); }); } @@ -102,7 +102,7 @@ TransactionManager::mount_ertr::future<> TransactionManager::mount() { LOG_PREFIX(TransactionManager::mount); - INFO("enter"); + INFO("..."); cache->init(); return epm->mount( ).safe_then([this] { @@ -169,7 +169,7 @@ TransactionManager::mount() return epm->open_for_write(); }).safe_then([FNAME, this] { epm->start_background(); - INFO("completed"); + INFO("done"); }).handle_error( mount_ertr::pass_further{}, crimson::ct_error::assert_all{"unhandled error"} @@ -179,7 +179,7 @@ TransactionManager::mount() TransactionManager::close_ertr::future<> TransactionManager::close() { LOG_PREFIX(TransactionManager::close); - INFO("enter"); + INFO("..."); return epm->stop_background( ).then([this] { return cache->close(); @@ -189,7 +189,7 @@ TransactionManager::close() { }).safe_then([this] { return epm->close(); }).safe_then([FNAME] { - INFO("completed"); + INFO("done"); return seastar::now(); }); } @@ -231,14 +231,14 @@ TransactionManager::ref_ret TransactionManager::remove( LogicalCachedExtentRef &ref) { LOG_PREFIX(TransactionManager::remove); - TRACET("{}", t, *ref); + DEBUGT("{} ...", t, *ref); return lba_manager->decref_extent(t, ref->get_laddr() ).si_then([this, FNAME, &t, ref](auto result) { - DEBUGT("extent refcount is decremented to {} -- {}", - t, result.refcount, *ref); if (result.refcount == 0) { cache->retire_extent(t, ref); } + DEBUGT("removed {}~0x{:x} refcount={} -- {}", + t, result.addr, result.length, result.refcount, *ref); return result.refcount; }); } @@ -248,11 +248,9 @@ TransactionManager::ref_ret TransactionManager::remove( laddr_t offset) { LOG_PREFIX(TransactionManager::remove); - TRACET("{}", t, offset); + DEBUGT("{} ...", t, offset); return lba_manager->decref_extent(t, offset ).si_then([this, FNAME, offset, &t](auto result) -> ref_ret { - DEBUGT("extent refcount is decremented to {} -- {}~{}, {}", - t, result.refcount, offset, result.length, result.addr); auto fut = ref_iertr::now(); if (result.refcount == 0) { if (result.addr.is_paddr() && @@ -261,8 +259,9 @@ TransactionManager::ref_ret TransactionManager::remove( t, result.addr.get_paddr(), result.length); } } - - return fut.si_then([result=std::move(result)] { + return fut.si_then([result=std::move(result), offset, &t, FNAME] { + DEBUGT("removed {}~0x{:x} refcount={} -- offset={}", + t, result.addr, result.length, result.refcount, offset); return result.refcount; }); }); @@ -273,9 +272,9 @@ TransactionManager::refs_ret TransactionManager::remove( std::vector offsets) { LOG_PREFIX(TransactionManager::remove); - DEBUG("{} offsets", offsets.size()); + DEBUGT("{} offsets ...", t, offsets.size()); return seastar::do_with(std::move(offsets), std::vector(), - [this, &t](auto &&offsets, auto &refcnts) { + [this, &t, FNAME](auto &&offsets, auto &refcnts) { return trans_intr::do_for_each(offsets.begin(), offsets.end(), [this, &t, &refcnts](auto &laddr) { return this->remove(t, laddr @@ -283,7 +282,8 @@ TransactionManager::refs_ret TransactionManager::remove( refcnts.push_back(ref); return ref_iertr::now(); }); - }).si_then([&refcnts] { + }).si_then([&refcnts, &t, FNAME] { + DEBUGT("removed {} offsets", t, refcnts.size()); return ref_iertr::make_ready_future>(std::move(refcnts)); }); }); @@ -520,7 +520,6 @@ TransactionManager::rewrite_logical_extent( ERRORT("extent has been invalidated -- {}", t, *extent); ceph_abort(); } - TRACET("rewriting extent -- {}", t, *extent); auto lextent = extent->cast(); cache->retire_extent(t, extent); @@ -534,7 +533,7 @@ TransactionManager::rewrite_logical_extent( lextent->get_rewrite_generation())->cast(); nlextent->rewrite(t, *lextent, 0); - DEBUGT("rewriting logical extent -- {} to {}", t, *lextent, *nlextent); + DEBUGT("rewriting meta -- {} to {}", t, *lextent, *nlextent); #ifndef NDEBUG if (get_checksum_needed(lextent->get_paddr())) { @@ -571,17 +570,16 @@ TransactionManager::rewrite_logical_extent( 0, lextent->get_length(), extent_ref_count_t(0), - [this, lextent, &t] + [this, FNAME, lextent, &t] (auto &extents, auto &off, auto &left, auto &refcount) { return trans_intr::do_for_each( extents, - [lextent, this, &t, &off, &left, &refcount](auto &nextent) { - LOG_PREFIX(TransactionManager::rewrite_logical_extent); + [lextent, this, FNAME, &t, &off, &left, &refcount](auto &nextent) { bool first_extent = (off == 0); ceph_assert(left >= nextent->get_length()); auto nlextent = nextent->template cast(); nlextent->rewrite(t, *lextent, off); - DEBUGT("rewriting logical extent -- {} to {}", t, *lextent, *nlextent); + DEBUGT("rewriting data -- {} to {}", t, *lextent, *nlextent); /* This update_mapping is, strictly speaking, unnecessary for delayed_alloc * extents since we're going to do it again once we either do the ool write @@ -635,10 +633,18 @@ TransactionManager::rewrite_extent_ret TransactionManager::rewrite_extent( { auto updated = cache->update_extent_from_transaction(t, extent); if (!updated) { - DEBUGT("extent is already retired, skipping -- {}", t, *extent); + DEBUGT("target={} {} already retired, skipping -- {}", t, + rewrite_gen_printer_t{target_generation}, + sea_time_point_printer_t{modify_time}, + *extent); return rewrite_extent_iertr::now(); } + extent = updated; + DEBUGT("target={} {} -- {} ...", t, + rewrite_gen_printer_t{target_generation}, + sea_time_point_printer_t{modify_time}, + *extent); ceph_assert(!extent->is_pending_io()); } @@ -656,9 +662,9 @@ TransactionManager::rewrite_extent_ret TransactionManager::rewrite_extent( // FIXME: is_dirty() is true for mutation pending extents // which shouldn't do inplace rewrite because a pending transaction // may fail. - DEBUGT("delta overwriting extent -- {}", t, *extent); t.add_inplace_rewrite_extent(extent); extent->set_inplace_rewrite_generation(); + DEBUGT("rewritten as inplace rewrite -- {}", t, *extent); return rewrite_extent_iertr::now(); } extent->set_target_rewrite_generation(INIT_GENERATION); @@ -672,22 +678,24 @@ TransactionManager::rewrite_extent_ret TransactionManager::rewrite_extent( } if (is_root_type(extent->get_type())) { - DEBUGT("rewriting root extent -- {}", t, *extent); cache->duplicate_for_write(t, extent); + DEBUGT("rewritten root {}", t, *extent); return rewrite_extent_iertr::now(); } + auto fut = rewrite_extent_iertr::now(); if (extent->is_logical()) { assert(is_logical_type(extent->get_type())); - return rewrite_logical_extent(t, extent->cast()); + fut = rewrite_logical_extent(t, extent->cast()); } else if (is_backref_node(extent->get_type())) { - DEBUGT("rewriting backref extent -- {}", t, *extent); - return backref_manager->rewrite_extent(t, extent); + fut = backref_manager->rewrite_extent(t, extent); } else { assert(is_lba_node(extent->get_type())); - DEBUGT("rewriting physical extent -- {}", t, *extent); - return lba_manager->rewrite_extent(t, extent); + fut = lba_manager->rewrite_extent(t, extent); } + return fut.si_then([FNAME, &t] { + DEBUGT("rewritten", t); + }); } TransactionManager::get_extents_if_live_ret @@ -699,7 +707,7 @@ TransactionManager::get_extents_if_live( extent_len_t len) { LOG_PREFIX(TransactionManager::get_extents_if_live); - TRACET("{} {}~{} {}", t, type, laddr, len, paddr); + DEBUGT("{} {}~0x{:x} {} ...", t, type, laddr, len, paddr); // This only works with segments to check if alive, // as parallel transactions may split the extent at the same time. @@ -709,7 +717,7 @@ TransactionManager::get_extents_if_live( ).si_then([=, this, &t](auto extent) -> get_extents_if_live_ret { if (extent && extent->get_length() == len) { - DEBUGT("{} {}~{} {} is live in cache -- {}", + DEBUGT("{} {}~0x{:x} {} is cached and alive -- {}", t, type, laddr, len, paddr, *extent); std::list res; res.emplace_back(std::move(extent)); @@ -763,7 +771,9 @@ TransactionManager::get_extents_if_live( list.emplace_back(std::move(ret)); return seastar::now(); }); - }).si_then([&list] { + }).si_then([&list, &t, FNAME, type, laddr, len, paddr] { + DEBUGT("{} {}~0x{:x} {} is alive as {} extents", + t, type, laddr, len, paddr, list.size()); return get_extents_if_live_ret( interruptible::ready_future_marker{}, std::move(list)); @@ -784,11 +794,11 @@ TransactionManager::get_extents_if_live( ).si_then([=, &t](auto ret) { std::list res; if (ret) { - DEBUGT("{} {}~{} {} is live as physical extent -- {}", + DEBUGT("{} {}~0x{:x} {} is absent and alive as physical extent -- {}", t, type, laddr, len, paddr, *ret); res.emplace_back(std::move(ret)); } else { - DEBUGT("{} {}~{} {} is not live as physical extent", + DEBUGT("{} {}~0x{:x} {} is not alive as physical extent", t, type, laddr, len, paddr); } return get_extents_if_live_ret( diff --git a/src/crimson/os/seastore/transaction_manager.h b/src/crimson/os/seastore/transaction_manager.h index 6d1b010ab69..c7a94a9ef11 100644 --- a/src/crimson/os/seastore/transaction_manager.h +++ b/src/crimson/os/seastore/transaction_manager.h @@ -106,8 +106,12 @@ public: Transaction &t, laddr_t offset) { LOG_PREFIX(TransactionManager::get_pin); - SUBTRACET(seastore_tm, "{}", t, offset); - return lba_manager->get_mapping(t, offset); + SUBDEBUGT(seastore_tm, "{} ...", t, offset); + return lba_manager->get_mapping(t, offset + ).si_then([FNAME, &t](LBAMappingRef pin) { + SUBDEBUGT(seastore_tm, "got {}", t, *pin); + return pin; + }); } /** @@ -122,9 +126,13 @@ public: laddr_t offset, extent_len_t length) { LOG_PREFIX(TransactionManager::get_pins); - SUBDEBUGT(seastore_tm, "{}~{}", t, offset, length); + SUBDEBUGT(seastore_tm, "{}~0x{:x} ...", t, offset, length); return lba_manager->get_mappings( - t, offset, length); + t, offset, length + ).si_then([FNAME, &t](lba_pin_list_t pins) { + SUBDEBUGT(seastore_tm, "got {} pins", t, pins.size()); + return pins; + }); } /** @@ -142,15 +150,15 @@ public: laddr_t offset, extent_len_t length) { LOG_PREFIX(TransactionManager::read_extent); - SUBTRACET(seastore_tm, "{}~{}", t, offset, length); + SUBDEBUGT(seastore_tm, "{}~0x{:x} {} ...", + t, offset, length, T::TYPE); return get_pin( t, offset ).si_then([this, FNAME, &t, offset, length] (auto pin) -> read_extent_ret { if (length != pin->get_length() || !pin->get_val().is_real()) { - SUBERRORT(seastore_tm, - "offset {} len {} got wrong pin {}", - t, offset, length, *pin); + SUBERRORT(seastore_tm, "{}~0x{:x} {} got wrong {}", + t, offset, length, T::TYPE, *pin); ceph_assert(0 == "Should be impossible"); } return this->read_pin(t, std::move(pin)); @@ -167,15 +175,15 @@ public: Transaction &t, laddr_t offset) { LOG_PREFIX(TransactionManager::read_extent); - SUBTRACET(seastore_tm, "{}", t, offset); + SUBDEBUGT(seastore_tm, "{} {} ...", + t, offset, T::TYPE); return get_pin( t, offset ).si_then([this, FNAME, &t, offset] (auto pin) -> read_extent_ret { if (!pin->get_val().is_real()) { - SUBERRORT(seastore_tm, - "offset {} got wrong pin {}", - t, offset, *pin); + SUBERRORT(seastore_tm, "{} {} got wrong {}", + t, offset, T::TYPE, *pin); ceph_assert(0 == "Should be impossible"); } return this->read_pin(t, std::move(pin)); @@ -187,6 +195,8 @@ public: Transaction &t, LBAMappingRef pin) { + LOG_PREFIX(TransactionManager::read_pin); + SUBDEBUGT(seastore_tm, "{} {} ...", t, T::TYPE, *pin); auto fut = base_iertr::make_ready_future(); if (!pin->is_parent_viewable()) { if (pin->is_parent_valid()) { @@ -212,6 +222,9 @@ public: } else { return this->pin_to_extent(t, std::move(std::get<0>(ret))); } + }).si_then([FNAME, &t](TCachedExtentRef ext) { + SUBDEBUGT(seastore_tm, "got {}", t, *ext); + return ext; }); } @@ -222,17 +235,9 @@ public: t, ref)->cast(); if (!ret->has_laddr()) { - SUBDEBUGT(seastore_tm, - "duplicating extent for write -- {} -> {}", - t, - *ref, - *ret); + SUBDEBUGT(seastore_tm, "duplicate from {}", t, *ref); ret->set_laddr(ref->get_laddr()); } else { - SUBTRACET(seastore_tm, - "extent is already duplicated -- {}", - t, - *ref); assert(ref->is_mutable()); assert(&*ref == &*ret); } @@ -291,23 +296,23 @@ public: extent_len_t len, placement_hint_t placement_hint = placement_hint_t::HOT) { LOG_PREFIX(TransactionManager::alloc_non_data_extent); - SUBTRACET(seastore_tm, "{} len={}, placement_hint={}, laddr_hint={}", - t, T::TYPE, len, placement_hint, laddr_hint); + SUBDEBUGT(seastore_tm, "{} hint {}~0x{:x} phint={} ...", + t, T::TYPE, laddr_hint, len, placement_hint); auto ext = cache->alloc_new_non_data_extent( t, len, placement_hint, INIT_GENERATION); if (!ext) { + SUBERRORT(seastore_tm, "insufficient space!", t); return crimson::ct_error::enospc::make(); } return lba_manager->alloc_extent( t, laddr_hint, *ext - ).si_then([ext=std::move(ext), laddr_hint, &t](auto &&) mutable { - LOG_PREFIX(TransactionManager::alloc_non_data_extent); - SUBDEBUGT(seastore_tm, "new extent: {}, laddr_hint: {}", t, *ext, laddr_hint); + ).si_then([ext=std::move(ext), &t, FNAME](auto &&) mutable { + SUBDEBUGT(seastore_tm, "allocated {}", t, *ext); return alloc_extent_iertr::make_ready_future>( std::move(ext)); }); @@ -330,14 +335,15 @@ public: extent_len_t len, placement_hint_t placement_hint = placement_hint_t::HOT) { LOG_PREFIX(TransactionManager::alloc_data_extents); - SUBTRACET(seastore_tm, "{} len={}, placement_hint={}, laddr_hint={}", - t, T::TYPE, len, placement_hint, laddr_hint); + SUBDEBUGT(seastore_tm, "{} hint {}~0x{:x} phint={} ...", + t, T::TYPE, laddr_hint, len, placement_hint); auto exts = cache->alloc_new_data_extents( t, len, placement_hint, INIT_GENERATION); if (exts.empty()) { + SUBERRORT(seastore_tm, "insufficient space!", t); return crimson::ct_error::enospc::make(); } return lba_manager->alloc_extents( @@ -348,7 +354,7 @@ public: EXTENT_DEFAULT_REF_COUNT ).si_then([exts=std::move(exts), &t, FNAME](auto &&) mutable { for (auto &ext : exts) { - SUBDEBUGT(seastore_tm, "new extent: {}", t, *ext); + SUBDEBUGT(seastore_tm, "allocated {}", t, *ext); } return alloc_extent_iertr::make_ready_future< std::vector>>(std::move(exts)); @@ -360,14 +366,17 @@ public: Transaction &t, laddr_t laddr, extent_len_t len) { + LOG_PREFIX(TransactionManager::get_mutable_extent_by_laddr); + SUBDEBUGT(seastore_tm, "{}~0x{:x} ...", t, laddr, len); return get_pin(t, laddr ).si_then([this, &t, len](auto pin) { ceph_assert(pin->is_data_stable() && !pin->is_zero_reserved()); ceph_assert(!pin->is_clone()); ceph_assert(pin->get_length() == len); return this->read_pin(t, std::move(pin)); - }).si_then([this, &t](auto extent) { + }).si_then([this, &t, FNAME](auto extent) { auto ext = get_mutable_extent(t, extent)->template cast(); + SUBDEBUGT(seastore_tm, "got mutable {}", t, *ext); return read_extent_iertr::make_ready_future>( std::move(ext)); }); @@ -424,10 +433,8 @@ public: extent_len_t original_len = pin->get_length(); paddr_t original_paddr = pin->get_val(); LOG_PREFIX(TransactionManager::remap_pin); - SUBDEBUGT(seastore_tm, - "original laddr: {}, original paddr: {}, original length: {}," - " remap to {} extents", - t, original_laddr, original_paddr, original_len, remaps.size()); + SUBDEBUGT(seastore_tm, "{}~0x{:x} {} into {} remaps ... {}", + t, original_laddr, original_len, original_paddr, remaps.size(), *pin); // The according extent might be stable or pending. auto fut = base_iertr::now(); if (!pin->is_indirect()) { @@ -484,14 +491,13 @@ public: auto remap_len = remap.len; auto remap_laddr = (original_laddr + remap_offset).checked_to_laddr(); auto remap_paddr = original_paddr.add_offset(remap_offset); + SUBDEBUGT(seastore_tm, "remap direct pin into {}~0x{:x} {} ...", + t, remap_laddr, remap_len, remap_paddr); ceph_assert(remap_len < original_len); ceph_assert(remap_offset + remap_len <= original_len); ceph_assert(remap_len != 0); ceph_assert(remap_offset % cache->get_block_size() == 0); ceph_assert(remap_len % cache->get_block_size() == 0); - SUBDEBUGT(seastore_tm, - "remap laddr: {}, remap paddr: {}, remap length: {}", t, - remap_laddr, remap_paddr, remap_len); auto extent = cache->alloc_remapped_extent( t, remap_laddr, @@ -503,13 +509,15 @@ public: } }); } - return fut.si_then([this, &t, &pin, &remaps, &extents] { + return fut.si_then([this, &t, &pin, &remaps, &extents, FNAME] { return lba_manager->remap_mappings( t, std::move(pin), std::vector(remaps.begin(), remaps.end()), std::move(extents) - ).si_then([](auto ret) { + ).si_then([FNAME, &t](auto ret) { + SUBDEBUGT(seastore_tm, "remapped {} pins", + t, ret.remapped_mappings.size()); return Cache::retire_extent_iertr::make_ready_future< std::vector>(std::move(ret.remapped_mappings)); }); @@ -529,11 +537,15 @@ public: laddr_t hint, extent_len_t len) { LOG_PREFIX(TransactionManager::reserve_region); - SUBDEBUGT(seastore_tm, "len={}, laddr_hint={}", t, len, hint); + SUBDEBUGT(seastore_tm, "hint {}~0x{:x} ...", t, hint, len); return lba_manager->reserve_region( t, hint, - len); + len + ).si_then([FNAME, &t](auto pin) { + SUBDEBUGT(seastore_tm, "reserved {}", t, *pin); + return pin; + }); } /* @@ -560,15 +572,17 @@ public: : mapping.get_key(); LOG_PREFIX(TransactionManager::clone_pin); - SUBDEBUGT(seastore_tm, "len={}, laddr_hint={}, clone_offset {}", - t, mapping.get_length(), hint, intermediate_key); + SUBDEBUGT(seastore_tm, "{} clone to hint {} ...", t, mapping, hint); return lba_manager->clone_mapping( t, hint, mapping.get_length(), intermediate_key, intermediate_base - ); + ).si_then([FNAME, &t](auto pin) { + SUBDEBUGT(seastore_tm, "cloned as {}", t, *pin); + return pin; + }); } /* alloc_extents @@ -583,10 +597,10 @@ public: extent_len_t len, int num) { LOG_PREFIX(TransactionManager::alloc_extents); - SUBDEBUGT(seastore_tm, "len={}, laddr_hint={}, num={}", - t, len, hint, num); + SUBDEBUGT(seastore_tm, "hint {}~({} * 0x{:x}) ...", + t, hint, num, len); return seastar::do_with(std::vector>(), - [this, &t, hint, len, num] (auto &extents) { + [this, &t, hint, len, num, FNAME](auto &extents) { return trans_intr::do_for_each( boost::make_counting_iterator(0), boost::make_counting_iterator(num), @@ -595,7 +609,8 @@ public: [&extents](auto &&node) { extents.push_back(node); }); - }).si_then([&extents] { + }).si_then([&extents, &t, FNAME] { + SUBDEBUGT(seastore_tm, "allocated {} extents", t, extents.size()); return alloc_extents_iertr::make_ready_future >>(std::move(extents)); }); @@ -701,7 +716,7 @@ public: const std::string& key, const std::string& value) { LOG_PREFIX(TransactionManager::update_root_meta); - SUBDEBUGT(seastore_tm, "seastore_tm, {} -> {}", t, key, value); + SUBDEBUGT(seastore_tm, "seastore_tm, {} -> {} ...", t, key, value); return cache->get_root( t ).si_then([this, &t, &key, &value](RootBlockRef root) { @@ -756,7 +771,7 @@ public: return cache->get_root(t).si_then([&t](auto croot) { LOG_PREFIX(TransactionManager::read_collection_root); auto ret = croot->get_root().collection_root.get(); - SUBTRACET(seastore_tm, "{}~{}", + SUBTRACET(seastore_tm, "{}~0x{:x}", t, ret.get_location(), ret.get_size()); return ret; }); @@ -769,7 +784,7 @@ public: */ void write_collection_root(Transaction &t, coll_root_t cmroot) { LOG_PREFIX(TransactionManager::write_collection_root); - SUBDEBUGT(seastore_tm, "{}~{}", + SUBDEBUGT(seastore_tm, "{}~0x{:x}", t, cmroot.get_location(), cmroot.get_size()); auto croot = cache->get_root_fast(t); croot = cache->duplicate_for_write(t, croot)->cast(); @@ -872,7 +887,7 @@ private: Transaction &t, LBAMappingRef pin) { LOG_PREFIX(TransactionManager::pin_to_extent); - SUBTRACET(seastore_tm, "getting extent {}", t, *pin); + SUBTRACET(seastore_tm, "getting absent extent from pin {} ...", t, *pin); static_assert(is_logical_type(T::TYPE)); using ret = pin_to_extent_ret; auto &pref = *pin; @@ -936,7 +951,8 @@ private: extent_types_t type) { LOG_PREFIX(TransactionManager::pin_to_extent_by_type); - SUBTRACET(seastore_tm, "getting extent {} type {}", t, *pin, type); + SUBTRACET(seastore_tm, "getting absent extent from pin {} type {} ...", + t, *pin, type); assert(is_logical_type(type)); auto &pref = *pin; return cache->get_absent_extent_by_type(