crimson/os/seastore: measure collection ordering_lock hold time

collock_wait already tells us how long a transaction waits for the
per-collection ordering_lock, but not how long the lock is then held.

comparing hold to wait time can point at either slow in-lock or
contention of a hot pg.

Signed-off-by: Matan Breizman <mbreizma@redhat.com>

diff --git a/src/crimson/os/seastore/ordering_handle.h b/src/crimson/os/seastore/ordering_handle.h
index 82e11dacf55bd19bbd26325897376636b0248168..a611dd316fbb517646ad74cef4a40cb379b756fc 100644 (file)
--- a/src/crimson/os/seastore/ordering_handle.h
+++ b/src/crimson/os/seastore/ordering_handle.h
@@ -3,6 +3,8 @@
 
 #pragma once
 
+#include <chrono>
+
 #include <seastar/core/shared_mutex.hh>
 
 #include "crimson/common/operation.h"
@@ -122,12 +124,17 @@ struct OrderingHandle {
   std::unique_ptr<OperationProxy> op;
   seastar::shared_mutex *collection_ordering_lock = nullptr;
 
+  std::chrono::steady_clock::time_point lock_acquire_time{};
+  std::chrono::steady_clock::duration lock_hold_time{0};
+
   // in the future we might add further constructors / template to type
   // erasure while extracting the location of tracking events.
   OrderingHandle(std::unique_ptr<OperationProxy> op) : op(std::move(op)) {}
   OrderingHandle(OrderingHandle &&other)
     : op(std::move(other.op)),
-      collection_ordering_lock(other.collection_ordering_lock) {
+      collection_ordering_lock(other.collection_ordering_lock),
+      lock_acquire_time(other.lock_acquire_time),
+      lock_hold_time(other.lock_hold_time) {
     other.collection_ordering_lock = nullptr;
   }
 
@@ -137,8 +144,19 @@ struct OrderingHandle {
     return collection_ordering_lock->lock();
   }
 
+  void set_lock_acquire_time(std::chrono::steady_clock::time_point tp) {
+    lock_acquire_time = tp;
+  }
+
+  std::chrono::steady_clock::duration get_lock_hold_time() const {
+    return lock_hold_time;
+  }
+
   void maybe_release_collection_lock() {
     if (collection_ordering_lock) {
+      if (lock_acquire_time != std::chrono::steady_clock::time_point{}) {
+        lock_hold_time = std::chrono::steady_clock::now() - lock_acquire_time;
+      }
       collection_ordering_lock->unlock();
       collection_ordering_lock = nullptr;
     }

diff --git a/src/crimson/os/seastore/seastore.cc b/src/crimson/os/seastore/seastore.cc
index ea7b8898df01149c46a6c0d995dccd925aca36d5..cf196e73209806c8d30b123d9f2aa1c0dfc8f357 100644 (file)
--- a/src/crimson/os/seastore/seastore.cc
+++ b/src/crimson/os/seastore/seastore.cc
@@ -215,6 +215,7 @@ void SeaStore::Shard::register_metrics(store_index_t store_index)
 
   std::pair<txn_stage_t, sm::label_instance> labels_by_stage[] = {
     {txn_stage_t::COLLOCK_WAIT,          sm::label_instance("stage", "collock_wait")},
+    {txn_stage_t::COLLOCK_HOLD,          sm::label_instance("stage", "collock_hold")},
     {txn_stage_t::THROTTLER_WAIT,        sm::label_instance("stage", "throttler_wait")},
     {txn_stage_t::BUILD,                 sm::label_instance("stage", "build")},
     {txn_stage_t::BUILD_GET_ONODE,       sm::label_instance("stage", "build_get_onode")},
@@ -1743,7 +1744,9 @@ seastar::future<> SeaStore::Shard::do_transaction_no_callbacks(
   co_await ctx.transaction->get_handle().take_collection_lock(
     static_cast<SeastoreCollection&>(*(ctx.ch)).ordering_lock
   );
-  auto collock_wait = std::chrono::steady_clock::now() - t_pre_collock;
+  auto t_post_collock = std::chrono::steady_clock::now();
+  auto collock_wait = t_post_collock - t_pre_collock;
+  ctx.transaction->get_handle().set_lock_acquire_time(t_post_collock);
 
   assert(shard_stats.waiting_collock_io_num);
   --(shard_stats.waiting_collock_io_num);
@@ -1818,6 +1821,8 @@ 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);

diff --git a/src/crimson/os/seastore/seastore.h b/src/crimson/os/seastore/seastore.h
index 34ac5e060c31df6a89bbc631594ca2cc42818e2a..ec40b94d4d78d0545f00cd2da7c92df94f58299e 100644 (file)
--- a/src/crimson/os/seastore/seastore.h
+++ b/src/crimson/os/seastore/seastore.h
@@ -49,6 +49,7 @@ enum class op_type_t : uint8_t {
 
 enum class txn_stage_t : uint8_t {
     COLLOCK_WAIT = 0,  // waiting on the collection ordering_lock
+    COLLOCK_HOLD,      // collection ordering_lock held (acquire -> release at prepare_record)
     THROTTLER_WAIT,    // waiting for a throttler slot
     BUILD,             // building the transaction (_do_transaction_step loop)
     BUILD_GET_ONODE,   // onode_manager get/get_or_create calls within BUILD