diff options
-rw-r--r-- | src/common/subsys.h | 1 | ||||
-rw-r--r-- | src/crimson/os/seastore/cache.cc | 105 | ||||
-rw-r--r-- | src/crimson/os/seastore/cache.h | 12 | ||||
-rw-r--r-- | src/crimson/os/seastore/transaction.h | 5 | ||||
-rw-r--r-- | src/crimson/os/seastore/transaction_manager.cc | 32 |
5 files changed, 104 insertions, 51 deletions
diff --git a/src/common/subsys.h b/src/common/subsys.h index 0667bbd79af..603a3be9c06 100644 --- a/src/common/subsys.h +++ b/src/common/subsys.h @@ -88,6 +88,7 @@ SUBSYS(seastore_onode, 0, 5) SUBSYS(seastore_odata, 0, 5) SUBSYS(seastore_omap, 0, 5) SUBSYS(seastore_tm, 0, 5) // logs below seastore tm +SUBSYS(seastore_t, 0, 5) SUBSYS(seastore_cleaner, 0, 5) SUBSYS(seastore_lba, 0, 5) SUBSYS(seastore_cache, 0, 5) diff --git a/src/crimson/os/seastore/cache.cc b/src/crimson/os/seastore/cache.cc index 3ee1d6ec838..5bb04886464 100644 --- a/src/crimson/os/seastore/cache.cc +++ b/src/crimson/os/seastore/cache.cc @@ -725,16 +725,19 @@ void Cache::invalidate_extent( Transaction& t, CachedExtent& extent) { - LOG_PREFIX(Cache::invalidate); - DEBUGT("conflict begin -- extent {}", t, extent); + LOG_PREFIX(Cache::invalidate_extent); + bool do_conflict_log = true; for (auto &&i: extent.transactions) { if (!i.t->conflicted) { + if (do_conflict_log) { + SUBDEBUGT(seastore_t, "conflict begin -- {}", t, extent); + do_conflict_log = false; + } assert(!i.t->is_weak()); account_conflict(t.get_src(), i.t->get_src()); mark_transaction_conflicted(*i.t, extent); } } - DEBUGT("conflict end", t); extent.state = CachedExtent::extent_state_t::INVALID; } @@ -742,8 +745,8 @@ void Cache::mark_transaction_conflicted( Transaction& t, CachedExtent& conflicting_extent) { LOG_PREFIX(Cache::mark_transaction_conflicted); + SUBTRACET(seastore_t, "", t); assert(!t.conflicted); - DEBUGT("set conflict", t); t.conflicted = true; auto& efforts = get_by_src(stats.invalidated_efforts_by_src, @@ -783,8 +786,8 @@ void Cache::mark_transaction_conflicted( auto& ool_stats = t.get_ool_write_stats(); efforts.fresh_ool_written.increment_stat(ool_stats.extents); efforts.num_ool_records += ool_stats.num_records; - efforts.ool_record_bytes += - (ool_stats.header_bytes + ool_stats.data_bytes); + auto ool_record_bytes = (ool_stats.header_bytes + ool_stats.data_bytes); + efforts.ool_record_bytes += ool_record_bytes; // Note: we only account overhead from committed ool records if (t.get_src() == Transaction::src_t::CLEANER_TRIM || @@ -798,6 +801,16 @@ void Cache::mark_transaction_conflicted( get_by_src(stats.invalidated_lba_tree_efforts, t.get_src() ).increment(t.lba_tree_stats); + + SUBDEBUGT(seastore_t, + "discard {} read, {} fresh, {} delta, {} retire, {}({}B) ool-records", + t, + read_stat, + fresh_stat, + delta_stat, + retire_stat, + ool_stats.num_records, + ool_record_bytes); } else { // read transaction won't have non-read efforts assert(t.retired_set.empty()); @@ -806,23 +819,27 @@ void Cache::mark_transaction_conflicted( assert(t.get_ool_write_stats().is_clear()); assert(t.onode_tree_stats.is_clear()); assert(t.lba_tree_stats.is_clear()); + SUBDEBUGT(seastore_t, "discard {} read", t, read_stat); } } void Cache::on_transaction_destruct(Transaction& t) { LOG_PREFIX(Cache::on_transaction_destruct); + SUBTRACET(seastore_t, "", t); if (t.get_src() == Transaction::src_t::READ && - t.conflicted == false && - !t.is_weak()) { - DEBUGT("read is successful", t); + t.conflicted == false) { io_stat_t read_stat; for (auto &i: t.read_set) { read_stat.increment(i.ref->get_length()); } + SUBDEBUGT(seastore_t, "done {} read", t, read_stat); - ++stats.success_read_efforts.num_trans; - stats.success_read_efforts.read.increment_stat(read_stat); + if (!t.is_weak()) { + // exclude weak transaction as it is impossible to conflict + ++stats.success_read_efforts.num_trans; + stats.success_read_efforts.read.increment_stat(read_stat); + } // read transaction won't have non-read efforts assert(t.retired_set.empty()); @@ -900,7 +917,7 @@ CachedExtentRef Cache::duplicate_for_write( record_t Cache::prepare_record(Transaction &t) { LOG_PREFIX(Cache::prepare_record); - DEBUGT("enter", t); + SUBTRACET(seastore_t, "enter", t); auto trans_src = t.get_src(); assert(!t.is_weak()); @@ -910,15 +927,17 @@ record_t Cache::prepare_record(Transaction &t) trans_src); // Should be valid due to interruptible future + io_stat_t read_stat; for (auto &i: t.read_set) { if (!i.ref->is_valid()) { - DEBUGT("read_set invalid extent: {}, aborting", t, *i.ref); + SUBERRORT(seastore_t, + "read_set got invalid extent, aborting -- {}", t, *i.ref); ceph_abort("no invalid extent allowed in transactions' read_set"); } get_by_ext(efforts.read_by_ext, i.ref->get_type()).increment(i.ref->get_length()); + read_stat.increment(i.ref->get_length()); } - DEBUGT("read_set validated", t); t.read_set.clear(); t.write_set.clear(); @@ -926,16 +945,20 @@ record_t Cache::prepare_record(Transaction &t) // Add new copy of mutated blocks, set_io_wait to block until written record.deltas.reserve(t.mutated_block_list.size()); + io_stat_t delta_stat; for (auto &i: t.mutated_block_list) { if (!i->is_valid()) { - DEBUGT("ignoring invalid {}", t, *i); + DEBUGT("invalid mutated extent -- {}", t, *i); continue; } - DEBUGT("mutating {}", t, *i); + assert(i->prior_instance); + auto delta_bl = i->get_delta(); + auto delta_length = delta_bl.length(); + DEBUGT("mutated extent with {}B delta -- {}, prior={}", + t, delta_length, *i, *i->prior_instance); get_by_ext(efforts.mutate_by_ext, i->get_type()).increment(i->get_length()); - assert(i->prior_instance); commit_replace_extent(t, i, i->prior_instance); i->prepare_write(); @@ -944,9 +967,10 @@ record_t Cache::prepare_record(Transaction &t) assert(i->get_version() > 0); auto final_crc = i->get_crc32c(); if (i->get_type() == extent_types_t::ROOT) { + SUBTRACET(seastore_t, "writing out root delta {}B -- {}", + t, delta_length, *i); assert(t.root == i); root = t.root; - DEBUGT("writing out root delta for {}", t, *t.root); record.push_back( delta_info_t{ extent_types_t::ROOT, @@ -956,7 +980,7 @@ record_t Cache::prepare_record(Transaction &t) 0, 0, t.root->get_version() - 1, - t.root->get_delta() + std::move(delta_bl) }); } else { record.push_back( @@ -970,22 +994,24 @@ record_t Cache::prepare_record(Transaction &t) final_crc, (seastore_off_t)i->get_length(), i->get_version() - 1, - i->get_delta() + std::move(delta_bl) }); i->last_committed_crc = final_crc; } - auto delta_length = record.deltas.back().bl.length(); assert(delta_length); get_by_ext(efforts.delta_bytes_by_ext, i->get_type()) += delta_length; + delta_stat.increment(delta_length); } // Transaction is now a go, set up in-memory cache state // invalidate now invalid blocks + io_stat_t retire_stat; for (auto &i: t.retired_set) { DEBUGT("retiring {}", t, *i); get_by_ext(efforts.retire_by_ext, i->get_type()).increment(i->get_length()); + retire_stat.increment(i->get_length()); commit_retire_extent(t, i); if (i->backend_type == device_type_t::RANDOM_BLOCK) { paddr_t paddr = i->get_paddr(); @@ -997,14 +1023,18 @@ record_t Cache::prepare_record(Transaction &t) } record.extents.reserve(t.inline_block_list.size()); + io_stat_t fresh_stat; + io_stat_t fresh_invalid_stat; for (auto &i: t.inline_block_list) { if (!i->is_valid()) { DEBUGT("fresh inline block (invalid) {}", 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); } + fresh_stat.increment(i->get_length()); get_by_ext(efforts.fresh_inline_by_ext, i->get_type()).increment(i->get_length()); assert(i->is_inline()); @@ -1053,23 +1083,29 @@ record_t Cache::prepare_record(Transaction &t) ceph_assert(ool_stats.extents.num == t.ool_block_list.size()); if (record.is_empty()) { - // XXX: improve osd logic to not submit empty transactions. - DEBUGT("record to submit is empty, src={}!", t, trans_src); + SUBINFOT(seastore_t, + "record to submit is empty, src={}", t, trans_src); assert(t.onode_tree_stats.is_clear()); assert(t.lba_tree_stats.is_clear()); assert(ool_stats.is_clear()); } - DEBUGT("record is ready to submit, src={}, mdsize={}, dsize={}; " - "{} ool records, mdsize={}, dsize={}, fillness={}", - t, trans_src, - record.size.get_raw_mdlength(), - record.size.dlength, - ool_stats.num_records, - ool_stats.header_raw_bytes, - ool_stats.data_bytes, - ((double)(ool_stats.header_raw_bytes + ool_stats.data_bytes) / - (ool_stats.header_bytes + ool_stats.data_bytes))); + SUBDEBUGT(seastore_t, + "commit H{} {} read, {} fresh with {} invalid, {} delta, {} retire, " + "{}(md={}B, data={}B, fill={}) ool-records, {}B md, {}B data", + t, (void*)&t.get_handle(), + read_stat, + fresh_stat, + fresh_invalid_stat, + delta_stat, + retire_stat, + ool_stats.num_records, + ool_stats.header_raw_bytes, + ool_stats.data_bytes, + ((double)(ool_stats.header_raw_bytes + ool_stats.data_bytes) / + (ool_stats.header_bytes + ool_stats.data_bytes)), + record.size.get_raw_mdlength(), + record.size.dlength); if (trans_src == Transaction::src_t::CLEANER_TRIM || trans_src == Transaction::src_t::CLEANER_RECLAIM) { // CLEANER transaction won't contain any onode tree operations @@ -1107,7 +1143,8 @@ void Cache::complete_commit( SegmentCleaner *cleaner) { LOG_PREFIX(Cache::complete_commit); - DEBUGT("enter", t); + SUBTRACET(seastore_t, "final_block_start={}, seq={}", + t, final_block_start, seq); t.for_each_fresh_block([&](auto &i) { if (i->is_inline()) { diff --git a/src/crimson/os/seastore/cache.h b/src/crimson/os/seastore/cache.h index 515d62c698b..0060dd8ad5e 100644 --- a/src/crimson/os/seastore/cache.h +++ b/src/crimson/os/seastore/cache.h @@ -83,6 +83,12 @@ namespace crimson::os::seastore { * CachedExtent::delta_written(paddr_t) with the address of the start * of the record * - Complete all promises with the final record start paddr_t + * + * + * Cache logs + * + * levels: + * - seastore_t logs */ class Cache { public: @@ -111,8 +117,8 @@ public: return on_transaction_destruct(t); } ); - SUBDEBUGT(seastore_cache, "created name={}, source={}, is_weak={}", - *ret, name, src, is_weak); + SUBDEBUGT(seastore_t, "created name={}, source={}, is_weak={}", + *ret, name, src, is_weak); return ret; } @@ -120,10 +126,10 @@ public: void reset_transaction_preserve_handle(Transaction &t) { LOG_PREFIX(Cache::reset_transaction_preserve_handle); if (t.did_reset()) { + SUBTRACET(seastore_t, "reset", t); ++(get_by_src(stats.trans_created_by_src, t.get_src())); } t.reset_preserve_handle(last_commit); - SUBDEBUGT(seastore_cache, "reset", t); } /// Declare ref retired in t diff --git a/src/crimson/os/seastore/transaction.h b/src/crimson/os/seastore/transaction.h index 5f1ee1d31fa..9fe502ab33a 100644 --- a/src/crimson/os/seastore/transaction.h +++ b/src/crimson/os/seastore/transaction.h @@ -45,6 +45,11 @@ inline std::ostream& operator<<(std::ostream& out, const io_stat_t& stat) { * Transaction * * Representation of in-progress mutation. Used exclusively through Cache methods. + * + * Transaction log levels: + * seastore_t + * - DEBUG: transaction create, conflict, commit events + * - TRACE: DEBUG details */ class Transaction { public: diff --git a/src/crimson/os/seastore/transaction_manager.cc b/src/crimson/os/seastore/transaction_manager.cc index 3dfb8977af6..15c6672b5b4 100644 --- a/src/crimson/os/seastore/transaction_manager.cc +++ b/src/crimson/os/seastore/transaction_manager.cc @@ -9,6 +9,12 @@ #include "crimson/os/seastore/segment_manager.h" #include "crimson/os/seastore/journal.h" +/* + * TransactionManager logs + * + * levels: + * - seastore_t logs + */ SET_SUBSYS(seastore_tm); namespace crimson::os::seastore { @@ -239,17 +245,18 @@ TransactionManager::submit_transaction( Transaction &t) { LOG_PREFIX(TransactionManager::submit_transaction); + SUBTRACET(seastore_t, "start", t); return trans_intr::make_interruptible( t.get_handle().enter(write_pipeline.reserve_projected_usage) ).then_interruptible([this, FNAME, &t] { size_t projected_usage = t.get_allocation_size(); - DEBUGT("waiting for projected_usage: {}", t, projected_usage); + SUBTRACET(seastore_t, "waiting for projected_usage: {}", t, projected_usage); return trans_intr::make_interruptible( segment_cleaner->reserve_projected_usage(projected_usage) ).then_interruptible([this, &t] { return submit_transaction_direct(t); }).finally([this, FNAME, projected_usage, &t] { - DEBUGT("releasing projected_usage: {}", t, projected_usage); + SUBTRACET(seastore_t, "releasing projected_usage: {}", t, projected_usage); segment_cleaner->release_projected_usage(projected_usage); }); }); @@ -260,18 +267,18 @@ TransactionManager::submit_transaction_direct( Transaction &tref) { LOG_PREFIX(TransactionManager::submit_transaction_direct); - DEBUGT("about to alloc delayed extents", tref); - + SUBTRACET(seastore_t, "start", tref); return trans_intr::make_interruptible( tref.get_handle().enter(write_pipeline.ool_writes) - ).then_interruptible([this, &tref] { + ).then_interruptible([this, FNAME, &tref] { + SUBTRACET(seastore_t, "process delayed and out-of-line 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([this, FNAME, &tref] { - DEBUGT("about to prepare", tref); + SUBTRACET(seastore_t, "about to prepare", tref); return tref.get_handle().enter(write_pipeline.prepare); }).si_then([this, FNAME, &tref]() mutable -> submit_transaction_iertr::future<> { @@ -279,17 +286,12 @@ TransactionManager::submit_transaction_direct( tref.get_handle().maybe_release_collection_lock(); - DEBUGT("about to submit to journal", tref); - + SUBTRACET(seastore_t, "about to submit to journal", tref); return journal->submit_record(std::move(record), tref.get_handle() ).safe_then([this, FNAME, &tref](auto submit_result) mutable { + SUBDEBUGT(seastore_t, "committed with {}", tref, submit_result); auto start_seq = submit_result.write_result.start_seq; auto end_seq = submit_result.write_result.get_end_seq(); - DEBUGT("journal commit to record_block_base={}, start_seq={}, end_seq={}", - tref, - submit_result.record_block_base, - start_seq, - end_seq); segment_cleaner->set_journal_head(end_seq); cache->complete_commit( tref, @@ -301,6 +303,7 @@ TransactionManager::submit_transaction_direct( cache->get_oldest_dirty_from().value_or(start_seq)); auto to_release = tref.get_segment_to_release(); if (to_release != NULL_SEG_ID) { + SUBDEBUGT(seastore_t, "releasing segment {}", tref, to_release); return segment_manager.release(to_release ).safe_then([this, to_release] { segment_cleaner->mark_segment_released(to_release); @@ -308,7 +311,8 @@ TransactionManager::submit_transaction_direct( } else { return SegmentManager::release_ertr::now(); } - }).safe_then([&tref] { + }).safe_then([FNAME, &tref] { + SUBTRACET(seastore_t, "completed", tref); return tref.get_handle().complete(); }).handle_error( submit_transaction_iertr::pass_further{}, |