crimson/os/seastore: use seastar::lowres_clock for do_transaction timing

do_transaction timing runs on the hot path and used for
latency histograms. std::chrono::steady_clock's per-call clock_gettime
is too costly for these needs. seastar::lowres_clock uses cached now()
at every task_quota poll (~0.5ms) - which is granular enough.

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 a611dd316fbb517646ad74cef4a40cb379b756fc..e4b375416e868698ece54fc46d1ee76c300774f7 100644 (file)
--- a/src/crimson/os/seastore/ordering_handle.h
+++ b/src/crimson/os/seastore/ordering_handle.h
@@ -5,6 +5,7 @@
 
 #include <chrono>
 
+#include <seastar/core/lowres_clock.hh>
 #include <seastar/core/shared_mutex.hh>
 
 #include "crimson/common/operation.h"
@@ -124,8 +125,8 @@ 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};
+  seastar::lowres_clock::time_point lock_acquire_time{};
+  seastar::lowres_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.
@@ -144,18 +145,18 @@ struct OrderingHandle {
     return collection_ordering_lock->lock();
   }
 
-  void set_lock_acquire_time(std::chrono::steady_clock::time_point tp) {
+  void set_lock_acquire_time(seastar::lowres_clock::time_point tp) {
     lock_acquire_time = tp;
   }
 
-  std::chrono::steady_clock::duration get_lock_hold_time() const {
+  seastar::lowres_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;
+      if (lock_acquire_time != seastar::lowres_clock::time_point{}) {
+        lock_hold_time = seastar::lowres_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 0614d961206c2ea09fd17595423f5460690f2dcd..679f670c013c78a727393bcac8179b55a33d0604 100644 (file)
--- a/src/crimson/os/seastore/seastore.cc
+++ b/src/crimson/os/seastore/seastore.cc
@@ -11,6 +11,7 @@
 
 #include <seastar/core/file.hh>
 #include <seastar/core/fstream.hh>
+#include <seastar/core/lowres_clock.hh>
 #include <seastar/core/metrics.hh>
 #include <seastar/core/shared_mutex.hh>
 
@@ -1751,11 +1752,11 @@ seastar::future<> SeaStore::Shard::do_transaction_no_callbacks(
   --(shard_stats.starting_io_num);
   ++(shard_stats.waiting_collock_io_num);
 
-  auto t_pre_collock = std::chrono::steady_clock::now();
+  auto t_pre_collock = seastar::lowres_clock::now();
   co_await ctx.transaction->get_handle().take_collection_lock(
     static_cast<SeastoreCollection&>(*(ctx.ch)).ordering_lock
   );
-  auto t_post_collock = std::chrono::steady_clock::now();
+  auto t_post_collock = seastar::lowres_clock::now();
   auto collock_wait = t_post_collock - t_pre_collock;
   ctx.transaction->get_handle().set_lock_acquire_time(t_post_collock);
 
@@ -1763,9 +1764,9 @@ seastar::future<> SeaStore::Shard::do_transaction_no_callbacks(
   --(shard_stats.waiting_collock_io_num);
   ++(shard_stats.waiting_throttler_io_num);
 
-  auto t_pre_throttler = std::chrono::steady_clock::now();
+  auto t_pre_throttler = seastar::lowres_clock::now();
   co_await throttler.get(1);
-  auto throttler_wait = std::chrono::steady_clock::now() - t_pre_throttler;
+  auto throttler_wait = seastar::lowres_clock::now() - t_pre_throttler;
 
   assert(shard_stats.waiting_throttler_io_num);
   --(shard_stats.waiting_throttler_io_num);
@@ -1804,7 +1805,7 @@ seastar::future<> SeaStore::Shard::do_transaction_no_callbacks(
       const size_t total_ops = ctx.ext_transaction.get_num_ops();
       size_t current_op = 0;
 
-      auto build_start = std::chrono::steady_clock::now();
+      auto build_start = seastar::lowres_clock::now();
       while (ctx.iter.have_op()) {
         current_op++;
 
@@ -1813,13 +1814,13 @@ seastar::future<> SeaStore::Shard::do_transaction_no_callbacks(
        co_await _do_transaction_step(
          ctx, ctx.ch, onodes, ctx.iter);
       }
-      ctx.build_time += std::chrono::steady_clock::now() - build_start;
+      ctx.build_time += seastar::lowres_clock::now() - build_start;
 
       DEBUGT("completed all {} ops for cid={}",
              t, total_ops, ctx.ch->get_cid());
-      auto submit_start = std::chrono::steady_clock::now();
+      auto submit_start = seastar::lowres_clock::now();
       co_await transaction_manager->submit_transaction(*ctx.transaction);
-      ctx.submit_time += std::chrono::steady_clock::now() - submit_start;
+      ctx.submit_time += seastar::lowres_clock::now() - submit_start;
     })
   ).handle_error(
     crimson::ct_error::all_same_way([FNAME, &ctx](auto e) {
@@ -1833,12 +1834,12 @@ seastar::future<> SeaStore::Shard::do_transaction_no_callbacks(
   add_conflict_replay_sample(ctx.transaction->get_num_replays());
   {
     auto& pd = ctx.transaction->get_phase_durations();
-    auto total = std::chrono::steady_clock::now() - ctx.begin_timestamp;
+    auto total = seastar::lowres_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>
+      std::pair<txn_stage_t, seastar::lowres_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()},
@@ -1867,7 +1868,8 @@ seastar::future<> SeaStore::Shard::do_transaction_no_callbacks(
   }
   add_latency_sample(
     op_type_t::DO_TRANSACTION,
-    std::chrono::steady_clock::now() - ctx.begin_timestamp);
+    seastar::lowres_clock::now() - ctx.begin_timestamp);
+
   add_onode_tree_sample(ctx.transaction->get_onode_tree_stats());
 
   throttler.put();
@@ -1969,7 +1971,7 @@ SeaStore::Shard::_do_transaction_step(
   }
   if (!onodes[op->oid]) {
     const ghobject_t& oid = i.get_oid(op->oid);
-    auto t0 = std::chrono::steady_clock::now();
+    auto t0 = seastar::lowres_clock::now();
     if (!create) {
       DEBUGT("op {}, get oid={} ...",
              *ctx.transaction, (uint32_t)op->op, oid);
@@ -1980,7 +1982,7 @@ SeaStore::Shard::_do_transaction_step(
       fut = onode_manager->get_or_create_onode(*ctx.transaction, oid);
     }
     fut = std::move(fut).si_then([&ctx, t0](auto onode) {
-      ctx.get_onode_time += std::chrono::steady_clock::now() - t0;
+      ctx.get_onode_time += seastar::lowres_clock::now() - t0;
       return onode_iertr::make_ready_future<OnodeRef>(std::move(onode));
     });
   }

diff --git a/src/crimson/os/seastore/seastore.h b/src/crimson/os/seastore/seastore.h
index 1326a44e281ca6da39a7f3e3f7f8e3e9731619c2..c261eb86352632b29a0bcef9afebc43d02de5529 100644 (file)
--- a/src/crimson/os/seastore/seastore.h
+++ b/src/crimson/os/seastore/seastore.h
@@ -261,11 +261,11 @@ public:
       TransactionRef transaction;
 
       ceph::os::Transaction::iterator iter;
-      std::chrono::steady_clock::time_point begin_timestamp = std::chrono::steady_clock::now();
+      seastar::lowres_clock::time_point begin_timestamp = seastar::lowres_clock::now();
 
-      std::chrono::steady_clock::duration build_time{0};
-      std::chrono::steady_clock::duration get_onode_time{0};
-      std::chrono::steady_clock::duration submit_time{0};
+      seastar::lowres_clock::duration build_time{0};
+      seastar::lowres_clock::duration get_onode_time{0};
+      seastar::lowres_clock::duration submit_time{0};
 
       void reset_preserve_handle(TransactionManager &tm) {
         tm.reset_transaction_preserve_handle(*transaction);
@@ -287,7 +287,7 @@ public:
       op_type_t op_type,
       cache_hint_t cache_hint_flags,
       F &&f) const {
-      auto begin_time = std::chrono::steady_clock::now();
+      auto begin_time = seastar::lowres_clock::now();
       return seastar::do_with(
         oid, Ret{}, std::forward<F>(f),
         [this, ch, src, op_type, begin_time, tname, cache_hint_flags
@@ -317,7 +317,7 @@ public:
           });
         }).safe_then([&ret, op_type, begin_time, this] {
           const_cast<Shard*>(this)->add_latency_sample(op_type,
-                     std::chrono::steady_clock::now() - begin_time);
+                     seastar::lowres_clock::now() - begin_time);
           return seastar::make_ready_future<Ret>(ret);
         });
       });
@@ -499,7 +499,7 @@ public:
     }
 
     void add_latency_sample(op_type_t op_type,
-        std::chrono::steady_clock::duration dur) {
+        seastar::lowres_clock::duration dur) {
       seastar::metrics::histogram& lat = get_latency(op_type);
       auto us = std::chrono::duration_cast<std::chrono::microseconds>(dur).count();
       lat.sample_count++;
@@ -538,7 +538,7 @@ public:
     void add_stage_latency_sample(
         std::array<seastar::metrics::histogram, STAGE_MAX>& arr,
         txn_stage_t stage,
-        std::chrono::steady_clock::duration dur) {
+        seastar::lowres_clock::duration dur) {
       auto& hist = arr[static_cast<std::size_t>(stage)];
       if (hist.buckets.empty()) {
         // register_metrics() did not run (store inactive); nothing to record.