From: Matan Breizman Date: Wed, 24 Jun 2026 12:59:13 +0000 (+0000) Subject: crimson/os/seastore: per-stage do_transaction breakdown for tail txns X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=3ba4b80f6743ce6001fc3f8e7af2a1f42a603bd7;p=ceph.git crimson/os/seastore: per-stage do_transaction breakdown for tail txns on hot shards a small fraction of transactions dominate latency,collecting one histogram for all is not enough. Add two more histograms of the same strcutre for txns that take more than 5ms and more than 10ms. Signed-off-by: Matan Breizman --- diff --git a/src/crimson/os/seastore/seastore.cc b/src/crimson/os/seastore/seastore.cc index cf196e73209..0614d961206 100644 --- a/src/crimson/os/seastore/seastore.cc +++ b/src/crimson/os/seastore/seastore.cc @@ -227,27 +227,38 @@ void SeaStore::Shard::register_metrics(store_index_t store_index) {txn_stage_t::SUBMIT_PREPARE_RECORD, sm::label_instance("stage", "submit_prepare_record")}, {txn_stage_t::SUBMIT_JOURNAL, sm::label_instance("stage", "submit_journal")}, }; - for (auto& [stage, label] : labels_by_stage) { - auto idx = static_cast(stage); - auto& hist = stats.stage_lat[idx]; - hist.buckets.resize(STAGE_LAT_BUCKETS_US.size()); - for (std::size_t i = 0; i < STAGE_LAT_BUCKETS_US.size(); ++i) { - hist.buckets[i].upper_bound = STAGE_LAT_BUCKETS_US[i]; - hist.buckets[i].count = 0; - } - metrics.add_group( - "seastore", - { - sm::make_histogram( - "do_transaction_stage_lat", - [this, idx]() -> seastar::metrics::histogram& { - return stats.stage_lat[idx]; - }, - sm::description("per-stage latency (microseconds) of do_transaction"), - {label, sm::label_instance("shard_store_index", std::to_string(store_index))} - ) + // Three tiers of the same per-stage histograms + std::pair*, const char*> + tail_tiers[] = { + {&stats.stage_lat, "all"}, + {&stats.stage_lat_slow, "slow"}, + {&stats.stage_lat_very_slow, "very_slow"}, + }; + for (auto& [arr_ptr, tail] : tail_tiers) { + for (auto& [stage, label] : labels_by_stage) { + auto idx = static_cast(stage); + auto& hist = (*arr_ptr)[idx]; + hist.buckets.resize(STAGE_LAT_BUCKETS_US.size()); + for (std::size_t i = 0; i < STAGE_LAT_BUCKETS_US.size(); ++i) { + hist.buckets[i].upper_bound = STAGE_LAT_BUCKETS_US[i]; + hist.buckets[i].count = 0; } - ); + metrics.add_group( + "seastore", + { + sm::make_histogram( + "do_transaction_stage_lat", + [arr_ptr, idx]() -> seastar::metrics::histogram& { + return (*arr_ptr)[idx]; + }, + sm::description("per-stage latency (microseconds) of do_transaction"), + {label, + sm::label_instance("tail", tail), + sm::label_instance("shard_store_index", std::to_string(store_index))} + ) + } + ); + } } metrics.add_group( @@ -1820,21 +1831,39 @@ seastar::future<> SeaStore::Shard::do_transaction_no_callbacks( DEBUGT("done", *ctx.transaction); add_conflict_replay_sample(ctx.transaction->get_num_replays()); - add_stage_latency_sample(txn_stage_t::COLLOCK_WAIT, collock_wait); - add_stage_latency_sample(txn_stage_t::COLLOCK_HOLD, - ctx.transaction->get_handle().get_lock_hold_time()); - add_stage_latency_sample(txn_stage_t::THROTTLER_WAIT, throttler_wait); - add_stage_latency_sample(txn_stage_t::BUILD, ctx.build_time); - add_stage_latency_sample(txn_stage_t::BUILD_GET_ONODE, ctx.get_onode_time); - add_stage_latency_sample(txn_stage_t::SUBMIT_TOTAL, ctx.submit_time); { auto& pd = ctx.transaction->get_phase_durations(); - add_stage_latency_sample(txn_stage_t::SUBMIT_RESERVE, pd.reserve); - add_stage_latency_sample(txn_stage_t::SUBMIT_OOL_WRITE, pd.ool_write); - add_stage_latency_sample(txn_stage_t::SUBMIT_LBA_UPDATE, pd.lba_update); - add_stage_latency_sample(txn_stage_t::SUBMIT_PREPARE_ENTER, pd.prepare_enter); - add_stage_latency_sample(txn_stage_t::SUBMIT_PREPARE_RECORD, pd.prepare_record); - add_stage_latency_sample(txn_stage_t::SUBMIT_JOURNAL, pd.journal); + auto total = std::chrono::steady_clock::now() - ctx.begin_timestamp; + auto total_us = static_cast( + std::chrono::duration_cast(total).count()); + + const std::array< + std::pair, STAGE_MAX> + stage_samples = {{ + {txn_stage_t::COLLOCK_WAIT, collock_wait}, + {txn_stage_t::COLLOCK_HOLD, ctx.transaction->get_handle().get_lock_hold_time()}, + {txn_stage_t::THROTTLER_WAIT, throttler_wait}, + {txn_stage_t::BUILD, ctx.build_time}, + {txn_stage_t::BUILD_GET_ONODE, ctx.get_onode_time}, + {txn_stage_t::SUBMIT_TOTAL, ctx.submit_time}, + {txn_stage_t::SUBMIT_RESERVE, pd.reserve}, + {txn_stage_t::SUBMIT_OOL_WRITE, pd.ool_write}, + {txn_stage_t::SUBMIT_LBA_UPDATE, pd.lba_update}, + {txn_stage_t::SUBMIT_PREPARE_ENTER, pd.prepare_enter}, + {txn_stage_t::SUBMIT_PREPARE_RECORD, pd.prepare_record}, + {txn_stage_t::SUBMIT_JOURNAL, pd.journal}, + }}; + + for (auto& [stage, dur] : stage_samples) { + add_stage_latency_sample(stats.stage_lat, stage, dur); + if (total_us > TAIL_SLOW_US) { + add_stage_latency_sample(stats.stage_lat_slow, stage, dur); + } + if (total_us > TAIL_VERY_SLOW_US) { + add_stage_latency_sample(stats.stage_lat_very_slow, stage, dur); + } + } + add_latency_sample(op_type_t::DO_TRANSACTION, total); } add_latency_sample( op_type_t::DO_TRANSACTION, diff --git a/src/crimson/os/seastore/seastore.h b/src/crimson/os/seastore/seastore.h index ec40b94d4d7..1326a44e281 100644 --- a/src/crimson/os/seastore/seastore.h +++ b/src/crimson/os/seastore/seastore.h @@ -462,6 +462,9 @@ public: 10000, 15000, 20000, 30000, 50000, 100000 }; + static constexpr uint64_t TAIL_SLOW_US = 5000; // 5 ms + static constexpr uint64_t TAIL_VERY_SLOW_US = 10000; // 10 ms + struct { std::array op_lat; seastar::metrics::histogram conflict_replays; @@ -473,6 +476,10 @@ public: uint64_t onode_updates = 0; uint64_t onode_erases = 0; int64_t onode_extents_delta = 0; + + // same metrics collected two more times for high tail txns. + std::array stage_lat_slow; + std::array stage_lat_very_slow; } stats; void add_onode_tree_sample(const Transaction::tree_stats_t& ts) { @@ -528,9 +535,11 @@ public: // Record the latency of one do_transaction stage (microseconds). Buckets are // non-cumulative (bucket = first upper_bound >= value); values above the top // bound aren't bucketed but still land in sample_count/sample_sum. - void add_stage_latency_sample(txn_stage_t stage, + void add_stage_latency_sample( + std::array& arr, + txn_stage_t stage, std::chrono::steady_clock::duration dur) { - auto& hist = stats.stage_lat[static_cast(stage)]; + auto& hist = arr[static_cast(stage)]; if (hist.buckets.empty()) { // register_metrics() did not run (store inactive); nothing to record. return;