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;