From: Yingxin Cheng Date: Sat, 29 Jan 2022 11:13:12 +0000 (+0800) Subject: crimson/os/seastore: misc log improvements X-Git-Tag: v18.0.0~1401^2 X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=cc5619ff105f8a826bbb7830d9f1d7ebc7049f7e;p=ceph.git crimson/os/seastore: misc log improvements Signed-off-by: Yingxin Cheng --- diff --git a/src/crimson/os/seastore/cache.cc b/src/crimson/os/seastore/cache.cc index 5a711a1b45c8..b9d62693cc1e 100644 --- a/src/crimson/os/seastore/cache.cc +++ b/src/crimson/os/seastore/cache.cc @@ -84,12 +84,13 @@ 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); ext->set_paddr(addr); ext->state = CachedExtent::extent_state_t::CLEAN; + DEBUGT("retire {}~{} as placeholder, add extent -- {}", + t, addr, length, *ext); add_extent(ext); } @@ -624,8 +625,6 @@ 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()) { @@ -670,8 +669,6 @@ void Cache::remove_from_dirty(CachedExtentRef ref) void Cache::remove_extent(CachedExtentRef ref) { - LOG_PREFIX(Cache::remove_extent); - TRACE("extent -- {}", *ref); assert(ref->is_valid()); if (ref->is_dirty()) { remove_from_dirty(ref); @@ -958,13 +955,13 @@ record_t Cache::prepare_record(Transaction &t) continue; } 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()); + auto delta_bl = i->get_delta(); + auto delta_length = delta_bl.length(); + DEBUGT("mutated extent with {}B delta, commit replace extent ... -- {}, prior={}", + t, delta_length, *i, *i->prior_instance); commit_replace_extent(t, i, i->prior_instance); i->prepare_write(); @@ -1014,10 +1011,10 @@ record_t Cache::prepare_record(Transaction &t) // invalidate now invalid blocks io_stat_t retire_stat; for (auto &i: t.retired_set) { - 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()); + DEBUGT("retired and remove extent -- {}", t, *i); commit_retire_extent(t, i); // FIXME: whether the extent belongs to RBM should be available through its // device-id from its paddr after RBM is properly integrated. @@ -1042,7 +1039,7 @@ record_t Cache::prepare_record(Transaction &t) get_by_ext(efforts.fresh_invalid_by_ext, i->get_type()).increment(i->get_length()); } else { - DEBUGT("fresh inline extent -- {}", t, *i); + TRACET("fresh inline extent -- {}", t, *i); } fresh_stat.increment(i->get_length()); get_by_ext(efforts.fresh_inline_by_ext, @@ -1078,8 +1075,9 @@ record_t Cache::prepare_record(Transaction &t) } for (auto &i: t.ool_block_list) { + TRACET("fresh ool extent -- {}", t, *i); ceph_assert(i->is_valid()); - DEBUGT("fresh ool extent -- {}", t, *i); + assert(!i->is_inline()); get_by_ext(efforts.fresh_ool_by_ext, i->get_type()).increment(i->get_length()); } @@ -1101,9 +1099,11 @@ record_t Cache::prepare_record(Transaction &t) } SUBDEBUGT(seastore_t, - "commit H{} {} read, {} fresh with {} invalid, {} delta, {} retire, " - "{}(md={}B, data={}B, fill={}) ool-records, {}B md, {}B data", + "commit H{} dirty_from={}, {} read, {} fresh with {} invalid, " + "{} delta, {} retire, {}(md={}B, data={}B, fill={}) ool-records, " + "{}B md, {}B data", t, (void*)&t.get_handle(), + get_oldest_dirty_from().value_or(journal_seq_t{}), read_stat, fresh_stat, fresh_invalid_stat, @@ -1157,7 +1157,9 @@ void Cache::complete_commit( t, final_block_start, seq); t.for_each_fresh_block([&](auto &i) { + bool is_inline = false; if (i->is_inline()) { + is_inline = true; i->set_paddr(final_block_start.add_relative(i->get_paddr())); } i->last_committed_crc = i->get_crc32c(); @@ -1165,6 +1167,8 @@ void Cache::complete_commit( if (i->is_valid()) { i->state = CachedExtent::extent_state_t::CLEAN; + DEBUGT("add extent as fresh, inline={} -- {}", + t, is_inline, *i); add_extent(i); if (cleaner) { cleaner->mark_space_used( @@ -1183,8 +1187,12 @@ void Cache::complete_commit( i->on_delta_write(final_block_start); i->prior_instance = CachedExtentRef(); i->state = CachedExtent::extent_state_t::DIRTY; + assert(i->version > 0); if (i->version == 1 || i->get_type() == extent_types_t::ROOT) { i->dirty_from_or_retired_at = seq; + DEBUGT("commit extent done, become dirty -- {}", t, *i); + } else { + DEBUGT("commit extent done -- {}", t, *i); } } @@ -1212,14 +1220,15 @@ void Cache::complete_commit( 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 + DEBUG("remove extent -- prv_root={}", *root); remove_extent(root); root = nullptr; } root = new RootBlock(); root->state = CachedExtent::extent_state_t::CLEAN; + INFO("init root -- {}", *root); extents.insert(*root); } @@ -1269,11 +1278,14 @@ Cache::replay_delta( { LOG_PREFIX(Cache::replay_delta); if (delta.type == extent_types_t::ROOT) { - DEBUG("replay root delta {} at {} {}", delta, journal_seq, record_base); + TRACE("replay root delta at {} {}, remove extent ... -- {}, prv_root={}", + journal_seq, record_base, delta, *root); remove_extent(root); root->apply_delta_and_adjust_crc(record_base, delta.bl); root->dirty_from_or_retired_at = journal_seq; root->state = CachedExtent::extent_state_t::DIRTY; + DEBUG("replayed root delta at {} {}, add extent -- {}, root={}", + journal_seq, record_base, delta, *root); add_extent(root); return replay_delta_ertr::now(); } else { @@ -1311,14 +1323,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); + DEBUG("replay extent is not present, so delta is obsolete at {} {} -- {}", + journal_seq, record_base, delta); assert(delta.pversion > 0); return; } - DEBUG("replay extent delta {} at {} {} -- {} ...", - delta, journal_seq, record_base, *extent); + TRACE("replay extent delta at {} {} ... -- {}, prv_extent={}", + journal_seq, record_base, delta, *extent); assert(extent->version == delta.pversion); @@ -1326,10 +1338,15 @@ Cache::replay_delta( extent->apply_delta_and_adjust_crc(record_base, delta.bl); assert(extent->last_committed_crc == delta.final_crc); - if (extent->version == 0) { + extent->version++; + if (extent->version == 1) { extent->dirty_from_or_retired_at = journal_seq; + DEBUG("replayed extent delta at {} {}, become dirty -- {}, extent={}" , + journal_seq, record_base, delta, *extent); + } else { + DEBUG("replayed extent delta at {} {} -- {}, extent={}" , + journal_seq, record_base, delta, *extent); } - extent->version++; mark_dirty(extent); }); } diff --git a/src/crimson/os/seastore/cache.h b/src/crimson/os/seastore/cache.h index 2d7042bd643a..cc6e48648af1 100644 --- a/src/crimson/os/seastore/cache.h +++ b/src/crimson/os/seastore/cache.h @@ -191,12 +191,13 @@ public: 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); ret->state = CachedExtent::extent_state_t::CLEAN_PENDING; + SUBDEBUG(seastore_cache, + "{} {}~{} is absent, add extent and reading ... -- {}", + T::TYPE, offset, length, *ret); add_extent(ret); extent_init_func(*ret); return read_extent( @@ -205,13 +206,13 @@ 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); ret->state = CachedExtent::extent_state_t::CLEAN_PENDING; + SUBDEBUG(seastore_cache, + "{} {}~{} is absent(placeholder), reading ... -- {}", + T::TYPE, offset, length, *ret); extents.replace(*ret, *cached); // replace placeholder in transactions @@ -640,7 +641,7 @@ public: return f(t, e ).si_then([this, FNAME, &t, e](bool is_alive) { if (!is_alive) { - SUBDEBUGT(seastore_cache, "extent is not alive, remove -- {}", t, *e); + SUBDEBUGT(seastore_cache, "extent is not alive, remove extent -- {}", t, *e); remove_extent(e); } else { SUBDEBUGT(seastore_cache, "extent is alive -- {}", t, *e); diff --git a/src/crimson/os/seastore/extent_reader.cc b/src/crimson/os/seastore/extent_reader.cc index 15ca6cad765a..0baaa12c9445 100644 --- a/src/crimson/os/seastore/extent_reader.cc +++ b/src/crimson/os/seastore/extent_reader.cc @@ -114,6 +114,7 @@ ExtentReader::scan_valid_records_ret ExtentReader::scan_valid_records( auto& segment_manager = *segment_managers[cursor.get_segment_id().device_id()]; if (cursor.get_segment_offset() == 0) { + INFO("start to scan segment {}", cursor.get_segment_id()); cursor.increment_seq(segment_manager.get_block_size()); } DEBUG("starting at {}, budget={}", cursor, budget); diff --git a/src/crimson/os/seastore/journal.cc b/src/crimson/os/seastore/journal.cc index dd2bd28ca562..acba0e3ce411 100644 --- a/src/crimson/os/seastore/journal.cc +++ b/src/crimson/os/seastore/journal.cc @@ -194,6 +194,7 @@ Journal::replay_segment( record_deltas.deltas, [locator, this, + FNAME, &handler](delta_info_t& delta) { /* The journal may validly contain deltas for extents in @@ -211,6 +212,11 @@ Journal::replay_segment( if (delta_paddr_segment_type == segment_type_t::NULL_SEG || (delta_paddr_segment_type == segment_type_t::JOURNAL && delta_paddr_segment_seq > locator_segment_seq)) { + SUBDEBUG(seastore_cache, + "delta is obsolete, delta_paddr_segment_seq={}, locator_segment_seq={} -- {}", + segment_seq_printer_t{delta_paddr_segment_seq}, + segment_seq_printer_t{locator_segment_seq}, + delta); return replay_ertr::now(); } } diff --git a/src/crimson/os/seastore/segment_cleaner.cc b/src/crimson/os/seastore/segment_cleaner.cc index 846bb72b24c4..8b87dc97f71c 100644 --- a/src/crimson/os/seastore/segment_cleaner.cc +++ b/src/crimson/os/seastore/segment_cleaner.cc @@ -283,6 +283,7 @@ SegmentCleaner::rewrite_dirty_ret SegmentCleaner::rewrite_dirty( limit, config.journal_rewrite_per_cycle ).si_then([=, &t](auto dirty_list) { + DEBUGT("rewrite {} dirty extents", t, dirty_list.size()); return seastar::do_with( std::move(dirty_list), [FNAME, this, &t](auto &dirty_list) {