From 241a7acf4bfc64f6adf8e3e2aab5bbd894e9f677 Mon Sep 17 00:00:00 2001 From: Xuehan Xu Date: Fri, 3 Sep 2021 23:19:28 +0800 Subject: [PATCH] crimson/os/seastore: better epm output Signed-off-by: Xuehan Xu --- .../os/seastore/extent_placement_manager.cc | 41 +++++++++++++------ .../os/seastore/extent_placement_manager.h | 15 ++++++- .../os/seastore/transaction_manager.cc | 4 +- 3 files changed, 45 insertions(+), 15 deletions(-) diff --git a/src/crimson/os/seastore/extent_placement_manager.cc b/src/crimson/os/seastore/extent_placement_manager.cc index 77ccd1a7e84eb..2f4bb480523dc 100644 --- a/src/crimson/os/seastore/extent_placement_manager.cc +++ b/src/crimson/os/seastore/extent_placement_manager.cc @@ -44,9 +44,10 @@ SegmentedAllocator::Writer::finish_write( ool_record_t& record) { return trans_intr::do_for_each(record.get_extents(), [this, &t](auto& ool_extent) { + LOG_PREFIX(SegmentedAllocator::Writer::finish_write); auto& lextent = ool_extent.get_lextent(); - logger().debug("SegmentedAllocator::Writer::finish_write: " - "extent: {}, ool_paddr: {}", + DEBUGT("extent: {}, ool_paddr: {}", + t, *lextent, ool_extent.get_ool_paddr()); return lba_manager.update_mapping( @@ -74,10 +75,11 @@ SegmentedAllocator::Writer::_write( bufferlist bl = record.encode(current_segment->segment->get_segment_id(), 0); seastar::promise<> pr; current_segment->inflight_writes.emplace_back(pr.get_future()); + LOG_PREFIX(SegmentedAllocator::Writer::_write); - logger().debug( - "SegmentedAllocator::Writer::write: written {} extents," - " {} bytes to segment {} at {}", + DEBUGT( + "written {} extents, {} bytes to segment {} at {}", + t, record.get_num_extents(), bl.length(), current_segment->segment->get_segment_id(), @@ -85,12 +87,15 @@ SegmentedAllocator::Writer::_write( return trans_intr::make_interruptible( current_segment->segment->write(record.get_base(), bl).safe_then( - [this, pr=std::move(pr), + [this, pr=std::move(pr), &t, it=(--current_segment->inflight_writes.end()), cs=current_segment]() mutable { + LOG_PREFIX(SegmentedAllocator::Writer::_write); if (cs->outdated) { + DEBUGT("segment rolled", t); pr.set_value(); } else{ + DEBUGT("segment not rolled", t); current_segment->inflight_writes.erase(it); } return seastar::now(); @@ -131,6 +136,7 @@ SegmentedAllocator::Writer::write( return !rolling_segment; }, [this, &record, &extents, &t]() -> write_iertr::future<> { + LOG_PREFIX(SegmentedAllocator::Writer::write); record.set_base(allocated_to); for (auto it = extents.begin(); it != extents.end();) { @@ -142,8 +148,9 @@ SegmentedAllocator::Writer::write( assert(!rolling_segment); rolling_segment = true; auto num_extents = record.get_num_extents(); - logger().debug( - "SegmentedAllocator::Writer::write: end of segment, writing {} extents to segment {} at {}", + DEBUGT( + "end of segment, writing {} extents to segment {} at {}", + t, num_extents, current_segment->segment->get_segment_id(), allocated_to); @@ -159,8 +166,9 @@ SegmentedAllocator::Writer::write( } record_size_t rsize = record.get_encoded_record_length(); - logger().debug( - "SegmentedAllocator::Writer::write: writing {} extents to segment {} at {}", + DEBUGT( + "writing {} extents to segment {} at {}", + t, record.get_num_extents(), current_segment->segment->get_segment_id(), allocated_to); @@ -222,6 +230,8 @@ SegmentedAllocator::Writer::init_segment(Segment& segment) { SegmentedAllocator::Writer::roll_segment_ertr::future<> SegmentedAllocator::Writer::roll_segment(bool set_rolling) { + LOG_PREFIX(SegmentedAllocator::Writer::roll_segment); + DEBUG("set_rolling {}", set_rolling); if (set_rolling) { rolling_segment = true; } @@ -238,15 +248,16 @@ SegmentedAllocator::Writer::roll_segment(bool set_rolling) { return fut.then( [cs=std::move(current_segment), this, it=(--open_segments.end())] { return cs->segment->close().safe_then([this, cs, it] { + LOG_PREFIX(SegmentedAllocator::Writer::roll_segment); assert((*it).get() == cs.get()); segment_provider.close_segment(cs->segment->get_segment_id()); open_segments.erase(it); + DEBUG("closed segment: {}", cs->segment->get_segment_id()); }); }); }).handle_exception_type([](seastar::gate_closed_exception e) { - logger().debug( - "SegmentedAllocator::Writer::roll_segment:" - " writer_guard closed, should be stopping"); + LOG_PREFIX(SegmentedAllocator::Writer::roll_segment); + DEBUG(" writer_guard closed, should be stopping"); return seastar::now(); }); } @@ -254,13 +265,17 @@ SegmentedAllocator::Writer::roll_segment(bool set_rolling) { return segment_provider.get_segment().safe_then([this](auto segment) { return segment_manager.open(segment); }).safe_then([this](auto segref) { + LOG_PREFIX(SegmentedAllocator::Writer::roll_segment); + DEBUG("opened new segment: {}", segref->get_segment_id()); return init_segment(*segref).safe_then([segref=std::move(segref), this] { + LOG_PREFIX(SegmentedAllocator::Writer::roll_segment); assert(!current_segment.get()); current_segment.reset(new open_segment_wrapper_t()); current_segment->segment = segref; open_segments.emplace_back(current_segment); rolling_segment = false; segment_rotation_guard.broadcast(); + DEBUG("inited new segment: {}", segref->get_segment_id()); }); }).handle_error( roll_segment_ertr::pass_further{}, diff --git a/src/crimson/os/seastore/extent_placement_manager.h b/src/crimson/os/seastore/extent_placement_manager.h index e7cfb8a8abd52..29e590b0d20ff 100644 --- a/src/crimson/os/seastore/extent_placement_manager.h +++ b/src/crimson/os/seastore/extent_placement_manager.h @@ -6,7 +6,7 @@ #include "seastar/core/gate.hh" #include "crimson/common/condition_variable.h" -#include "crimson/common/log.h" +#include "crimson/os/seastore/logging.h" #include "crimson/os/seastore/cache.h" #include "crimson/os/seastore/cached_extent.h" #include "crimson/os/seastore/lba_manager.h" @@ -259,6 +259,8 @@ public: alloc_paddr_iertr::future<> alloc_ool_extents_paddr( Transaction& t, std::list& extents) final { + LOG_PREFIX(SegmentedAllocator::alloc_ool_extents_paddr); + DEBUGT("start", t); return seastar::do_with( std::map>(), [this, extents=std::move(extents), &t](auto& alloc_map) { @@ -355,11 +357,15 @@ public: using alloc_paddr_iertr = ExtentOolWriter::write_iertr; alloc_paddr_iertr::future<> delayed_alloc_or_ool_write( Transaction& t) { + LOG_PREFIX(ExtentPlacementManager::delayed_alloc_or_ool_write); + DEBUGT("start", t); return seastar::do_with( std::map>(), std::list>(), [this, &t](auto& alloc_map, auto& inline_list) mutable { + LOG_PREFIX(ExtentPlacementManager::delayed_alloc_or_ool_write); auto& alloc_list = t.get_delayed_alloc_list(); + uint64_t num_ool_extents = 0; for (auto& extent : alloc_list) { // extents may be invalidated if (!extent->is_valid()) { @@ -373,12 +379,19 @@ public: } auto& allocator_ptr = get_allocator(extent->backend_type, extent->hint); alloc_map[allocator_ptr.get()].emplace_back(extent); + num_ool_extents++; } + DEBUGT("{} inline extents, {} ool extents", + t, + inline_list.size(), + num_ool_extents); return trans_intr::do_for_each(alloc_map, [&t](auto& p) { auto allocator = p.first; auto& extents = p.second; return allocator->alloc_ool_extents_paddr(t, extents); }).si_then([&inline_list, this, &t] { + LOG_PREFIX(ExtentPlacementManager::delayed_alloc_or_ool_write); + DEBUGT("processing {} inline extents", t, inline_list.size()); return trans_intr::do_for_each(inline_list, [this, &t](auto& p) { auto old_addr = p.first; auto& extent = p.second; diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc index 8cc0e0b44a470..df14ed2fb2ad9 100644 --- a/src/crimson/os/seastore/transaction_manager.cc +++ b/src/crimson/os/seastore/transaction_manager.cc @@ -236,13 +236,15 @@ TransactionManager::submit_transaction_direct( Transaction &tref) { LOG_PREFIX(TransactionManager::submit_transaction_direct); - DEBUGT("about to prepare", tref); + DEBUGT("about to alloc delayed extents", tref); return epm->delayed_alloc_or_ool_write(tref) .handle_error_interruptible( crimson::ct_error::input_output_error::pass_further(), crimson::ct_error::assert_all("invalid error") ).si_then([&tref, this] { + LOG_PREFIX(TransactionManager::submit_transaction_direct); + DEBUGT("about to prepare", tref); return tref.get_handle().enter(write_pipeline.prepare); }).si_then([this, FNAME, &tref]() mutable -> submit_transaction_iertr::future<> { -- 2.39.5