From abb0951eda905e3c7d6b4b5a7b9488933f780fd5 Mon Sep 17 00:00:00 2001 From: Yingxin Cheng Date: Wed, 19 Jan 2022 10:57:20 +0800 Subject: [PATCH] crimson/os/seastore/cache: consolidate logs in levels Signed-off-by: Yingxin Cheng --- src/crimson/os/seastore/cache.cc | 98 +++++++++++++-------- src/crimson/os/seastore/cache.h | 122 ++++++++++++++++++++------ src/crimson/os/seastore/transaction.h | 17 ++-- 3 files changed, 159 insertions(+), 78 deletions(-) diff --git a/src/crimson/os/seastore/cache.cc b/src/crimson/os/seastore/cache.cc index 5bb04886464..39ac510b96b 100644 --- a/src/crimson/os/seastore/cache.cc +++ b/src/crimson/os/seastore/cache.cc @@ -30,6 +30,8 @@ Cache::Cache( lru(crimson::common::get_conf( "seastore_cache_lru_size")) { + LOG_PREFIX(Cache::Cache); + INFO("created, lru_size={}", lru.get_capacity()); register_metrics(); } @@ -37,7 +39,7 @@ Cache::~Cache() { LOG_PREFIX(Cache::~Cache); for (auto &i: extents) { - ERROR("extent {} still alive", i); + ERROR("extent is still alive -- {}", i); } ceph_assert(extents.empty()); } @@ -45,17 +47,19 @@ Cache::~Cache() Cache::retire_extent_ret Cache::retire_extent_addr( Transaction &t, paddr_t addr, extent_len_t length) { + LOG_PREFIX(Cache::retire_extent_addr); + TRACET("retire {}~{}", t, addr, length); + assert(addr.is_real() && !addr.is_block_relative()); - LOG_PREFIX(Cache::retire_extent); CachedExtentRef ext; auto result = t.get_extent(addr, &ext); if (result == Transaction::get_extent_ret::PRESENT) { - DEBUGT("found {} in t", t, addr); + DEBUGT("retire {}~{} on t -- {}", t, addr, length, *ext); t.add_to_retired_set(CachedExtentRef(&*ext)); return retire_extent_iertr::now(); } else if (result == Transaction::get_extent_ret::RETIRED) { - ERRORT("{} is already retired", t, addr); + ERRORT("retire {}~{} failed, already retired -- {}", t, addr, length, *ext); ceph_abort(); } @@ -66,6 +70,7 @@ Cache::retire_extent_ret Cache::retire_extent_addr( // retiring is not included by the cache hit metrics ext = query_cache(addr, nullptr); if (ext) { + DEBUGT("retire {}~{} in cache -- {}", t, addr, length, *ext); if (ext->get_type() != extent_types_t::RETIRED_PLACEHOLDER) { t.add_to_read_set(ext); return trans_intr::make_interruptible( @@ -77,6 +82,7 @@ Cache::retire_extent_ret Cache::retire_extent_addr( } // the retired-placeholder exists } else { + DEBUGT("retire {}~{} as placeholder", t, addr, length); // add a new placeholder to Cache ext = CachedExtent::make_cached_extent_ref< RetiredExtentPlaceholder>(length); @@ -103,6 +109,9 @@ void Cache::dump_contents() void Cache::register_metrics() { + LOG_PREFIX(Cache::register_metrics); + DEBUG(""); + stats = {}; namespace sm = seastar::metrics; @@ -614,6 +623,7 @@ void Cache::register_metrics() void Cache::add_extent(CachedExtentRef ref) { LOG_PREFIX(Cache::add_extent); + TRACE("extent -- {}", *ref); assert(ref->is_valid()); extents.insert(*ref); if (ref->is_dirty()) { @@ -621,12 +631,10 @@ void Cache::add_extent(CachedExtentRef ref) } else { touch_extent(*ref); } - DEBUG("extent {}", *ref); } void Cache::mark_dirty(CachedExtentRef ref) { - LOG_PREFIX(Cache::mark_dirty); if (ref->is_dirty()) { assert(ref->primary_ref_list_hook.is_linked()); return; @@ -635,8 +643,6 @@ void Cache::mark_dirty(CachedExtentRef ref) lru.remove_from_lru(*ref); add_to_dirty(ref); ref->state = CachedExtent::extent_state_t::DIRTY; - - DEBUG("extent: {}", *ref); } void Cache::add_to_dirty(CachedExtentRef ref) @@ -663,7 +669,7 @@ void Cache::remove_from_dirty(CachedExtentRef ref) void Cache::remove_extent(CachedExtentRef ref) { LOG_PREFIX(Cache::remove_extent); - DEBUG("extent {}", *ref); + TRACE("extent -- {}", *ref); assert(ref->is_valid()); if (ref->is_dirty()) { remove_from_dirty(ref); @@ -677,8 +683,6 @@ void Cache::commit_retire_extent( Transaction& t, CachedExtentRef ref) { - LOG_PREFIX(Cache::commit_retire_extent); - DEBUGT("extent {}", t, *ref); remove_extent(ref); ref->dirty_from_or_retired_at = JOURNAL_SEQ_MAX; @@ -690,8 +694,6 @@ void Cache::commit_replace_extent( CachedExtentRef next, CachedExtentRef prev) { - LOG_PREFIX(Cache::commit_replace_extent); - DEBUGT("prev {}, next {}", t, *prev, *next); assert(next->get_paddr() == prev->get_paddr()); assert(next->version == prev->version + 1); extents.replace(*next, *prev); @@ -777,7 +779,6 @@ void Cache::mark_transaction_conflicted( if (!i->is_valid()) { continue; } - DEBUGT("was mutating extent: {}", t, *i); efforts.mutate.increment(i->get_length()); delta_stat.increment(i->get_delta().length()); } @@ -857,6 +858,9 @@ CachedExtentRef Cache::alloc_new_extent_by_type( bool delay ///< [in] whether to delay paddr alloc ) { + LOG_PREFIX(Cache::alloc_new_extent_by_type); + SUBDEBUGT(seastore_cache, "allocate {} {}B, delay={}", + t, type, length, delay); switch (type) { case extent_types_t::ROOT: ceph_assert(0 == "ROOT is never directly alloc'd"); @@ -1008,7 +1012,7 @@ record_t Cache::prepare_record(Transaction &t) // invalidate now invalid blocks io_stat_t retire_stat; for (auto &i: t.retired_set) { - DEBUGT("retiring {}", t, *i); + DEBUGT("retired extent -- {}", t, *i); get_by_ext(efforts.retire_by_ext, i->get_type()).increment(i->get_length()); retire_stat.increment(i->get_length()); @@ -1027,12 +1031,12 @@ record_t Cache::prepare_record(Transaction &t) io_stat_t fresh_invalid_stat; for (auto &i: t.inline_block_list) { if (!i->is_valid()) { - DEBUGT("fresh inline block (invalid) {}", t, *i); + DEBUGT("invalid fresh inline extent -- {}", t, *i); fresh_invalid_stat.increment(i->get_length()); get_by_ext(efforts.fresh_invalid_by_ext, i->get_type()).increment(i->get_length()); } else { - DEBUGT("fresh inline block {}", t, *i); + DEBUGT("fresh inline extent -- {}", t, *i); } fresh_stat.increment(i->get_length()); get_by_ext(efforts.fresh_inline_by_ext, @@ -1069,7 +1073,7 @@ record_t Cache::prepare_record(Transaction &t) for (auto &i: t.ool_block_list) { ceph_assert(i->is_valid()); - DEBUGT("fresh ool block {}", t, *i); + DEBUGT("fresh ool extent -- {}", t, *i); get_by_ext(efforts.fresh_ool_by_ext, i->get_type()).increment(i->get_length()); } @@ -1155,7 +1159,6 @@ void Cache::complete_commit( if (i->is_valid()) { i->state = CachedExtent::extent_state_t::CLEAN; - DEBUGT("fresh {}", t, *i); add_extent(i); if (cleaner) { cleaner->mark_space_used( @@ -1170,7 +1173,6 @@ void Cache::complete_commit( if (!i->is_valid()) { continue; } - DEBUGT("mutated {}", t, *i); assert(i->prior_instance); i->on_delta_write(final_block_start); i->prior_instance = CachedExtentRef(); @@ -1197,12 +1199,14 @@ void Cache::complete_commit( last_commit = seq; for (auto &i: t.retired_set) { - DEBUGT("retiring {}", t, *i); i->dirty_from_or_retired_at = last_commit; } } -void Cache::init() { +void Cache::init() +{ + LOG_PREFIX(Cache::init); + INFO("init root"); if (root) { // initial creation will do mkfs followed by mount each of which calls init remove_extent(root); @@ -1215,6 +1219,8 @@ void Cache::init() { Cache::mkfs_iertr::future<> Cache::mkfs(Transaction &t) { + LOG_PREFIX(Cache::mkfs); + INFOT("create root", t); return get_root(t).si_then([this, &t](auto croot) { duplicate_for_write(t, croot); return mkfs_iertr::now(); @@ -1228,6 +1234,15 @@ Cache::mkfs_iertr::future<> Cache::mkfs(Transaction &t) Cache::close_ertr::future<> Cache::close() { + LOG_PREFIX(Cache::close); + INFO("close with {}({}B) dirty from {}, {}({}B) lru, totally {}({}B) indexed extents", + dirty.size(), + stats.dirty_bytes, + get_oldest_dirty_from().value_or(journal_seq_t{}), + lru.get_current_contents_extents(), + lru.get_current_contents_bytes(), + extents.size(), + extents.get_bytes()); root.reset(); for (auto i = dirty.begin(); i != dirty.end(); ) { auto ptr = &*i; @@ -1248,7 +1263,7 @@ Cache::replay_delta( { LOG_PREFIX(Cache::replay_delta); if (delta.type == extent_types_t::ROOT) { - DEBUG("found root delta"); + DEBUG("replay root delta {} at {} {}", delta, journal_seq, record_base); remove_extent(root); root->apply_delta_and_adjust_crc(record_base, delta.bl); root->dirty_from_or_retired_at = journal_seq; @@ -1290,14 +1305,14 @@ Cache::replay_delta( ); return extent_fut.safe_then([=, &delta](auto extent) { if (!extent) { + DEBUG("replay extent is not present, so delta is obsolete {} at {} {}", + delta, journal_seq, record_base); assert(delta.pversion > 0); - DEBUG( - "replaying {}, extent not present so delta is obsolete", - delta); return; } - DEBUG("replaying {} on {}", *extent, delta); + DEBUG("replay extent delta {} at {} {} -- {} ...", + delta, journal_seq, record_base, *extent); assert(extent->version == delta.pversion); @@ -1320,6 +1335,13 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents( size_t max_bytes) { LOG_PREFIX(Cache::get_next_dirty_extents); + if (dirty.empty()) { + DEBUGT("max_bytes={}B, seq={}, dirty is empty", + t, max_bytes, seq); + } else { + DEBUGT("max_bytes={}B, seq={}, dirty_from={}", + t, max_bytes, seq, dirty.begin()->get_dirty_from()); + } std::vector cand; size_t bytes_so_far = 0; for (auto i = dirty.begin(); @@ -1330,9 +1352,10 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents( dirty_from != JOURNAL_SEQ_MAX && dirty_from != NO_DELTAS); if (dirty_from < seq) { - DEBUGT("next {}", t, *i); + TRACET("next extent -- {}", t, *i); if (!cand.empty() && cand.back()->get_dirty_from() > dirty_from) { - ERRORT("last {}, next {}", t, *cand.back(), *i); + ERRORT("dirty extents are not ordered by dirty_from -- last={}, next={}", + t, *cand.back(), *i); ceph_abort(); } bytes_so_far += i->get_length(); @@ -1348,8 +1371,7 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents( return trans_intr::do_for_each( cand, [FNAME, this, &t, &ret](auto &ext) { - DEBUG("waiting on {}", *ext); - + TRACET("waiting on extent -- {}", t, *ext); return trans_intr::make_interruptible( ext->wait_io() ).then_interruptible([FNAME, this, ext, &t, &ret] { @@ -1362,7 +1384,7 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents( CachedExtentRef on_transaction; auto result = t.get_extent(ext->get_paddr(), &on_transaction); if (result == Transaction::get_extent_ret::ABSENT) { - DEBUGT("{} absent on t", t, *ext); + DEBUGT("extent is absent on t -- {}", t, *ext); t.add_to_read_set(ext); if (ext->get_type() == extent_types_t::ROOT) { if (t.root) { @@ -1375,11 +1397,11 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents( } ret.push_back(ext); } else if (result == Transaction::get_extent_ret::PRESENT) { - DEBUGT("{} present on t as {}", t, *ext, *on_transaction); + DEBUGT("extent is present on t -- {}, on t {}", t, *ext, *on_transaction); ret.push_back(on_transaction); } else { assert(result == Transaction::get_extent_ret::RETIRED); - DEBUGT("{} retired on t", t, *ext); + DEBUGT("extent is retired on t -- {}", t, *ext); } }); }).then_interruptible([&ret] { @@ -1392,16 +1414,16 @@ Cache::get_root_ret Cache::get_root(Transaction &t) { LOG_PREFIX(Cache::get_root); if (t.root) { - DEBUGT("root already on transaction {}", t, *t.root); + TRACET("root already on t -- {}", t, *t.root); return get_root_iertr::make_ready_future( t.root); } else { auto ret = root; - DEBUGT("waiting root {}", t, *ret); + DEBUGT("root not on t -- {}", t, *ret); return ret->wait_io().then([this, FNAME, ret, &t] { - DEBUGT("got root read {}", t, *ret); + TRACET("root wait io done -- {}", t, *ret); if (!ret->is_valid()) { - DEBUGT("root became invalid: {}", t, *ret); + DEBUGT("root is invalid -- {}", t, *ret); ++(get_by_src(stats.trans_conflicts_by_unknown, t.get_src())); mark_transaction_conflicted(t, *ret); return get_root_iertr::make_ready_future(); diff --git a/src/crimson/os/seastore/cache.h b/src/crimson/os/seastore/cache.h index 0060dd8ad5e..a63162a45a0 100644 --- a/src/crimson/os/seastore/cache.h +++ b/src/crimson/os/seastore/cache.h @@ -88,6 +88,9 @@ namespace crimson::os::seastore { * Cache logs * * levels: + * - INFO: major initiation, closing operations + * - DEBUG: major extent related operations, INFO details + * - TRACE: DEBUG details * - seastore_t logs */ class Cache { @@ -134,6 +137,8 @@ public: /// Declare ref retired in t void retire_extent(Transaction &t, CachedExtentRef ref) { + LOG_PREFIX(Cache::retire_extent); + SUBDEBUGT(seastore_cache, "retire extent -- {}", t, *ref); t.add_to_retired_set(ref); } @@ -158,6 +163,8 @@ public: * returns t.root and assume it is already present/read in t */ RootBlockRef get_root_fast(Transaction &t) { + LOG_PREFIX(Cache::get_root_fast); + SUBTRACET(seastore_cache, "root already on t -- {}", t, *t.root); assert(t.root); return t.root; } @@ -180,8 +187,11 @@ public: const src_ext_t* p_metric_key, ///< [in] cache query metric key Func &&extent_init_func ///< [in] init func for extent ) { + LOG_PREFIX(Cache::get_extent); auto cached = query_cache(offset, p_metric_key); if (!cached) { + SUBDEBUG(seastore_cache, + "{} {}~{} is absent, reading ...", T::TYPE, offset, length); auto ret = CachedExtent::make_cached_extent_ref( alloc_cache_buf(length)); ret->set_paddr(offset); @@ -194,6 +204,9 @@ public: // extent PRESENT in cache if (cached->get_type() == extent_types_t::RETIRED_PLACEHOLDER) { + SUBDEBUG(seastore_cache, + "{} {}~{} is absent(placeholder), reading ...", + T::TYPE, offset, length); auto ret = CachedExtent::make_cached_extent_ref( alloc_cache_buf(length)); ret->set_paddr(offset); @@ -211,6 +224,9 @@ public: return read_extent( std::move(ret)); } else { + SUBTRACE(seastore_cache, + "{} {}~{} is present in cache -- {}", + T::TYPE, offset, length, *cached); auto ret = TCachedExtentRef(static_cast(cached.get())); return ret->wait_io( ).then([ret=std::move(ret)]() mutable @@ -248,11 +264,14 @@ public: CachedExtentRef ret; LOG_PREFIX(Cache::get_extent_if_cached); auto result = t.get_extent(offset, &ret); - if (result != Transaction::get_extent_ret::ABSENT) { - // including get_extent_ret::RETIRED - SUBDEBUGT(seastore_cache, - "Found extent at offset {} on transaction: {}", - t, offset, *ret); + if (result == Transaction::get_extent_ret::RETIRED) { + SUBDEBUGT(seastore_cache, "{} {} is retired on t -- {}", + t, type, offset, *ret); + return get_extent_if_cached_iertr::make_ready_future< + CachedExtentRef>(ret); + } else if (result == Transaction::get_extent_ret::PRESENT) { + SUBTRACET(seastore_cache, "{} {} is present on t -- {}", + t, type, offset, *ret); return get_extent_if_cached_iertr::make_ready_future< CachedExtentRef>(ret); } @@ -263,17 +282,15 @@ public: if (!ret || // retired_placeholder is not really cached yet ret->get_type() == extent_types_t::RETIRED_PLACEHOLDER) { - SUBDEBUGT(seastore_cache, - "No extent at offset {}, retired_placeholder: {}", - t, offset, !!ret); + SUBDEBUGT(seastore_cache, "{} {} is absent{}", + t, type, offset, !!ret ? "(placeholder)" : ""); return get_extent_if_cached_iertr::make_ready_future< CachedExtentRef>(); } // present in cache and is not a retired_placeholder - SUBDEBUGT(seastore_cache, - "Found extent at offset {} in cache: {}", - t, offset, *ret); + SUBDEBUGT(seastore_cache, "{} {} is present in cache -- {}", + t, type, offset, *ret); t.add_to_read_set(ret); touch_extent(*ret); return ret->wait_io().then([ret] { @@ -303,29 +320,33 @@ public: LOG_PREFIX(Cache::get_extent); auto result = t.get_extent(offset, &ret); if (result != Transaction::get_extent_ret::ABSENT) { + SUBTRACET(seastore_cache, "{} {}~{} is {} on t -- {}", + t, + T::TYPE, + offset, + length, + result == Transaction::get_extent_ret::PRESENT ? "present" : "retired", + *ret); assert(result != Transaction::get_extent_ret::RETIRED); - SUBDEBUGT(seastore_cache, - "Found extent at offset {} on transaction: {}", - t, offset, *ret); return seastar::make_ready_future>( ret->cast()); } else { + SUBTRACET(seastore_cache, "{} {}~{} is absent on t, query cache ...", + t, T::TYPE, offset, length); auto metric_key = std::make_pair(t.get_src(), T::TYPE); return trans_intr::make_interruptible( get_extent( offset, length, &metric_key, std::forward(extent_init_func)) - ).si_then([this, FNAME, offset, &t](auto ref) { + ).si_then([this, FNAME, offset, length, &t](auto ref) { (void)this; // silence incorrect clang warning about capture if (!ref->is_valid()) { - SUBDEBUGT(seastore_cache, "got invalid extent: {}", t, ref); + SUBDEBUGT(seastore_cache, "{} {}~{} is invalid -- {}", + t, T::TYPE, offset, length, *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 { - SUBDEBUGT(seastore_cache, - "Read extent at offset {} in cache: {}", - t, offset, *ref); touch_extent(*ref); t.add_to_read_set(ref); return get_extent_iertr::make_ready_future>( @@ -387,14 +408,22 @@ private: paddr_t offset, laddr_t laddr, seastore_off_t length, - extent_init_func_t &&extent_init_func) { + extent_init_func_t &&extent_init_func + ) { + LOG_PREFIX(Cache::get_extent_by_type); CachedExtentRef ret; auto status = t.get_extent(offset, &ret); if (status == Transaction::get_extent_ret::RETIRED) { + SUBDEBUGT(seastore_cache, "{} {}~{} {} is retired on t -- {}", + t, type, offset, length, laddr, *ret); return seastar::make_ready_future(); } else if (status == Transaction::get_extent_ret::PRESENT) { + SUBTRACET(seastore_cache, "{} {}~{} {} is present on t -- {}", + t, type, offset, length, laddr, *ret); return seastar::make_ready_future(ret); } else { + SUBTRACET(seastore_cache, "{} {}~{} {} is absent on t, query cache ...", + t, type, offset, length, laddr); auto src = t.get_src(); return trans_intr::make_interruptible( _get_extent_by_type( @@ -402,8 +431,8 @@ private: std::move(extent_init_func)) ).si_then([=, &t](CachedExtentRef ret) { if (!ret->is_valid()) { - LOG_PREFIX(Cache::get_extent_by_type); - SUBDEBUGT(seastore_cache, "got invalid extent: {}", t, ret); + SUBDEBUGT(seastore_cache, "{} {}~{} {} is invalid -- {}", + t, type, offset, length, laddr, *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(); @@ -464,6 +493,9 @@ public: seastore_off_t length, ///< [in] length bool delayed = false ///< [in] whether the paddr allocation of extent is delayed ) { + LOG_PREFIX(Cache::alloc_new_extent); + SUBDEBUGT(seastore_cache, "allocate {} {}B, delay={}", + t, T::TYPE, length, delayed); auto ret = CachedExtent::make_cached_extent_ref( alloc_cache_buf(length)); t.add_fresh_extent(ret, delayed); @@ -473,14 +505,21 @@ public: void mark_delayed_extent_inline( Transaction& t, - LogicalCachedExtentRef& ref) { + LogicalCachedExtentRef& ref + ) { + LOG_PREFIX(Cache::mark_delayed_extent_inline); + SUBDEBUGT(seastore_cache, "-- {}", t, *ref); t.mark_delayed_extent_inline(ref); } void mark_delayed_extent_ool( Transaction& t, LogicalCachedExtentRef& ref, - paddr_t final_addr) { + paddr_t final_addr + ) { + LOG_PREFIX(Cache::mark_delayed_extent_ool); + SUBDEBUGT(seastore_cache, "final_addr={} -- {}", + t, final_addr, *ref); t.mark_delayed_extent_ool(ref, final_addr); } @@ -588,6 +627,15 @@ public: Transaction &t, F &&f) { + LOG_PREFIX(Cache::init_cached_extents); + SUBINFOT(seastore_cache, + "start with {}({}B) extents, {} dirty, from {}", + t, + extents.size(), + extents.get_bytes(), + dirty.size(), + get_oldest_dirty_from().value_or(journal_seq_t{})); + // journal replay should has been finished at this point, // Cache::root should have been inserted to the dirty list assert(root->is_dirty()); @@ -598,16 +646,20 @@ public: return seastar::do_with( std::forward(f), std::move(_dirty), - [this, &t](auto &f, auto &refs) mutable + [this, FNAME, &t](auto &f, auto &refs) mutable { return trans_intr::do_for_each( refs, - [this, &t, &f](auto &e) + [this, FNAME, &t, &f](auto &e) { + SUBTRACET(seastore_cache, "inspecting extent ... -- {}", t, *e); return f(t, e - ).si_then([this, &t, e](bool is_alive) { + ).si_then([this, FNAME, &t, e](bool is_alive) { if (!is_alive) { + SUBDEBUGT(seastore_cache, "extent is not alive, remove -- {}", t, *e); remove_extent(e); + } else { + SUBDEBUGT(seastore_cache, "extent is alive -- {}", t, *e); } }); }); @@ -616,7 +668,15 @@ public: crimson::ct_error::assert_all{ "Invalid error in Cache::init_cached_extents" } - ); + ).si_then([this, FNAME, &t] { + SUBINFOT(seastore_cache, + "finish with {}({}B) extents, {} dirty, from {}", + t, + extents.size(), + extents.get_bytes(), + dirty.size(), + get_oldest_dirty_from().value_or(journal_seq_t{})); + }); } /** @@ -742,6 +802,10 @@ private: public: LRU(size_t capacity) : capacity(capacity) {} + size_t get_capacity() const { + return capacity; + } + size_t get_current_contents_bytes() const { return contents; } @@ -974,12 +1038,14 @@ private: extent->get_bptr() ).safe_then( [extent=std::move(extent)]() mutable { + LOG_PREFIX(Cache::read_extent); extent->state = CachedExtent::extent_state_t::CLEAN; /* TODO: crc should be checked against LBA manager */ extent->last_committed_crc = extent->get_crc32c(); extent->on_clean_read(); extent->complete_io(); + SUBDEBUG(seastore_cache, "read extent done -- {}", *extent); return get_extent_ertr::make_ready_future>( std::move(extent)); }, diff --git a/src/crimson/os/seastore/transaction.h b/src/crimson/os/seastore/transaction.h index 9fe502ab33a..8e4cb8d17f5 100644 --- a/src/crimson/os/seastore/transaction.h +++ b/src/crimson/os/seastore/transaction.h @@ -50,6 +50,7 @@ inline std::ostream& operator<<(std::ostream& out, const io_stat_t& stat) { * seastore_t * - DEBUG: transaction create, conflict, commit events * - TRACE: DEBUG details + * - seastore_cache logs */ class Transaction { public: @@ -68,7 +69,8 @@ public: iter != write_set.end()) { if (out) *out = CachedExtentRef(&*iter); - SUBTRACET(seastore_tm, "Found offset {} in write_set: {}", *this, addr, *iter); + SUBTRACET(seastore_cache, "{} is present in write_set -- {}", + *this, addr, *iter); return get_extent_ret::PRESENT; } else if ( auto iter = read_set.find(addr); @@ -78,7 +80,8 @@ public: assert(iter->ref->get_type() != extent_types_t::RETIRED_PLACEHOLDER); if (out) *out = iter->ref; - SUBTRACET(seastore_tm, "Found offset {} in read_set: {}", *this, addr, *(iter->ref)); + SUBTRACET(seastore_cache, "{} is present in read_set -- {}", + *this, addr, *(iter->ref)); return get_extent_ret::PRESENT; } else { return get_extent_ret::ABSENT; @@ -115,7 +118,6 @@ public: void add_fresh_extent( CachedExtentRef ref, bool delayed = false) { - LOG_PREFIX(Transaction::add_fresh_extent); ceph_assert(!is_weak()); if (delayed) { assert(ref->is_logical()); @@ -128,39 +130,30 @@ public: inline_block_list.push_back(ref); } fresh_block_stats.increment(ref->get_length()); - 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); - 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); - 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); - 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); - SUBTRACET(seastore_tm, "adding {} to write_set", *this, *ref); write_set.insert(*ref); } void add_mutated_extent(CachedExtentRef ref) { - LOG_PREFIX(Transaction::add_mutated_extent); ceph_assert(!is_weak()); assert(read_set.count(ref->prior_instance->get_paddr())); mutated_block_list.push_back(ref); - SUBTRACET(seastore_tm, "adding {} to write_set", *this, *ref); write_set.insert(*ref); }