From 1dd10f1267e152b6a6f8c26649ce1dfbdf7a4480 Mon Sep 17 00:00:00 2001 From: Samuel Just Date: Thu, 29 Apr 2021 15:15:40 -0700 Subject: [PATCH] crimson/os/seastore: convert cache and transaction_manager to use new debugging macros The goal here is to capture the transaction address and to standardize the prefix format. Signed-off-by: Samuel Just --- src/common/subsys.h | 1 + src/crimson/os/seastore/cache.cc | 98 ++++++++-------- src/crimson/os/seastore/cache.h | 6 + src/crimson/os/seastore/logging.h | 24 ++++ .../os/seastore/transaction_manager.cc | 106 ++++++++---------- src/crimson/os/seastore/transaction_manager.h | 48 ++++---- 6 files changed, 154 insertions(+), 129 deletions(-) create mode 100644 src/crimson/os/seastore/logging.h diff --git a/src/common/subsys.h b/src/common/subsys.h index 958f860f1699d..99cfd4ecb2cd4 100644 --- a/src/common/subsys.h +++ b/src/common/subsys.h @@ -82,3 +82,4 @@ SUBSYS(prioritycache, 1, 5) SUBSYS(test, 0, 5) SUBSYS(cephfs_mirror, 0, 5) SUBSYS(cephsqlite, 0, 5) +SUBSYS(seastore, 0, 5) diff --git a/src/crimson/os/seastore/cache.cc b/src/crimson/os/seastore/cache.cc index ea0fb10b5ddd3..cae26ba3f0010 100644 --- a/src/crimson/os/seastore/cache.cc +++ b/src/crimson/os/seastore/cache.cc @@ -1,8 +1,8 @@ // -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*- // vim: ts=8 sw=2 smarttab +#include "crimson/os/seastore/logging.h" #include "crimson/os/seastore/cache.h" -#include "crimson/common/log.h" // included for get_extent_by_type #include "crimson/os/seastore/collection_manager/collection_flat_node.h" @@ -13,12 +13,6 @@ #include "crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h" #include "test/crimson/seastore/test_block.h" -namespace { - seastar::logger& logger() { - return crimson::get_logger(ceph_subsys_filestore); - } -} - namespace crimson::os::seastore { Cache::Cache(SegmentManager &segment_manager) : @@ -26,8 +20,9 @@ Cache::Cache(SegmentManager &segment_manager) : Cache::~Cache() { + LOG_PREFIX(Cache::~Cache); for (auto &i: extents) { - logger().error("~Cache: extent {} still alive", i); + ERROR("extent {} still alive", i); } ceph_assert(extents.empty()); } @@ -35,8 +30,9 @@ Cache::~Cache() Cache::retire_extent_ret Cache::retire_extent( Transaction &t, paddr_t addr, extent_len_t length) { + LOG_PREFIX(Cache::retire_extent); if (auto ext = t.write_set.find_offset(addr); ext != t.write_set.end()) { - logger().debug("{}: found {} in t.write_set", __func__, addr); + DEBUGT("found {} in t.write_set", t, addr); t.add_to_retired_set(CachedExtentRef(&*ext)); return retire_extent_ertr::now(); } else if (auto iter = extents.find_offset(addr); @@ -54,6 +50,7 @@ Cache::retire_extent_ret Cache::retire_extent( void Cache::add_extent(CachedExtentRef ref) { + LOG_PREFIX(Cache::add_extent); assert(ref->is_valid()); extents.insert(*ref); @@ -62,11 +59,12 @@ void Cache::add_extent(CachedExtentRef ref) } else { ceph_assert(!ref->primary_ref_list_hook.is_linked()); } - logger().debug("add_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; @@ -75,7 +73,7 @@ void Cache::mark_dirty(CachedExtentRef ref) add_to_dirty(ref); ref->state = CachedExtent::extent_state_t::DIRTY; - logger().debug("mark_dirty: {}", *ref); + DEBUG("extent: {}", *ref); } void Cache::add_to_dirty(CachedExtentRef ref) @@ -99,7 +97,8 @@ void Cache::remove_from_dirty(CachedExtentRef ref) void Cache::remove_extent(CachedExtentRef ref) { - logger().debug("remove_extent: {}", *ref); + LOG_PREFIX(Cache::remove_extent); + DEBUG("extent {}", *ref); assert(ref->is_valid()); remove_from_dirty(ref); extents.erase(*ref); @@ -107,7 +106,8 @@ void Cache::remove_extent(CachedExtentRef ref) void Cache::retire_extent(CachedExtentRef ref) { - logger().debug("retire_extent: {}", *ref); + LOG_PREFIX(Cache::retire_extent); + DEBUG("extent {}", *ref); assert(ref->is_valid()); remove_from_dirty(ref); @@ -118,6 +118,8 @@ void Cache::retire_extent(CachedExtentRef ref) void Cache::replace_extent(CachedExtentRef next, CachedExtentRef prev) { + LOG_PREFIX(Cache::replace_extent); + DEBUG("prev {}, next {}", *prev, *next); assert(next->get_paddr() == prev->get_paddr()); assert(next->version == prev->version + 1); extents.replace(*next, *prev); @@ -187,6 +189,7 @@ CachedExtentRef Cache::alloc_new_extent_by_type( CachedExtentRef Cache::duplicate_for_write( Transaction &t, CachedExtentRef i) { + LOG_PREFIX(Cache::duplicate_for_write); if (i->is_pending()) return i; @@ -201,12 +204,15 @@ CachedExtentRef Cache::duplicate_for_write( ret->version++; ret->state = CachedExtent::extent_state_t::MUTATION_PENDING; - logger().debug("Cache::duplicate_for_write: {} -> {}", *i, *ret); + DEBUGT("{} -> {}", t, *i, *ret); return ret; } std::optional Cache::try_construct_record(Transaction &t) { + LOG_PREFIX(Cache::try_construct_record); + DEBUGT("enter", t); + // First, validate read set for (auto &i: t.read_set) { if (i->state == CachedExtent::extent_state_t::INVALID) { @@ -214,6 +220,8 @@ std::optional Cache::try_construct_record(Transaction &t) } } + DEBUGT("read_set validated", t); + record_t record; t.write_set.clear(); @@ -222,10 +230,10 @@ std::optional Cache::try_construct_record(Transaction &t) record.deltas.reserve(t.mutated_block_list.size()); for (auto &i: t.mutated_block_list) { if (!i->is_valid()) { - logger().debug("try_construct_record: ignoring invalid {}", *i); + DEBUGT("ignoring invalid {}", t, *i); continue; } - logger().debug("try_construct_record: mutating {}", *i); + DEBUGT("mutating {}", t, *i); assert(i->prior_instance); replace_extent(i, i->prior_instance); @@ -237,10 +245,7 @@ std::optional Cache::try_construct_record(Transaction &t) auto final_crc = i->get_crc32c(); if (i->get_type() == extent_types_t::ROOT) { root = t.root; - logger().debug( - "{}: writing out root delta for {}", - __func__, - *t.root); + DEBUGT("writing out root delta for {}", t, *t.root); record.deltas.push_back( delta_info_t{ extent_types_t::ROOT, @@ -273,7 +278,7 @@ std::optional Cache::try_construct_record(Transaction &t) // Transaction is now a go, set up in-memory cache state // invalidate now invalid blocks for (auto &i: t.retired_set) { - logger().debug("try_construct_record: retiring {}", *i); + DEBUGT("retiring {}", t, *i); retire_extent(i); } @@ -295,7 +300,7 @@ std::optional Cache::try_construct_record(Transaction &t) record.extents.reserve(t.fresh_block_list.size()); for (auto &i: t.fresh_block_list) { - logger().debug("try_construct_record: fresh block {}", *i); + DEBUGT("fresh block {}", t, *i); bufferlist bl; i->prepare_write(); bl.append(i->get_bptr()); @@ -322,18 +327,21 @@ void Cache::complete_commit( journal_seq_t seq, SegmentCleaner *cleaner) { + LOG_PREFIX(Cache::complete_commit); + DEBUGT("enter", t); + for (auto &i: t.fresh_block_list) { i->set_paddr(final_block_start.add_relative(i->get_paddr())); i->last_committed_crc = i->get_crc32c(); i->on_initial_write(); if (!i->is_valid()) { - logger().debug("complete_commit: invalid {}", *i); + DEBUGT("invalid {}", t, *i); continue; } i->state = CachedExtent::extent_state_t::CLEAN; - logger().debug("complete_commit: fresh {}", *i); + DEBUGT("fresh {}", t, *i); add_extent(i); if (cleaner) { cleaner->mark_space_used( @@ -344,12 +352,12 @@ void Cache::complete_commit( // Add new copy of mutated blocks, set_io_wait to block until written for (auto &i: t.mutated_block_list) { - logger().debug("complete_commit: mutated {}", *i); + DEBUGT("mutated {}", t, *i); assert(i->prior_instance); i->on_delta_write(final_block_start); i->prior_instance = CachedExtentRef(); if (!i->is_valid()) { - logger().debug("complete_commit: not dirtying invalid {}", *i); + DEBUGT("not dirtying invalid {}", t, *i); continue; } i->state = CachedExtent::extent_state_t::DIRTY; @@ -372,7 +380,7 @@ void Cache::complete_commit( last_commit = seq; for (auto &i: t.retired_set) { - logger().debug("try_construct_record: retiring {}", *i); + DEBUGT("retiring {}", t, *i); i->dirty_from_or_retired_at = last_commit; } @@ -420,8 +428,9 @@ Cache::replay_delta( paddr_t record_base, const delta_info_t &delta) { + LOG_PREFIX(Cache::replay_delta); if (delta.type == extent_types_t::ROOT) { - logger().debug("replay_delta: found root delta"); + DEBUG("found root delta"); remove_extent(root); root->apply_delta_and_adjust_crc(record_base, delta.bl); root->dirty_from_or_retired_at = journal_seq; @@ -454,16 +463,13 @@ Cache::replay_delta( return extent_fut.safe_then([=, &delta](auto extent) { if (!extent) { assert(delta.pversion > 0); - logger().debug( - "replay_delta: replaying {}, extent not present so delta is obsolete", + DEBUG( + "replaying {}, extent not present so delta is obsolete", delta); return; } - logger().debug( - "replay_delta: replaying {} on {}", - *extent, - delta); + DEBUG("replaying {} on {}", *extent, delta); assert(extent->version == delta.pversion); @@ -484,6 +490,7 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents( journal_seq_t seq, size_t max_bytes) { + LOG_PREFIX(Cache::get_next_dirty_extents); std::vector ret; size_t bytes_so_far = 0; for (auto i = dirty.begin(); @@ -491,15 +498,10 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents( ++i) { CachedExtentRef cand; if (i->get_dirty_from() != journal_seq_t() && i->get_dirty_from() < seq) { - logger().debug( - "Cache::get_next_dirty_extents: next {}", - *i); + DEBUG("next {}", *i); if (!(ret.empty() || ret.back()->get_dirty_from() <= i->get_dirty_from())) { - logger().debug( - "Cache::get_next_dirty_extents: last {}, next {}", - *ret.back(), - *i); + DEBUG("last {}, next {}", *ret.back(), *i); } assert(ret.empty() || ret.back()->get_dirty_from() <= i->get_dirty_from()); bytes_so_far += i->get_length(); @@ -510,13 +512,11 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents( } return seastar::do_with( std::move(ret), - [](auto &ret) { + [FNAME](auto &ret) { return seastar::do_for_each( ret, - [](auto &ext) { - logger().debug( - "get_next_dirty_extents: waiting on {}", - *ext); + [FNAME](auto &ext) { + DEBUG("waiting on {}", *ext); return ext->wait_io(); }).then([&ret]() mutable { return seastar::make_ready_future>( @@ -527,13 +527,17 @@ Cache::get_next_dirty_extents_ret Cache::get_next_dirty_extents( 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); return get_root_ret( get_root_ertr::ready_future_marker{}, t.root); } else { auto ret = root; - return ret->wait_io().then([ret, &t] { + DEBUGT("waiting root {}", t, *ret); + return ret->wait_io().then([FNAME, ret, &t] { + DEBUGT("got root read {}", t, *ret); t.root = ret; t.add_to_read_set(ret); return get_root_ret( diff --git a/src/crimson/os/seastore/cache.h b/src/crimson/os/seastore/cache.h index bdfbb2e223bbd..d8fc5bed62201 100644 --- a/src/crimson/os/seastore/cache.h +++ b/src/crimson/os/seastore/cache.h @@ -8,6 +8,8 @@ #include "seastar/core/shared_future.hh" #include "include/buffer.h" + +#include "crimson/os/seastore/logging.h" #include "crimson/os/seastore/seastore_types.h" #include "crimson/os/seastore/transaction.h" #include "crimson/os/seastore/segment_manager.h" @@ -94,23 +96,27 @@ public: /// Creates empty transaction TransactionRef create_transaction() { + LOG_PREFIX(Cache::create_transaction); auto ret = std::make_unique( get_dummy_ordering_handle(), false, last_commit ); retired_extent_gate.add_token(ret->retired_gate_token); + DEBUGT("created", *ret); return ret; } /// Creates empty weak transaction TransactionRef create_weak_transaction() { + LOG_PREFIX(Cache::create_weak_transaction); auto ret = std::make_unique( get_dummy_ordering_handle(), true, last_commit ); retired_extent_gate.add_token(ret->retired_gate_token); + DEBUGT("created", *ret); return ret; } diff --git a/src/crimson/os/seastore/logging.h b/src/crimson/os/seastore/logging.h new file mode 100644 index 0000000000000..68805b03c7482 --- /dev/null +++ b/src/crimson/os/seastore/logging.h @@ -0,0 +1,24 @@ +// -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*- +// vim: ts=8 sw=2 smarttab + +#pragma once + +#include "crimson/common/log.h" + +#define LOGGER crimson::get_logger(ceph_subsys_seastore) +#define LOG_PREFIX(x) constexpr auto FNAME = #x + +#define LOG(LEVEL, MSG, ...) LOGGER . LEVEL("{}: " MSG, FNAME __VA_OPT__(,) __VA_ARGS__) +#define LOGT(LEVEL, MSG, t, ...) LOGGER . LEVEL("{}({}): " MSG, FNAME, (void*)&t __VA_OPT__(,) __VA_ARGS__) + +#define TRACE(...) LOG(trace, __VA_ARGS__) +#define TRACET(...) LOGT(trace, __VA_ARGS__) + +#define DEBUG(...) LOG(debug, __VA_ARGS__) +#define DEBUGT(...) LOGT(debug, __VA_ARGS__) + +#define WARN(...) LOG(warn, __VA_ARGS__) +#define WARNT(...) LOGT(warn, __VA_ARGS__) + +#define ERROR(...) LOG(error, __VA_ARGS__) +#define ERRORT(...) LOGT(error, __VA_ARGS__) diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc index 1c5e195bd1305..fa6c14f343037 100644 --- a/src/crimson/os/seastore/transaction_manager.cc +++ b/src/crimson/os/seastore/transaction_manager.cc @@ -4,18 +4,11 @@ #include "include/denc.h" #include "include/intarith.h" -#include "crimson/common/log.h" - +#include "crimson/os/seastore/logging.h" #include "crimson/os/seastore/transaction_manager.h" #include "crimson/os/seastore/segment_manager.h" #include "crimson/os/seastore/journal.h" -namespace { - seastar::logger& logger() { - return crimson::get_logger(ceph_subsys_filestore); - } -} - namespace crimson::os::seastore { TransactionManager::TransactionManager( @@ -36,19 +29,22 @@ TransactionManager::TransactionManager( TransactionManager::mkfs_ertr::future<> TransactionManager::mkfs() { - return journal->open_for_write().safe_then([this](auto addr) { - logger().debug("TransactionManager::mkfs: about to do_with"); + LOG_PREFIX(TransactionManager::mkfs); + return journal->open_for_write().safe_then([this, FNAME](auto addr) { + DEBUG("TransactionManager::mkfs: about to do_with"); segment_cleaner->init_mkfs(addr); return seastar::do_with( create_transaction(), - [this](auto &transaction) { - logger().debug("TransactionManager::mkfs: about to cache->mkfs"); + [this, FNAME](auto &transaction) { + DEBUGT( + "about to cache->mkfs", + *transaction); cache->init(); return cache->mkfs(*transaction ).safe_then([this, &transaction] { return lba_manager->mkfs(*transaction); - }).safe_then([this, &transaction] { - logger().debug("TransactionManager::mkfs: about to submit_transaction"); + }).safe_then([this, FNAME, &transaction] { + DEBUGT("about to submit_transaction", *transaction); return submit_transaction_direct(std::move(transaction)).handle_error( crimson::ct_error::eagain::handle([] { ceph_assert(0 == "eagain impossible"); @@ -65,31 +61,34 @@ TransactionManager::mkfs_ertr::future<> TransactionManager::mkfs() TransactionManager::mount_ertr::future<> TransactionManager::mount() { + LOG_PREFIX(TransactionManager::mount); cache->init(); return journal->replay([this](auto seq, auto paddr, const auto &e) { return cache->replay_delta(seq, paddr, e); }).safe_then([this] { return journal->open_for_write(); - }).safe_then([this](auto addr) { + }).safe_then([this, FNAME](auto addr) { segment_cleaner->set_journal_head(addr); return seastar::do_with( create_weak_transaction(), - [this](auto &t) { + [this, FNAME](auto &t) { return cache->init_cached_extents(*t, [this](auto &t, auto &e) { return lba_manager->init_cached_extent(t, e); - }).safe_then([this, &t] { + }).safe_then([this, FNAME, &t] { assert(segment_cleaner->debug_check_space( *segment_cleaner->get_empty_space_tracker())); return lba_manager->scan_mapped_space( *t, - [this](paddr_t addr, extent_len_t len) { - logger().trace("TransactionManager::mount: marking {}~{} used", - addr, - len); - segment_cleaner->mark_space_used( - addr, - len , - /* init_scan = */ true); + [this, FNAME, &t](paddr_t addr, extent_len_t len) { + TRACET( + "marking {}~{} used", + t, + addr, + len); + segment_cleaner->mark_space_used( + addr, + len , + /* init_scan = */ true); }); }); }); @@ -138,11 +137,13 @@ TransactionManager::ref_ret TransactionManager::dec_ref( Transaction &t, LogicalCachedExtentRef &ref) { + LOG_PREFIX(TransactionManager::dec_ref); return lba_manager->decref_extent(t, ref->get_laddr() - ).safe_then([this, &t, ref](auto ret) { + ).safe_then([this, FNAME, &t, ref](auto ret) { if (ret.refcount == 0) { - logger().debug( - "TransactionManager::dec_ref: extent {} refcount 0", + DEBUGT( + "extent {} refcount 0", + t, *ref); cache->retire_extent(t, ref); } @@ -154,12 +155,11 @@ TransactionManager::ref_ret TransactionManager::dec_ref( Transaction &t, laddr_t offset) { + LOG_PREFIX(TransactionManager::dec_ref); return lba_manager->decref_extent(t, offset - ).safe_then([this, offset, &t](auto result) -> ref_ret { + ).safe_then([this, FNAME, offset, &t](auto result) -> ref_ret { if (result.refcount == 0 && !result.addr.is_zero()) { - logger().debug( - "TransactionManager::dec_ref: offset {} refcount 0", - offset); + DEBUGT("offset {} refcount 0", t, offset); return cache->retire_extent( t, result.addr, result.length ).safe_then([] { @@ -197,7 +197,8 @@ TransactionManager::submit_transaction_ertr::future<> TransactionManager::submit_transaction( TransactionRef t) { - logger().debug("TransactionManager::submit_transaction"); + LOG_PREFIX(TransactionManager::submit_transaction); + DEBUGT("about to await throttle", *t); auto &tref = *t; return tref.handle.enter(write_pipeline.wait_throttle ).then([this] { @@ -211,21 +212,24 @@ TransactionManager::submit_transaction_direct_ret TransactionManager::submit_transaction_direct( TransactionRef t) { - logger().debug("TransactionManager::submit_transaction_direct"); + LOG_PREFIX(TransactionManager::submit_transaction_direct); + DEBUGT("about to prepare", *t); auto &tref = *t; return tref.handle.enter(write_pipeline.prepare - ).then([this, &tref]() mutable + ).then([this, FNAME, &tref]() mutable -> submit_transaction_ertr::future<> { auto record = cache->try_construct_record(tref); if (!record) { - logger().debug("TransactionManager::submit_transaction_direct: " - "conflict detected, returning eagain."); + DEBUGT("conflict detected, returning eagain.", tref); return crimson::ct_error::eagain::make(); } + DEBUGT("about to submit to journal", tref); + return journal->submit_record(std::move(*record), tref.handle - ).safe_then([this, &tref](auto p) mutable { + ).safe_then([this, FNAME, &tref](auto p) mutable { auto [addr, journal_seq] = p; + DEBUGT("journal commit to {} seq {}", tref, addr, journal_seq); segment_cleaner->set_journal_head(journal_seq); cache->complete_commit(tref, addr, journal_seq, segment_cleaner.get()); lba_manager->complete_transaction(tref); @@ -264,23 +268,18 @@ TransactionManager::rewrite_extent_ret TransactionManager::rewrite_extent( Transaction &t, CachedExtentRef extent) { + LOG_PREFIX(TransactionManager::rewrite_extent); { auto updated = cache->update_extent_from_transaction(t, extent); if (!updated) { - logger().debug( - "{}: {} is already retired, skipping", - __func__, - *extent); + DEBUGT("{} is already retired, skipping", t, *extent); return rewrite_extent_ertr::now(); } extent = updated; } if (extent->get_type() == extent_types_t::ROOT) { - logger().debug( - "{}: marking root {} for rewrite", - __func__, - *extent); + DEBUGT("marking root {} for rewrite", t, *extent); cache->duplicate_for_write(t, extent); return rewrite_extent_ertr::now(); } @@ -294,16 +293,11 @@ TransactionManager::get_extent_if_live_ret TransactionManager::get_extent_if_liv laddr_t laddr, segment_off_t len) { - logger().debug( - "TransactionManager::get_extent_if_live:" - " type {}, addr {}, laddr {}, len {}", - type, - addr, - laddr, - len); + LOG_PREFIX(TransactionManager::get_extent_if_live); + DEBUGT("type {}, addr {}, laddr {}, len {}", t, type, addr, laddr, len); return cache->get_extent_if_cached(t, addr - ).then([this, &t, type, addr, laddr, len](auto extent) + ).then([this, FNAME, &t, type, addr, laddr, len](auto extent) -> get_extent_if_live_ret { if (extent) { return get_extent_if_live_ret( @@ -357,9 +351,7 @@ TransactionManager::get_extent_if_live_ret TransactionManager::get_extent_if_liv } }); } else { - logger().debug( - "TransactionManager::get_extent_if_live: non-logical extent {}", - addr); + DEBUGT("non-logical extent {}", t, addr); return lba_manager->get_physical_extent_if_live( t, type, diff --git a/src/crimson/os/seastore/transaction_manager.h b/src/crimson/os/seastore/transaction_manager.h index 68736657f09a2..afbf69fe84c65 100644 --- a/src/crimson/os/seastore/transaction_manager.h +++ b/src/crimson/os/seastore/transaction_manager.h @@ -20,6 +20,7 @@ #include "crimson/osd/exceptions.h" +#include "crimson/os/seastore/logging.h" #include "crimson/os/seastore/segment_cleaner.h" #include "crimson/os/seastore/seastore_types.h" #include "crimson/os/seastore/cache.h" @@ -32,16 +33,18 @@ class Journal; template auto repeat_eagain(F &&f) { + LOG_PREFIX("repeat_eagain"); return seastar::do_with( std::forward(f), - [](auto &f) { + [FNAME](auto &f) { return crimson::do_until( - [&f] { + [FNAME, &f] { return std::invoke(f ).safe_then([] { return true; }).handle_error( - [](const crimson::ct_error::eagain &e) { + [FNAME](const crimson::ct_error::eagain &e) { + DEBUG("hit eagain, restarting"); return seastar::make_ready_future(false); }, crimson::ct_error::pass_further_all{} @@ -124,15 +127,14 @@ public: pin_to_extent_ret pin_to_extent( Transaction &t, LBAPinRef pin) { + LOG_PREFIX(TransactionManager::pin_to_extent); using ret = pin_to_extent_ret; - crimson::get_logger(ceph_subsys_filestore).debug( - "pin_to_extent: getting extent {}", - *pin); + DEBUGT("getting extent {}", t, *pin); return cache->get_extent( t, pin->get_paddr(), pin->get_length() - ).safe_then([this, pin=std::move(pin)](auto ref) mutable -> ret { + ).safe_then([this, FNAME, &t, pin=std::move(pin)](auto ref) mutable -> ret { if (!ref->has_pin()) { if (pin->has_been_invalidated() || ref->has_been_invalidated()) { return crimson::ct_error::eagain::make(); @@ -141,9 +143,7 @@ public: lba_manager->add_pin(ref->get_pin()); } } - crimson::get_logger(ceph_subsys_filestore).debug( - "pin_to_extent: got extent {}", - *ref); + DEBUGT("got extent {}", t, *ref); return pin_to_extent_ret( pin_to_extent_ertr::ready_future_marker{}, std::move(ref)); @@ -165,18 +165,16 @@ public: Transaction &t, laddr_t offset, extent_len_t length) { + LOG_PREFIX(TransactionManager::read_extent); return get_pins( t, offset, length - ).safe_then([this, &t, offset, length](auto pins) { + ).safe_then([this, FNAME, &t, offset, length](auto pins) { if (pins.size() != 1 || !pins.front()->get_paddr().is_real()) { - auto &logger = crimson::get_logger(ceph_subsys_filestore); - logger.error( - "TransactionManager::read_extent offset {} len {} got {} extents:", - offset, - length, - pins.size()); + ERRORT( + "offset {} len {} got {} extents:", + t, offset, length, pins.size()); for (auto &i: pins) { - logger.error("\t{}", *i); + ERRORT("\t{}", t, *i); } ceph_assert(0 == "Should be impossible"); } @@ -186,21 +184,21 @@ public: /// Obtain mutable copy of extent LogicalCachedExtentRef get_mutable_extent(Transaction &t, LogicalCachedExtentRef ref) { - auto &logger = crimson::get_logger(ceph_subsys_filestore); + LOG_PREFIX(TransactionManager::get_mutable_extent); auto ret = cache->duplicate_for_write( t, ref)->cast(); if (!ret->has_pin()) { - logger.debug( - "{}: duplicating {} for write: {}", - __func__, + DEBUGT( + "duplicating {} for write: {}", + t, *ref, *ret); ret->set_pin(ref->get_pin().duplicate()); } else { - logger.debug( - "{}: {} already pending", - __func__, + DEBUGT( + "{} already pending", + t, *ref); assert(ref->is_pending()); assert(&*ref == &*ret); -- 2.39.5