From da84cbad3c3e6c4744789088ef2b789e44571a3e Mon Sep 17 00:00:00 2001
From: James Liu <james.liu@ssi.samsung.com>
Date: Mon, 29 Feb 2016 16:11:25 -0800
Subject: [PATCH] os/kstore: Latency breakdown in each stage of transaction for
 Kstore

Signed-off-by: James Liu <james.liu@ssi.samsung.com>
---
 src/os/kstore/KStore.cc | 16 ++++++++++++++++
 src/os/kstore/KStore.h  | 27 +++++++++++++++++++++++----
 2 files changed, 39 insertions(+), 4 deletions(-)

diff --git a/src/os/kstore/KStore.cc b/src/os/kstore/KStore.cc
index 3ae9cc4c6e9b..3b44b0ec25f5 100644
--- a/src/os/kstore/KStore.cc
+++ b/src/os/kstore/KStore.cc
@@ -652,11 +652,22 @@ KStore::~KStore()
 void KStore::_init_logger()
 {
   // XXX
+  PerfCountersBuilder b(g_ceph_context, "KStore",
+                        l_kstore_first, l_kstore_last);
+  b.add_time_avg(l_kstore_state_prepare_lat, "state_prepare_lat", "Average prepare state latency");
+  b.add_time_avg(l_kstore_state_kv_queued_lat, "state_kv_queued_lat", "Average kv_queued state latency");
+  b.add_time_avg(l_kstore_state_kv_done_lat, "state_kv_done_lat", "Average kv_done state latency");
+  b.add_time_avg(l_kstore_state_finishing_lat, "state_finishing_lat", "Average finishing state latency");
+  b.add_time_avg(l_kstore_state_done_lat, "state_done_lat", "Average done state latency");
+  logger = b.create_perf_counters();
+  g_ceph_context->get_perfcounters_collection()->add(logger);
 }
 
 void KStore::_shutdown_logger()
 {
   // XXX
+  g_ceph_context->get_perfcounters_collection()->remove(logger);
+  delete logger;
 }
 
 int KStore::_open_path()
@@ -2170,6 +2181,7 @@ void KStore::_txc_state_proc(TransContext *txc)
 	     << " " << txc->get_state_name() << dendl;
     switch (txc->state) {
     case TransContext::STATE_PREPARE:
+      txc->log_state_latency(logger, l_kstore_state_prepare_lat);
       txc->state = TransContext::STATE_KV_QUEUED;
       if (!g_conf->kstore_sync_transaction) {
 	std::lock_guard<std::mutex> l(kv_lock);
@@ -2184,15 +2196,18 @@ void KStore::_txc_state_proc(TransContext *txc)
       break;
 
     case TransContext::STATE_KV_QUEUED:
+      txc->log_state_latency(logger, l_kstore_state_kv_queued_lat);
       txc->state = TransContext::STATE_KV_DONE;
       _txc_finish_kv(txc);
       // ** fall-thru **
 
     case TransContext::STATE_KV_DONE:
+      txc->log_state_latency(logger, l_kstore_state_kv_done_lat);
       txc->state = TransContext::STATE_FINISHING;
       break;
 
     case TransContext::TransContext::STATE_FINISHING:
+      txc->log_state_latency(logger, l_kstore_state_finishing_lat);
       _txc_finish(txc);
       return;
 
@@ -2303,6 +2318,7 @@ void KStore::_osr_reap_done(OpSequencer *osr)
     }
 
     osr->q.pop_front();
+    txc->log_state_latency(logger, l_kstore_state_done_lat);
     delete txc;
     osr->qcond.notify_all();
     if (osr->q.empty())
diff --git a/src/os/kstore/KStore.h b/src/os/kstore/KStore.h
index 1c163cce667d..4b0066331dee 100644
--- a/src/os/kstore/KStore.h
+++ b/src/os/kstore/KStore.h
@@ -30,6 +30,7 @@
 #include "common/RWLock.h"
 #include "common/WorkQueue.h"
 #include "os/ObjectStore.h"
+#include "common/perf_counters.h"
 #include "os/fs/FS.h"
 #include "kv/KeyValueDB.h"
 
@@ -37,6 +38,16 @@
 
 #include "boost/intrusive/list.hpp"
 
+enum {  
+  l_kstore_first = 832430,
+  l_kstore_state_prepare_lat,
+  l_kstore_state_kv_queued_lat,
+  l_kstore_state_kv_done_lat,
+  l_kstore_state_finishing_lat,
+  l_kstore_state_done_lat,
+  l_kstore_last
+};
+
 class KStore : public ObjectStore {
   // -----------------------------------------------------
   // types
@@ -192,6 +203,13 @@ public:
       return "???";
     }
 
+    void log_state_latency(PerfCounters *logger, int state) {      
+        utime_t lat, now = ceph_clock_now(g_ceph_context);
+        lat = now - start;
+        logger->tinc(state, lat);
+        start = now;
+    }
+
     OpSequencerRef osr;
     boost::intrusive::list_member_hook<> sequencer_item;
 
@@ -206,7 +224,7 @@ public:
     list<CollectionRef> removed_collections; ///< colls we removed
 
     CollectionRef first_collection;  ///< first referenced collection
-
+    utime_t start;
     explicit TransContext(OpSequencer *o)
       : state(STATE_PREPARE),
 	osr(o),
@@ -214,7 +232,8 @@ public:
 	bytes(0),
 	oncommit(NULL),
 	onreadable(NULL),
-	onreadable_sync(NULL) {
+	onreadable_sync(NULL),
+        start(ceph_clock_now(g_ceph_context)){
       //cout << "txc new " << this << std::endl;
     }
     ~TransContext() {
@@ -310,8 +329,8 @@ private:
   bool kv_stop;
   deque<TransContext*> kv_queue, kv_committing;
 
-  Logger *logger;
-
+  //Logger *logger;
+  PerfCounters *logger;
   std::mutex reap_lock;
   list<CollectionRef> removed_collections;
 
-- 
2.47.3