From cdf9db2398259fd924f956c642f2cf44a2f70cf5 Mon Sep 17 00:00:00 2001 From: Yingxin Cheng Date: Fri, 29 Jul 2022 13:31:08 +0800 Subject: [PATCH] crimson/os/seastore/async_cleaner: improve log gc status Signed-off-by: Yingxin Cheng --- src/crimson/os/seastore/async_cleaner.cc | 145 +++++++++++------------ src/crimson/os/seastore/async_cleaner.h | 29 +++-- 2 files changed, 92 insertions(+), 82 deletions(-) diff --git a/src/crimson/os/seastore/async_cleaner.cc b/src/crimson/os/seastore/async_cleaner.cc index 7b31b8288e8ea..4c9d703ec2536 100644 --- a/src/crimson/os/seastore/async_cleaner.cc +++ b/src/crimson/os/seastore/async_cleaner.cc @@ -318,6 +318,23 @@ void segments_info_t::update_written_to( segment_info.written_to = new_written_to; } +std::ostream &operator<<(std::ostream &os, const segments_info_t &infos) +{ + return os << "segments(" + << "empty=" << infos.get_num_empty() + << ", open=" << infos.get_num_open() + << ", closed=" << infos.get_num_closed() + << ", type_journal=" << infos.get_num_type_journal() + << ", type_ool=" << infos.get_num_type_ool() + << ", total=" << infos.get_total_bytes() << "B" + << ", available=" << infos.get_available_bytes() << "B" + << ", unavailable=" << infos.get_unavailable_bytes() << "B" + << ", available_ratio=" << infos.get_available_ratio() + << ", submitted_head=" << infos.get_submitted_journal_head() + << ", time_bound=" << sea_time_point_printer_t{infos.get_time_bound()} + << ")"; +} + bool SpaceTrackerSimple::equals(const SpaceTrackerI &_other) const { LOG_PREFIX(SpaceTrackerSimple::equals); @@ -606,13 +623,7 @@ segment_id_t AsyncCleaner::allocate_segment( gc_process.maybe_wake_on_space_used(); auto new_usage = calc_utilization(seg_id); adjust_segment_util(old_usage, new_usage); - INFO("opened, should_block_on_trim {}, should_block_on_reclaim {}, " - "projected_avail_ratio {}, reclaim_ratio {}, alive_ratio {}", - should_block_on_trim(), - should_block_on_reclaim(), - get_projected_available_ratio(), - get_reclaim_ratio(), - get_alive_ratio()); + INFO("opened, {}", gc_stat_printer_t{this, false}); return seg_id; } } @@ -683,14 +694,7 @@ void AsyncCleaner::close_segment(segment_id_t segment) } auto new_usage = calc_utilization(segment); adjust_segment_util(old_usage, new_usage); - INFO("closed, should_block_on_trim {}, should_block_on_reclaim {}, " - "projected_avail_ratio {}, reclaim_ratio {}, alive_ratio {} -- {}", - should_block_on_trim(), - should_block_on_reclaim(), - get_projected_available_ratio(), - get_reclaim_ratio(), - get_alive_ratio(), - seg_info); + INFO("closed, {} -- {}", gc_stat_printer_t{this, false}, seg_info); } AsyncCleaner::trim_alloc_ret AsyncCleaner::trim_alloc( @@ -1118,6 +1122,8 @@ AsyncCleaner::mount_ret AsyncCleaner::mount() crimson::ct_error::input_output_error::pass_further{}, crimson::ct_error::assert_all{"unexpected error"} ); + }).safe_then([this, FNAME] { + INFO("done, {}", segments); }); } @@ -1197,14 +1203,7 @@ AsyncCleaner::maybe_release_segment(Transaction &t) segments.mark_empty(to_release); auto new_usage = calc_utilization(to_release); adjust_segment_util(old_usage, new_usage); - INFOT("released, should_block_on_trim {}, should_block_on_reclaim {}, " - "projected_avail_ratio {}, reclaim_ratio {}, alive_ratio {}", - t, - should_block_on_trim(), - should_block_on_reclaim(), - get_projected_available_ratio(), - get_reclaim_ratio(), - get_alive_ratio()); + INFOT("released, {}", t, gc_stat_printer_t{this, false}); if (space_tracker->get_usage(to_release) != 0) { space_tracker->dump_usage(to_release); ceph_abort(); @@ -1223,15 +1222,23 @@ void AsyncCleaner::complete_init() init_complete = true; return; } - INFO("done, start GC, time_bound={}", - sea_time_point_printer_t{segments.get_time_bound()}); + init_complete = true; + INFO("done, start GC, {}", gc_stat_printer_t{this, true}); ceph_assert(journal_head != JOURNAL_SEQ_NULL); ceph_assert(journal_alloc_tail != JOURNAL_SEQ_NULL); ceph_assert(journal_dirty_tail != JOURNAL_SEQ_NULL); - init_complete = true; gc_process.start(); } +seastar::future<> AsyncCleaner::stop() +{ + return gc_process.stop( + ).then([this] { + LOG_PREFIX(AsyncCleaner::stop); + INFO("done, {}", gc_stat_printer_t{this, true}); + }); +} + void AsyncCleaner::mark_space_used( paddr_t addr, extent_len_t len, @@ -1347,54 +1354,7 @@ void AsyncCleaner::log_gc_state(const char *caller) const LOG_PREFIX(AsyncCleaner::log_gc_state); if (LOCAL_LOGGER.is_enabled(seastar::log_level::debug) && !disable_trim) { - DEBUG( - "caller {}, " - "empty {}, " - "open {}, " - "closed {}, " - "in_journal {}, " - "total {}B, " - "available {}B, " - "unavailable {}B, " - "unavailable_used {}B, " - "unavailable_unused {}B; " - "reclaim_ratio {}, " - "available_ratio {}, " - "should_block_on_trim {}, " - "should_block_on_reclaim {}, " - "gc_should_reclaim_space {}, " - "journal_head {}, " - "journal_alloc_tail {}, " - "journal_dirty_tail {}, " - "alloc_tail_target {}, " - "dirty_tail_target {}, " - "tail_limit {}, " - "gc_should_trim_dirty {}, " - "gc_should_trim_alloc{}, ", - caller, - segments.get_num_empty(), - segments.get_num_open(), - segments.get_num_closed(), - get_segments_in_journal(), - segments.get_total_bytes(), - segments.get_available_bytes(), - segments.get_unavailable_bytes(), - stats.used_bytes, - get_unavailable_unused_bytes(), - get_reclaim_ratio(), - segments.get_available_ratio(), - should_block_on_trim(), - should_block_on_reclaim(), - gc_should_reclaim_space(), - journal_head, - journal_alloc_tail, - journal_dirty_tail, - get_alloc_tail_target(), - get_dirty_tail_target(), - get_tail_limit(), - gc_should_trim_dirty(), - gc_should_trim_alloc() - ); + DEBUG("caller {}, {}", caller, gc_stat_printer_t{this, true}); } } @@ -1453,4 +1413,41 @@ void AsyncCleaner::release_projected_usage(std::size_t projected_usage) return maybe_wake_gc_blocked_io(); } +std::ostream &operator<<(std::ostream &os, AsyncCleaner::gc_stat_printer_t stats) +{ + os << "gc_stats("; + if (stats.cleaner->init_complete) { + os << "should_block_on_(trim=" << stats.cleaner->should_block_on_trim() + << ", reclaim=" << stats.cleaner->should_block_on_reclaim() << ")" + << ", should_(trim_dirty=" << stats.cleaner->gc_should_trim_dirty() + << ", trim_alloc=" << stats.cleaner->gc_should_trim_alloc() + << ", reclaim=" << stats.cleaner->gc_should_reclaim_space() << ")"; + } else { + os << "init"; + } + os << ", projected_avail_ratio=" << stats.cleaner->get_projected_available_ratio() + << ", reclaim_ratio=" << stats.cleaner->get_reclaim_ratio() + << ", alive_ratio=" << stats.cleaner->get_alive_ratio(); + if (stats.detailed) { + os << ", journal_head=" << stats.cleaner->journal_head + << ", alloc_tail=" << stats.cleaner->journal_alloc_tail + << ", dirty_tail=" << stats.cleaner->journal_dirty_tail; + if (stats.cleaner->init_complete) { + os << ", alloc_tail_target=" << stats.cleaner->get_alloc_tail_target() + << ", dirty_tail_target=" << stats.cleaner->get_dirty_tail_target() + << ", tail_limit=" << stats.cleaner->get_tail_limit(); + } + os << ", unavailable_unreclaimable=" + << stats.cleaner->get_unavailable_unreclaimable_bytes() << "B" + << ", unavailable_reclaimble=" + << stats.cleaner->get_unavailable_reclaimable_bytes() << "B" + << ", alive=" << stats.cleaner->stats.used_bytes << "B"; + } + os << ")"; + if (stats.detailed) { + os << ", " << stats.cleaner->segments; + } + return os; +} + } diff --git a/src/crimson/os/seastore/async_cleaner.h b/src/crimson/os/seastore/async_cleaner.h index 14822b09a89ea..2113afbb6feb3 100644 --- a/src/crimson/os/seastore/async_cleaner.h +++ b/src/crimson/os/seastore/async_cleaner.h @@ -264,6 +264,8 @@ private: std::multiset modify_times; }; +std::ostream &operator<<(std::ostream &, const segments_info_t &); + /** * Callback interface for managing available segments */ @@ -872,9 +874,7 @@ public: return st; } - seastar::future<> stop() { - return gc_process.stop(); - } + seastar::future<> stop(); seastar::future<> run_until_halt() { return gc_process.run_until_halt(); @@ -948,6 +948,7 @@ private: journal_seq_t limit); journal_seq_t get_dirty_tail_target() const { + assert(init_complete); auto ret = journal_head; ceph_assert(ret != JOURNAL_SEQ_NULL); if (ret.segment_seq >= config.target_journal_dirty_segments) { @@ -960,6 +961,7 @@ private: } journal_seq_t get_tail_limit() const { + assert(init_complete); auto ret = journal_head; ceph_assert(ret != JOURNAL_SEQ_NULL); if (ret.segment_seq >= config.max_journal_segments) { @@ -972,6 +974,7 @@ private: } journal_seq_t get_alloc_tail_target() const { + assert(init_complete); auto ret = journal_head; ceph_assert(ret != JOURNAL_SEQ_NULL); if (ret.segment_seq >= config.target_journal_alloc_segments) { @@ -1243,17 +1246,15 @@ private: * Encapsulates whether block pending gc. */ bool should_block_on_trim() const { + assert(init_complete); if (disable_trim) return false; - if (!init_complete) { - return false; - } return get_tail_limit() > get_journal_tail(); } bool should_block_on_reclaim() const { + assert(init_complete); if (disable_trim) return false; - if (!init_complete || - get_segments_reclaimable() == 0) { + if (get_segments_reclaimable() == 0) { return false; } auto aratio = get_projected_available_ratio(); @@ -1261,6 +1262,7 @@ private: } bool should_block_on_gc() const { + assert(init_complete); return should_block_on_trim() || should_block_on_reclaim(); } @@ -1294,6 +1296,7 @@ private: * Encapsulates logic for whether gc should be reclaiming segment space. */ bool gc_should_reclaim_space() const { + assert(init_complete); if (disable_trim) return false; if (get_segments_reclaimable() == 0) { return false; @@ -1308,10 +1311,12 @@ private: } bool gc_should_trim_dirty() const { + assert(init_complete); return get_dirty_tail_target() > journal_dirty_tail; } bool gc_should_trim_alloc() const { + assert(init_complete); return get_alloc_tail_target() > journal_alloc_tail; } /** @@ -1342,7 +1347,15 @@ private: ool_segment_seq_allocator->set_next_segment_seq(seq); } } + + struct gc_stat_printer_t { + const AsyncCleaner *cleaner; + bool detailed = false; + }; + friend std::ostream &operator<<(std::ostream &, gc_stat_printer_t); }; using AsyncCleanerRef = std::unique_ptr; +std::ostream &operator<<(std::ostream &, AsyncCleaner::gc_stat_printer_t); + } -- 2.39.5