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 <mbreizma@redhat.com>

diff --git a/src/crimson/os/seastore/seastore.cc b/src/crimson/os/seastore/seastore.cc
index cf196e73209806c8d30b123d9f2aa1c0dfc8f357..0614d961206c2ea09fd17595423f5460690f2dcd 100644 (file)
--- 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<std::size_t>(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<std::array<seastar::metrics::histogram, STAGE_MAX>*, 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<std::size_t>(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<uint64_t>(
+      std::chrono::duration_cast<std::chrono::microseconds>(total).count());
+
+    const std::array<
+      std::pair<txn_stage_t, std::chrono::steady_clock::duration>, 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 ec40b94d4d78d0545f00cd2da7c92df94f58299e..1326a44e281ca6da39a7f3e3f7f8e3e9731619c2 100644 (file)
--- 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<seastar::metrics::histogram, LAT_MAX> 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<seastar::metrics::histogram, STAGE_MAX> stage_lat_slow;
+      std::array<seastar::metrics::histogram, STAGE_MAX> 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<seastar::metrics::histogram, STAGE_MAX>& arr,
+        txn_stage_t stage,
         std::chrono::steady_clock::duration dur) {
-      auto& hist = stats.stage_lat[static_cast<std::size_t>(stage)];
+      auto& hist = arr[static_cast<std::size_t>(stage)];
       if (hist.buckets.empty()) {
         // register_metrics() did not run (store inactive); nothing to record.
         return;