Measure OSD op/subop latency

Something is wrong: loopback RTT between OSDs is sometimes as high as 70us (should be 20us or less probably)

osd.cpp

@@ -7,12 +7,48 @@
 
 #include "osd.h"
 
+static const char* osd_op_names[] = {
+    "",
+    "read",
+    "write",
+    "sync",
+    "stabilize",
+    "rollback",
+    "delete",
+    "sync_stab_all",
+    "list",
+    "show_config",
+    "primary_read",
+    "primary_write",
+    "primary_sync",
+};
+
 osd_t::osd_t(blockstore_config_t & config, blockstore_t *bs, ring_loop_t *ringloop)
 {
     this->config = config;
     this->bs = bs;
     this->ringloop = ringloop;
-    this->tick_tfd = new timerfd_interval(ringloop, 1, []() {});
+    this->tick_tfd = new timerfd_interval(ringloop, 3, [this]()
+    {
+        for (int i = 0; i <= OSD_OP_MAX; i++)
+        {
+            if (op_stat_count[i] != 0)
+            {
+                printf("avg latency for op %d (%s): %ld us\n", i, osd_op_names[i], op_stat_sum[i]/op_stat_count[i]);
+                op_stat_count[i] = 0;
+                op_stat_sum[i] = 0;
+            }
+        }
+        for (int i = 0; i <= OSD_OP_MAX; i++)
+        {
+            if (subop_stat_count[i] != 0)
+            {
+                printf("avg latency for subop %d (%s): %ld us\n", i, osd_op_names[i], subop_stat_sum[i]/subop_stat_count[i]);
+                subop_stat_count[i] = 0;
+                subop_stat_sum[i] = 0;
+            }
+        }
+    });
     this->bs_block_size = bs->get_block_size();
     // FIXME: use bitmap granularity instead
     this->bs_disk_alignment = bs->get_disk_alignment();
@@ -309,6 +345,7 @@ void osd_t::stop_client(int peer_fd)
 
 void osd_t::exec_op(osd_op_t *cur_op)
 {
+    gettimeofday(&cur_op->tv_begin, NULL);
     if (stopping)
     {
         // Throw operation away

osd.h

@@ -96,6 +96,7 @@ struct osd_primary_op_data_t;
 
 struct osd_op_t
 {
+    timeval tv_begin;
     int op_type = OSD_OP_IN;
     int peer_fd;
     osd_any_op_t req;
@@ -208,6 +209,10 @@ class osd_t
     std::unordered_map<int,osd_client_t> clients;
     std::vector<int> read_ready_clients;
     std::vector<int> write_ready_clients;
+    uint64_t op_stat_sum[OSD_OP_MAX+1] = { 0 };
+    uint64_t op_stat_count[OSD_OP_MAX+1] = { 0 };
+    uint64_t subop_stat_sum[OSD_OP_MAX+1] = { 0 };
+    uint64_t subop_stat_count[OSD_OP_MAX+1] = { 0 };
 
     // methods
 

osd_receive.cpp

@@ -90,6 +90,14 @@ void osd_t::handle_read(ring_data_t *data, int peer_fd)
                     cl.sent_ops.erase(req_it);
                     cl.read_reply_id = 0;
                     cl.read_state = 0;
+                    // Measure subop latency
+                    timeval tv_end;
+                    gettimeofday(&tv_end, NULL);
+                    subop_stat_count[request->req.hdr.opcode]++;
+                    subop_stat_sum[request->req.hdr.opcode] += (
+                        (tv_end.tv_sec - request->tv_begin.tv_sec)*1000000 +
+                        tv_end.tv_usec - request->tv_begin.tv_usec
+                    );
                     request->callback(request);
                 }
             }
@@ -182,6 +190,14 @@ void osd_t::handle_reply_hdr(osd_client_t *cl)
     {
         cl->read_state = 0;
         cl->sent_ops.erase(req_it);
+        // Measure subop latency
+        timeval tv_end;
+        gettimeofday(&tv_end, NULL);
+        subop_stat_count[op->req.hdr.opcode]++;
+        subop_stat_sum[op->req.hdr.opcode] += (
+            (tv_end.tv_sec - op->tv_begin.tv_sec)*1000000 +
+            tv_end.tv_usec - op->tv_begin.tv_usec
+        );
         op->callback(op);
     }
 }

osd_send.cpp

@@ -3,6 +3,10 @@
 void osd_t::outbox_push(osd_client_t & cl, osd_op_t *cur_op)
 {
     assert(cur_op->peer_fd);
+    if (cur_op->op_type == OSD_OP_OUT)
+    {
+        gettimeofday(&cur_op->tv_begin, NULL);
+    }
     if (cl.write_state == 0)
     {
         cl.write_state = CL_WRITE_READY;
@@ -38,6 +42,14 @@ void osd_t::send_replies()
             }
             else
             {
+                // Measure execution latency
+                timeval tv_end;
+                gettimeofday(&tv_end, NULL);
+                op_stat_count[cl.write_op->req.hdr.opcode]++;
+                op_stat_sum[cl.write_op->req.hdr.opcode] += (
+                    (tv_end.tv_sec - cl.write_op->tv_begin.tv_sec)*1000000 +
+                    tv_end.tv_usec - cl.write_op->tv_begin.tv_usec
+                );
                 cl.write_buf = &cl.write_op->reply.buf;
                 cl.write_remaining = OSD_PACKET_SIZE;
                 cl.write_state = CL_WRITE_REPLY;