From: Sage Weil <sage@redhat.com>
Date: Tue, 14 Mar 2017 20:13:34 +0000 (-0400)
Subject: os/bluestore: log kv latencies
X-Git-Tag: v12.0.2~310^2~4
X-Git-Url: http://git.apps.os.sepia.ceph.com/?a=commitdiff_plain;h=b713d6971e256efcee8cc9e50af95aa7b6e7dede;p=ceph.git

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 e5996af4d362b..105777c429c27 100644
--- 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 04cb5536e5f93..4a643a1ff1287 100644
--- 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,