os/bluestore: log kv latencies

Signed-off-by: Sage Weil <sage@redhat.com>

diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc
index e5996af4d362b2a72ac866a12352ec66ab08405e..105777c429c27a0a9b68f176efb9905819cdbce2 100644 (file)
--- a/src/os/bluestore/BlueStore.cc
+++ b/src/os/bluestore/BlueStore.cc
@@ -3407,6 +3407,12 @@ void BlueStore::_init_logger()
     "Average finishing state latency");
   b.add_time_avg(l_bluestore_state_done_lat, "state_done_lat",
     "Average done state latency");
+  b.add_time_avg(l_bluestore_kv_flush_lat, "kv_flush_lat",
+                "Average kv_thread flush latency", "kflat");
+  b.add_time_avg(l_bluestore_kv_commit_lat, "kv_commit_lat",
+                "Average kv_thread commit latency", "kclat");
+  b.add_time_avg(l_bluestore_kv_lat, "kv_lat",
+                "Average kv_thread sync latency", "klat");
   b.add_time_avg(l_bluestore_submit_lat, "submit_lat",
     "Average submit latency");
   b.add_time_avg(l_bluestore_commit_lat, "commit_lat",
@@ -7668,6 +7674,7 @@ void BlueStore::_kv_sync_thread()
                               deferred_done.end());
        deferred_done.clear();
       }
+      utime_t after_flush = ceph_clock_now();
 
       // we will use one final transaction to force a sync
       KeyValueDB::Transaction synct = db->get_transaction();
@@ -7765,10 +7772,19 @@ void BlueStore::_kv_sync_thread()
       }
 
       utime_t finish = ceph_clock_now();
+      utime_t dur_flush = after_flush - start;
+      utime_t dur_kv = finish - after_flush;
       utime_t dur = finish - start;
       dout(20) << __func__ << " committed " << kv_committing.size()
               << " cleaned " << deferred_stable.size()
-              << " in " << dur << dendl;
+              << " in " << dur
+              << " (" << dur_flush << " flush + " << dur_kv << " kv commit)"
+              << dendl;
+      if (logger) {
+       logger->tinc(l_bluestore_kv_flush_lat, dur_flush);
+       logger->tinc(l_bluestore_kv_commit_lat, dur_kv);
+       logger->tinc(l_bluestore_kv_lat, dur);
+      }
       while (!kv_committing.empty()) {
        TransContext *txc = kv_committing.front();
        assert(txc->state == TransContext::STATE_KV_SUBMITTED);

diff --git a/src/os/bluestore/BlueStore.h b/src/os/bluestore/BlueStore.h
index 04cb5536e5f93695bc8365928dc3e477f0bc29aa..4a643a1ff1287c8fffb4dded67cf4d3ff6b726d7 100644 (file)
--- a/src/os/bluestore/BlueStore.h
+++ b/src/os/bluestore/BlueStore.h
@@ -61,6 +61,9 @@ enum {
   l_bluestore_state_deferred_cleanup_lat,
   l_bluestore_state_finishing_lat,
   l_bluestore_state_done_lat,
+  l_bluestore_kv_flush_lat,
+  l_bluestore_kv_commit_lat,
+  l_bluestore_kv_lat,
   l_bluestore_submit_lat,
   l_bluestore_commit_lat,
   l_bluestore_read_lat,