From: Yingxin Cheng Date: Mon, 24 Jan 2022 05:16:20 +0000 (+0800) Subject: crimson/os/seastore/transaction_manager: consolidate logs in levels X-Git-Tag: v18.0.0~1491^2 X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=refs%2Fpull%2F44748%2Fhead;p=ceph.git crimson/os/seastore/transaction_manager: consolidate logs in levels Signed-off-by: Yingxin Cheng --- diff --git a/src/crimson/os/seastore/seastore_types.cc b/src/crimson/os/seastore/seastore_types.cc index f738870544cf..d6f5fb94ba85 100644 --- a/src/crimson/os/seastore/seastore_types.cc +++ b/src/crimson/os/seastore/seastore_types.cc @@ -513,6 +513,20 @@ try_decode_deltas( return record_deltas; } +std::ostream& operator<<(std::ostream& out, placement_hint_t h) +{ + switch (h) { + case placement_hint_t::HOT: + return out << "HOT"; + case placement_hint_t::COLD: + return out << "COLD"; + case placement_hint_t::REWRITE: + return out << "REWRITE"; + default: + return out << "INVALID_PLACEMENT_HINT_TYPE!"; + } +} + bool can_delay_allocation(device_type_t type) { // Some types of device may not support delayed allocation, for example PMEM. return type <= device_type_t::RANDOM_BLOCK; diff --git a/src/crimson/os/seastore/seastore_types.h b/src/crimson/os/seastore/seastore_types.h index db7c907a29a9..10f70afafa5c 100644 --- a/src/crimson/os/seastore/seastore_types.h +++ b/src/crimson/os/seastore/seastore_types.h @@ -696,6 +696,8 @@ enum class placement_hint_t { NUM_HINTS // Constant for number of hints }; +std::ostream& operator<<(std::ostream& out, placement_hint_t h); + enum class device_type_t { NONE = 0, SEGMENTED, // i.e. Hard_Disk, SATA_SSD, NAND_NVME diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc index 769d759177c6..25252b34afd8 100644 --- a/src/crimson/os/seastore/transaction_manager.cc +++ b/src/crimson/os/seastore/transaction_manager.cc @@ -13,6 +13,9 @@ * TransactionManager logs * * levels: + * - INFO: major initiation, closing operations + * - DEBUG: major extent related operations, INFO details + * - TRACE: DEBUG details * - seastore_t logs */ SET_SUBSYS(seastore_tm); @@ -42,24 +45,23 @@ TransactionManager::TransactionManager( TransactionManager::mkfs_ertr::future<> TransactionManager::mkfs() { LOG_PREFIX(TransactionManager::mkfs); + INFO("enter"); segment_cleaner->mount( segment_manager.get_device_id(), scanner.get_segment_managers()); return journal->open_for_write().safe_then([this, FNAME](auto addr) { - DEBUG("about to do_with"); segment_cleaner->init_mkfs(addr); return with_transaction_intr( Transaction::src_t::MUTATE, "mkfs_tm", [this, FNAME](auto& t) { - DEBUGT("about to cache->mkfs", t); cache->init(); return cache->mkfs(t ).si_then([this, &t] { return lba_manager->mkfs(t); }).si_then([this, FNAME, &t] { - DEBUGT("about to submit_transaction", t); + INFOT("submitting mkfs transaction", t); return submit_transaction_direct(t); }); }).handle_error( @@ -71,12 +73,15 @@ TransactionManager::mkfs_ertr::future<> TransactionManager::mkfs() ); }).safe_then([this] { return close(); + }).safe_then([FNAME] { + INFO("completed"); }); } TransactionManager::mount_ertr::future<> TransactionManager::mount() { LOG_PREFIX(TransactionManager::mount); + INFO("enter"); cache->init(); segment_cleaner->mount( segment_manager.get_device_id(), @@ -128,8 +133,9 @@ TransactionManager::mount_ertr::future<> TransactionManager::mount() }); }); }); - }).safe_then([this] { + }).safe_then([this, FNAME] { segment_cleaner->complete_init(); + INFO("completed"); }).handle_error( mount_ertr::pass_further{}, crimson::ct_error::all_same_way([] { @@ -140,7 +146,7 @@ TransactionManager::mount_ertr::future<> TransactionManager::mount() TransactionManager::close_ertr::future<> TransactionManager::close() { LOG_PREFIX(TransactionManager::close); - DEBUG("enter"); + INFO("enter"); return segment_cleaner->stop( ).then([this] { return cache->close(); @@ -148,7 +154,7 @@ TransactionManager::close_ertr::future<> TransactionManager::close() { cache->dump_contents(); return journal->close(); }).safe_then([FNAME] { - DEBUG("completed"); + INFO("completed"); return seastar::now(); }); } @@ -157,8 +163,13 @@ TransactionManager::ref_ret TransactionManager::inc_ref( Transaction &t, LogicalCachedExtentRef &ref) { - return lba_manager->incref_extent(t, ref->get_laddr()).si_then([](auto r) { - return r.refcount; + LOG_PREFIX(TransactionManager::inc_ref); + TRACET("{}", t, *ref); + return lba_manager->incref_extent(t, ref->get_laddr() + ).si_then([FNAME, ref, &t](auto result) { + DEBUGT("extent refcount is incremented to {} -- {}", + t, result.refcount, *ref); + return result.refcount; }).handle_error_interruptible( ref_iertr::pass_further{}, ct_error::all_same_way([](auto e) { @@ -170,7 +181,12 @@ TransactionManager::ref_ret TransactionManager::inc_ref( Transaction &t, laddr_t offset) { - return lba_manager->incref_extent(t, offset).si_then([](auto result) { + LOG_PREFIX(TransactionManager::inc_ref); + TRACET("{}", t, offset); + return lba_manager->incref_extent(t, offset + ).si_then([FNAME, offset, &t](auto result) { + DEBUGT("extent refcount is incremented to {} -- {}~{}, {}", + t, result.refcount, offset, result.length, result.addr); return result.refcount; }); } @@ -180,16 +196,15 @@ TransactionManager::ref_ret TransactionManager::dec_ref( LogicalCachedExtentRef &ref) { LOG_PREFIX(TransactionManager::dec_ref); + TRACET("{}", t, *ref); return lba_manager->decref_extent(t, ref->get_laddr() - ).si_then([this, FNAME, &t, ref](auto ret) { - if (ret.refcount == 0) { - DEBUGT( - "extent {} refcount 0", - t, - *ref); + ).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); } - return ret.refcount; + return result.refcount; }); } @@ -198,10 +213,12 @@ TransactionManager::ref_ret TransactionManager::dec_ref( laddr_t offset) { LOG_PREFIX(TransactionManager::dec_ref); + TRACET("{}", 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); if (result.refcount == 0 && !result.addr.is_zero()) { - DEBUGT("offset {} refcount 0", t, offset); return cache->retire_extent_addr( t, result.addr, result.length ).si_then([] { @@ -221,6 +238,8 @@ TransactionManager::refs_ret TransactionManager::dec_ref( Transaction &t, std::vector offsets) { + LOG_PREFIX(TransactionManager::dec_ref); + DEBUG("{} offsets", offsets.size()); return seastar::do_with(std::move(offsets), std::vector(), [this, &t] (auto &&offsets, auto &refcnt) { return trans_intr::do_for_each(offsets.begin(), offsets.end(), @@ -322,6 +341,8 @@ TransactionManager::submit_transaction_direct( seastar::future<> TransactionManager::flush(OrderingHandle &handle) { + LOG_PREFIX(TransactionManager::flush); + SUBDEBUG(seastore_t, "H{} start", (void*)&handle); return handle.enter(write_pipeline.reserve_projected_usage ).then([this, &handle] { return handle.enter(write_pipeline.ool_writes); @@ -330,6 +351,8 @@ seastar::future<> TransactionManager::flush(OrderingHandle &handle) }).then([this, &handle] { handle.maybe_release_collection_lock(); return journal->flush(handle); + }).then([FNAME, &handle] { + SUBDEBUG(seastore_t, "H{} completed", (void*)&handle); }); } @@ -339,6 +362,8 @@ TransactionManager::get_next_dirty_extents( journal_seq_t seq, size_t max_bytes) { + LOG_PREFIX(TransactionManager::get_next_dirty_extents); + DEBUGT("max_bytes={}B, seq={}", t, max_bytes, seq); return cache->get_next_dirty_extents(t, seq, max_bytes); } @@ -349,10 +374,10 @@ TransactionManager::rewrite_logical_extent( { LOG_PREFIX(TransactionManager::rewrite_logical_extent); if (extent->has_been_invalidated()) { - ERRORT("{} has been invalidated", t, *extent); + ERRORT("extent has been invalidated -- {}", t, *extent); ceph_abort(); } - DEBUGT("rewriting {}", t, *extent); + TRACET("rewriting extent -- {}", t, *extent); auto lextent = extent->cast(); cache->retire_extent(t, extent); @@ -368,11 +393,7 @@ TransactionManager::rewrite_logical_extent( nlextent->set_laddr(lextent->get_laddr()); nlextent->set_pin(lextent->get_pin().duplicate()); - DEBUGT( - "rewriting {} into {}", - t, - *lextent, - *nlextent); + DEBUGT("rewriting extent -- {} 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 @@ -393,14 +414,14 @@ TransactionManager::rewrite_extent_ret TransactionManager::rewrite_extent( { auto updated = cache->update_extent_from_transaction(t, extent); if (!updated) { - DEBUGT("{} is already retired, skipping", t, *extent); + DEBUGT("extent is already retired, skipping -- {}", t, *extent); return rewrite_extent_iertr::now(); } extent = updated; } if (extent->get_type() == extent_types_t::ROOT) { - DEBUGT("marking root {} for rewrite", t, *extent); + DEBUGT("marking root for rewrite -- {}", t, *extent); cache->duplicate_for_write(t, extent); return rewrite_extent_iertr::now(); } @@ -408,6 +429,7 @@ TransactionManager::rewrite_extent_ret TransactionManager::rewrite_extent( if (extent->is_logical()) { return rewrite_logical_extent(t, extent->cast()); } else { + DEBUGT("rewriting physical extent -- {}", t, *extent); return lba_manager->rewrite_extent(t, extent); } } @@ -420,12 +442,14 @@ TransactionManager::get_extent_if_live_ret TransactionManager::get_extent_if_liv seastore_off_t len) { LOG_PREFIX(TransactionManager::get_extent_if_live); - DEBUGT("type {}, addr {}, laddr {}, len {}", t, type, addr, laddr, len); + TRACET("{} {}~{} {}", t, type, laddr, len, addr); return cache->get_extent_if_cached(t, addr, type ).si_then([this, FNAME, &t, type, addr, laddr, len](auto extent) -> get_extent_if_live_ret { if (extent) { + DEBUGT("{} {}~{} {} is live in cache -- {}", + t, type, laddr, len, addr, *extent); return get_extent_if_live_ret ( interruptible::ready_future_marker{}, extent); @@ -440,14 +464,16 @@ TransactionManager::get_extent_if_live_ret TransactionManager::get_extent_if_liv if (pin->get_paddr() == addr) { if (pin->get_length() != (extent_len_t)len) { ERRORT( - "Invalid pin laddr {} paddr {} len {} found for " - "extent laddr {} len{}", + "Invalid pin {}~{} {} found for " + "extent {} {}~{} {}", t, pin->get_laddr(), - pin->get_paddr(), pin->get_length(), + pin->get_paddr(), + type, laddr, - len); + len, + addr); ceph_abort(); } return cache->get_extent_by_type( @@ -463,8 +489,14 @@ TransactionManager::get_extent_if_live_ret TransactionManager::get_extent_if_liv assert(!pin->has_been_invalidated()); lref->set_pin(std::move(pin)); lba_manager->add_pin(lref->get_pin()); + }).si_then([=, &t](auto ret) {; + DEBUGT("{} {}~{} {} is live as logical extent -- {}", + t, type, laddr, len, addr, extent); + return ret; }); } else { + DEBUGT("{} {}~{} {} is not live as logical extent", + t, type, laddr, len, addr); return inner_ret( interruptible::ready_future_marker{}, CachedExtentRef()); @@ -473,13 +505,22 @@ TransactionManager::get_extent_if_live_ret TransactionManager::get_extent_if_liv return CachedExtentRef(); }), crimson::ct_error::pass_further_all{}); } else { - DEBUGT("non-logical extent {}", t, addr); return lba_manager->get_physical_extent_if_live( t, type, addr, laddr, - len); + len + ).si_then([=, &t](auto ret) { + if (ret) { + DEBUGT("{} {}~{} {} is live as physical extent -- {}", + t, type, laddr, len, addr, *ret); + } else { + DEBUGT("{} {}~{} {} is not live as physical extent", + t, type, laddr, len, addr); + } + return ret; + }); } }); } diff --git a/src/crimson/os/seastore/transaction_manager.h b/src/crimson/os/seastore/transaction_manager.h index cc3683993130..34f32e39217f 100644 --- a/src/crimson/os/seastore/transaction_manager.h +++ b/src/crimson/os/seastore/transaction_manager.h @@ -34,24 +34,22 @@ class Journal; template auto repeat_eagain(F &&f) { - LOG_PREFIX("repeat_eagain"); return seastar::do_with( std::forward(f), - [FNAME](auto &f) { - return crimson::repeat( - [FNAME, &f] { - return std::invoke(f - ).safe_then([] { - return seastar::stop_iteration::yes; - }).handle_error( - [FNAME](const crimson::ct_error::eagain &e) { - SUBDEBUG(seastore_tm, "hit eagain, restarting"); - return seastar::stop_iteration::no; - }, - crimson::ct_error::pass_further_all{} - ); - }); + [](auto &f) + { + return crimson::repeat([&f] { + return std::invoke(f + ).safe_then([] { + return seastar::stop_iteration::yes; + }).handle_error( + [](const crimson::ct_error::eagain &e) { + return seastar::stop_iteration::no; + }, + crimson::ct_error::pass_further_all{} + ); }); + }); } /** @@ -115,6 +113,8 @@ public: get_pin_ret get_pin( Transaction &t, laddr_t offset) { + LOG_PREFIX(TransactionManager::get_pin); + SUBTRACET(seastore_tm, "{}", t, offset); return lba_manager->get_mapping(t, offset); } @@ -129,6 +129,8 @@ public: Transaction &t, laddr_t offset, extent_len_t length) { + LOG_PREFIX(TransactionManager::get_pins); + SUBDEBUGT(seastore_tm, "{}~{}", t, offset, length); return lba_manager->get_mappings( t, offset, length); } @@ -148,8 +150,8 @@ public: Transaction &t, LBAPinRef pin) { LOG_PREFIX(TransactionManager::pin_to_extent); + SUBTRACET(seastore_tm, "getting extent {}", t, *pin); using ret = pin_to_extent_ret; - SUBDEBUGT(seastore_tm, "getting extent {}", t, *pin); auto &pref = *pin; return cache->get_extent( t, @@ -163,7 +165,7 @@ public: lba_manager->add_pin(extent.get_pin()); } ).si_then([FNAME, &t](auto ref) mutable -> ret { - SUBDEBUGT(seastore_tm, "got extent {}", t, *ref); + SUBTRACET(seastore_tm, "got extent -- {}", t, *ref); return pin_to_extent_ret( interruptible::ready_future_marker{}, std::move(ref)); @@ -186,6 +188,7 @@ public: laddr_t offset, extent_len_t length) { LOG_PREFIX(TransactionManager::read_extent); + SUBTRACET(seastore_tm, "{}~{}", t, offset, length); return get_pin( t, offset ).si_then([this, FNAME, &t, offset, length] (auto pin) { @@ -209,6 +212,7 @@ public: Transaction &t, laddr_t offset) { LOG_PREFIX(TransactionManager::read_extent); + SUBTRACET(seastore_tm, "{}", t, offset); return get_pin( t, offset ).si_then([this, FNAME, &t, offset] (auto pin) { @@ -230,14 +234,14 @@ public: ref)->cast(); if (!ret->has_pin()) { SUBDEBUGT(seastore_tm, - "duplicating {} for write: {}", + "duplicating extent for write -- {} -> {}", t, *ref, *ret); ret->set_pin(ref->get_pin().duplicate()); } else { - SUBDEBUGT(seastore_tm, - "{} already pending", + SUBTRACET(seastore_tm, + "extent is already duplicated -- {}", t, *ref); assert(ref->is_pending()); @@ -297,6 +301,9 @@ public: } else { placement_hint = placement_hint_t::HOT; } + LOG_PREFIX(TransactionManager::alloc_extent); + SUBTRACET(seastore_tm, "{} len={}, placement_hint={}, laddr_hint={}", + t, T::TYPE, len, placement_hint, laddr_hint); auto ext = epm->alloc_new_extent( t, len, @@ -306,8 +313,7 @@ public: laddr_hint, len, ext->get_paddr() - ).si_then([ext=std::move(ext), laddr_hint, &t](auto &&ref) mutable { - LOG_PREFIX(TransactionManager::alloc_extent); + ).si_then([ext=std::move(ext), laddr_hint, &t, FNAME](auto &&ref) mutable { ext->set_pin(std::move(ref)); SUBDEBUGT(seastore_tm, "new extent: {}, laddr_hint: {}", t, *ext, laddr_hint); return alloc_extent_iertr::make_ready_future>( @@ -321,6 +327,8 @@ public: Transaction &t, laddr_t hint, extent_len_t len) { + LOG_PREFIX(TransactionManager::reserve_region); + SUBDEBUGT(seastore_tm, "len={}, laddr_hint={}", t, len, hint); return lba_manager->alloc_extent( t, hint, @@ -340,6 +348,9 @@ public: laddr_t hint, extent_len_t len, int num) { + LOG_PREFIX(TransactionManager::alloc_extents); + SUBDEBUGT(seastore_tm, "len={}, laddr_hint={}, num={}", + t, len, hint, num); return seastar::do_with(std::vector>(), [this, &t, hint, len, num] (auto &extents) { return trans_intr::do_for_each( @@ -402,6 +413,8 @@ public: SegmentCleaner::ExtentCallbackInterface::release_segment_ret; release_segment_ret release_segment( segment_id_t id) final { + LOG_PREFIX(TransactionManager::release_segment); + SUBDEBUG(seastore_tm, "{}", id); return segment_manager.release(id); } @@ -419,12 +432,15 @@ public: const std::string &key) { return cache->get_root( t - ).si_then([&key](auto root) { + ).si_then([&key, &t](auto root) { + LOG_PREFIX(TransactionManager::read_root_meta); auto meta = root->root.get_meta(); auto iter = meta.find(key); if (iter == meta.end()) { + SUBDEBUGT(seastore_tm, "{} -> nullopt", t, key); return seastar::make_ready_future(std::nullopt); } else { + SUBDEBUGT(seastore_tm, "{} -> {}", t, key, iter->second); return seastar::make_ready_future(iter->second); } }); @@ -441,6 +457,8 @@ public: Transaction& t, const std::string& key, const std::string& value) { + LOG_PREFIX(TransactionManager::update_root_meta); + SUBDEBUGT(seastore_tm, "seastore_tm, {} -> {}", t, key, value); return cache->get_root( t ).si_then([this, &t, &key, &value](RootBlockRef root) { @@ -462,8 +480,10 @@ public: using read_onode_root_iertr = base_iertr; using read_onode_root_ret = read_onode_root_iertr::future; read_onode_root_ret read_onode_root(Transaction &t) { - return cache->get_root(t).si_then([](auto croot) { + return cache->get_root(t).si_then([&t](auto croot) { + LOG_PREFIX(TransactionManager::read_onode_root); laddr_t ret = croot->get_root().onode_root; + SUBTRACET(seastore_tm, "{}", t, ret); return ret; }); } @@ -474,6 +494,8 @@ public: * Write onode-tree root logical address, must be called after read. */ void write_onode_root(Transaction &t, laddr_t addr) { + LOG_PREFIX(TransactionManager::write_onode_root); + SUBDEBUGT(seastore_tm, "{}", t, addr); auto croot = cache->get_root_fast(t); croot = cache->duplicate_for_write(t, croot)->cast(); croot->get_root().onode_root = addr; @@ -488,8 +510,12 @@ public: using read_collection_root_ret = read_collection_root_iertr::future< coll_root_t>; read_collection_root_ret read_collection_root(Transaction &t) { - return cache->get_root(t).si_then([](auto croot) { - return croot->get_root().collection_root.get(); + 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, "{}~{}", + t, ret.get_location(), ret.get_size()); + return ret; }); } @@ -499,6 +525,9 @@ public: * Update collection root addr */ void write_collection_root(Transaction &t, coll_root_t cmroot) { + LOG_PREFIX(TransactionManager::write_collection_root); + SUBDEBUGT(seastore_tm, "{}~{}", + t, cmroot.get_location(), cmroot.get_size()); auto croot = cache->get_root_fast(t); croot = cache->duplicate_for_write(t, croot)->cast(); croot->get_root().collection_root.update(cmroot);