crimson/os/seastore: track onode lookup latency in do_transaction

we might be able to reduce onode lookup stage by storing the prev
lookup already made when getting the obc.

according to to the stats I've colleceted onode lookup takes 40%
of total build time (which is ~20% of total txn time)

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 3d88bb1c405a4faab4c643e5ff372d07fcdd7021..6c77820ba4385d04a8272d6953c76dbc0da22e00 100644 (file)
--- a/src/crimson/os/seastore/seastore.cc
+++ b/src/crimson/os/seastore/seastore.cc
@@ -229,6 +229,7 @@ void SeaStore::Shard::register_metrics(store_index_t store_index)
     {txn_stage_t::COLLOCK_WAIT,          sm::label_instance("stage", "collock_wait")},
     {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")},
     {txn_stage_t::SUBMIT_TOTAL,          sm::label_instance("stage", "submit_total")},
     {txn_stage_t::SUBMIT_RESERVE,        sm::label_instance("stage", "submit_reserve")},
     {txn_stage_t::SUBMIT_OOL_WRITE,      sm::label_instance("stage", "submit_ool_write")},
@@ -1780,6 +1781,7 @@ seastar::future<> SeaStore::Shard::do_transaction_no_callbacks(
   add_stage_latency_sample(txn_stage_t::COLLOCK_WAIT, collock_wait);
   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();
@@ -1893,6 +1895,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();
     if (!create) {
       DEBUGT("op {}, get oid={} ...",
              *ctx.transaction, (uint32_t)op->op, oid);
@@ -1902,6 +1905,10 @@ SeaStore::Shard::_do_transaction_step(
              *ctx.transaction, (uint32_t)op->op, oid);
       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;
+      return onode_iertr::make_ready_future<OnodeRef>(std::move(onode));
+    });
   }
   return fut.si_then([&, op, this, FNAME](auto get_onode)
                       -> OnodeManager::get_or_create_onode_iertr::future<> {

diff --git a/src/crimson/os/seastore/seastore.h b/src/crimson/os/seastore/seastore.h
index 0cb63205052d2ea0d0df6dec0d8b52d4954b184f..56277b405dd122d0780b36aab2553174f1db85da 100644 (file)
--- a/src/crimson/os/seastore/seastore.h
+++ b/src/crimson/os/seastore/seastore.h
@@ -51,6 +51,7 @@ enum class txn_stage_t : uint8_t {
     COLLOCK_WAIT = 0,  // waiting on the collection ordering_lock
     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
     SUBMIT_TOTAL,      // the whole submit_transaction (pipeline + journal write)
     // Sub-phases of submit_transaction:
     SUBMIT_RESERVE,        // enter(reserve_projected_usage) + epm reserve_projected_usage
@@ -268,6 +269,7 @@ public:
       std::chrono::steady_clock::time_point begin_timestamp = std::chrono::steady_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};
 
       void reset_preserve_handle(TransactionManager &tm) {