Merge pull request #474 from raakella1/add_metrics

add metrics

conanfile.py

@@ -9,7 +9,7 @@
 
 class HomestoreConan(ConanFile):
     name = "homestore"
-    version = "6.4.30"
+    version = "6.4.31"
 
     homepage = "https://github.com/eBay/Homestore"
     description = "HomeStore Storage Engine"

src/lib/replication/log_store/repl_log_store.cpp

@@ -70,10 +70,14 @@ void ReplLogStore::end_of_append_batch(ulong start_lsn, ulong count) {
         // In the meanwhile, we can flush the journal for this lsn batch. It is ok to flush the entries in log before
         // actual data is written, because, even if we have the log, it doesn't mean data is committed, until state
         // machine reports that. This way the flush and fetch both can run in parallel.
+        auto cur_time = std::chrono::steady_clock::now();
         HomeRaftLogStore::end_of_append_batch(start_lsn, count);
+        HISTOGRAM_OBSERVE(m_rd.metrics(), raft_end_of_append_batch_latency_us, get_elapsed_time_us(cur_time));
 
+        cur_time = std::chrono::steady_clock::now();
         // Wait for the fetch and write to be completed successfully.
         std::move(fut).wait();
+        HISTOGRAM_OBSERVE(m_rd.metrics(), data_channel_wait_latency_us, get_elapsed_time_us(cur_time));
 
         // Mark all the reqs also completely written
         for (auto const& rreq : *reqs) {

src/lib/replication/repl_dev/raft_repl_dev.cpp

@@ -250,12 +250,14 @@ void RaftReplDev::push_data_to_all_followers(repl_req_ptr_t rreq, sisl::sg_list
 }
 
 void RaftReplDev::on_push_data_received(intrusive< sisl::GenericRpcData >& rpc_data) {
+    auto const push_data_rcv_time = Clock::now();
     auto const& incoming_buf = rpc_data->request_blob();
     if (!incoming_buf.cbytes()) {
         RD_LOGW("Data Channel: PushData received with empty buffer, ignoring this call");
         rpc_data->send_response();
         return;
     }
+
     auto const fb_size =
         flatbuffers::ReadScalar< flatbuffers::uoffset_t >(incoming_buf.cbytes()) + sizeof(flatbuffers::uoffset_t);
     auto push_req = GetSizePrefixedPushDataRequest(incoming_buf.cbytes());
@@ -295,7 +297,6 @@ void RaftReplDev::on_push_data_received(intrusive< sisl::GenericRpcData >& rpc_d
     COUNTER_INCREMENT(m_metrics, total_write_cnt, 1);
     COUNTER_INCREMENT(m_metrics, outstanding_data_write_cnt, 1);
 
-    auto const push_data_rcv_time = Clock::now();
     // Schedule a write and upon completion, mark the data as written.
     data_service()
         .async_write(r_cast< const char* >(rreq->data()), push_req->data_size(), rreq->local_blkid())
@@ -320,10 +321,10 @@ void RaftReplDev::on_push_data_received(intrusive< sisl::GenericRpcData >& rpc_d
                 auto const write_num_pieces = rreq->local_blkid().num_pieces();
 
                 HISTOGRAM_OBSERVE(m_metrics, rreq_pieces_per_write, write_num_pieces);
-                HISTOGRAM_OBSERVE(m_metrics, rreq_data_write_latency_us, data_write_latency);
+                HISTOGRAM_OBSERVE(m_metrics, rreq_push_data_latency_us, data_write_latency);
                 HISTOGRAM_OBSERVE(m_metrics, rreq_total_data_write_latency_us, total_data_write_latency);
 
-                RD_LOGI("Data Channel: Data write completed for rreq=[{}], time_diff_data_log_us={}, "
+                RD_LOGD("Data Channel: Data write completed for rreq=[{}], time_diff_data_log_us={}, "
                         "data_write_latency_us={}, total_data_write_latency_us(rreq creation to write complete)={}, "
                         "local_blkid.num_pieces={}",
                         rreq->to_compact_string(), data_log_diff_us, data_write_latency, total_data_write_latency,
@@ -730,7 +731,7 @@ void RaftReplDev::handle_fetch_data_response(sisl::GenericClientResponse respons
                     rreq->add_state(repl_req_state_t::DATA_WRITTEN);
                     rreq->m_data_written_promise.setValue();
 
-                    RD_LOGI("Data Channel: Data Write completed rreq=[{}], data_write_latency_us={}, "
+                    RD_LOGD("Data Channel: Data Write completed rreq=[{}], data_write_latency_us={}, "
                             "total_write_latency_us={}, write_num_pieces={}",
                             rreq->to_compact_string(), data_write_latency, total_data_write_latency, write_num_pieces);
                 });

src/lib/replication/repl_dev/raft_repl_dev.h

@@ -62,6 +62,14 @@ class RaftReplDevMetrics : public sisl::MetricsGroup {
                            {"op", "write"});
         REGISTER_HISTOGRAM(rreq_data_read_latency_us, "rreq data read latency in us", "rreq_data_op_latency",
                            {"op", "read"}); // placeholder
+        REGISTER_HISTOGRAM(rreq_push_data_latency_us, "rreq data write latency in us", "rreq_data_op_latency",
+                           {"op", "push"});
+        // latency from req received to sending response
+        REGISTER_HISTOGRAM(rreq_data_write_respond_latency_us, "rreq data write and respond latency in us",
+                           "rreq_data_op_latency", {"op", "respond"});
+        // latency from req received to rpc complete
+        REGISTER_HISTOGRAM(rreq_data_write_complete_latency_us, "rreq data rpc complete latency in us",
+                           "rreq_data_op_latency", {"op", "complete"});
         // latency from follower->originator->follower, not including actual data write on follower;
         REGISTER_HISTOGRAM(rreq_data_fetch_latency_us, "rreq data fetch latency in us", "rreq_data_op_latency",
                            {"op", "fetch"});
@@ -75,6 +83,12 @@ class RaftReplDevMetrics : public sisl::MetricsGroup {
         REGISTER_HISTOGRAM(rreq_pieces_per_write, "Number of individual pieces per write",
                            HistogramBucketsType(LinearUpto64Buckets));
 
+        // Raft channel metrics
+        REGISTER_HISTOGRAM(raft_end_of_append_batch_latency_us, "Raft end_of_append_batch latency in us",
+                           "raft_logstore_append_latency", {"op", "end_of_append_batch"});
+        REGISTER_HISTOGRAM(data_channel_wait_latency_us, "Data channel wait latency in us",
+                           "raft_logstore_append_latency", {"op", "wait_for_data"});
+
         register_me_to_farm();
     }
 
@@ -163,6 +177,7 @@ class RaftReplDev : public ReplDev,
     //////////////// Accessor/shortcut methods ///////////////////////
     nuraft_mesg::repl_service_ctx* group_msg_service();
     nuraft::raft_server* raft_server();
+    RaftReplDevMetrics& metrics() { return m_metrics; }
 
     //////////////// Methods needed for other Raft classes to access /////////////////
     void use_config(json_superblk raft_config_sb);