osd: Add op_process_latency in perf counter

Fixes: #7167
Signed-off-by: Ray Lv <xiangyulv@gmail.com>

diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc
index f192f479c2ecf7a6fe75ae6c3fbdf702b5d587ac..2537371d8d0cfbc8e26aded85486004f5dcbd62a 100644 (file)
--- a/src/osd/OSD.cc
+++ b/src/osd/OSD.cc
@@ -1299,19 +1299,23 @@ void OSD::create_logger()
   osd_plb.add_u64_counter(l_osd_op_inb,   "op_in_bytes");       // client op in bytes (writes)
   osd_plb.add_u64_counter(l_osd_op_outb,  "op_out_bytes");      // client op out bytes (reads)
   osd_plb.add_time_avg(l_osd_op_lat,   "op_latency");       // client op latency
+  osd_plb.add_time_avg(l_osd_op_process_lat, "op_process_latency");   // client op process latency
 
   osd_plb.add_u64_counter(l_osd_op_r,      "op_r");        // client reads
   osd_plb.add_u64_counter(l_osd_op_r_outb, "op_r_out_bytes");   // client read out bytes
   osd_plb.add_time_avg(l_osd_op_r_lat,  "op_r_latency");    // client read latency
+  osd_plb.add_time_avg(l_osd_op_r_process_lat, "op_r_process_latency");   // client read process latency
   osd_plb.add_u64_counter(l_osd_op_w,      "op_w");        // client writes
   osd_plb.add_u64_counter(l_osd_op_w_inb,  "op_w_in_bytes");    // client write in bytes
   osd_plb.add_time_avg(l_osd_op_w_rlat, "op_w_rlat");   // client write readable/applied latency
   osd_plb.add_time_avg(l_osd_op_w_lat,  "op_w_latency");    // client write latency
+  osd_plb.add_time_avg(l_osd_op_w_process_lat, "op_w_process_latency");   // client write process latency
   osd_plb.add_u64_counter(l_osd_op_rw,     "op_rw");       // client rmw
   osd_plb.add_u64_counter(l_osd_op_rw_inb, "op_rw_in_bytes");   // client rmw in bytes
   osd_plb.add_u64_counter(l_osd_op_rw_outb,"op_rw_out_bytes");  // client rmw out bytes
   osd_plb.add_time_avg(l_osd_op_rw_rlat,"op_rw_rlat");  // client rmw readable/applied latency
   osd_plb.add_time_avg(l_osd_op_rw_lat, "op_rw_latency");   // client rmw latency
+  osd_plb.add_time_avg(l_osd_op_rw_process_lat, "op_rw_process_latency");   // client rmw process latency
 
   osd_plb.add_u64_counter(l_osd_sop,       "subop");         // subops
   osd_plb.add_u64_counter(l_osd_sop_inb,   "subop_in_bytes");     // subop in bytes
@@ -7226,7 +7230,9 @@ void OSD::dequeue_op(
   PGRef pg, OpRequestRef op,
   ThreadPool::TPHandle &handle)
 {
-  utime_t latency = ceph_clock_now(cct) - op->get_req()->get_recv_stamp();
+  utime_t now = ceph_clock_now(cct);
+  op->set_dequeued_time(now);
+  utime_t latency = now - op->get_req()->get_recv_stamp();
   dout(10) << "dequeue_op " << op << " prio " << op->get_req()->get_priority()
           << " cost " << op->get_req()->get_cost()
           << " latency " << latency

diff --git a/src/osd/OSD.h b/src/osd/OSD.h
index 889822b39949bf5ef70d58084bab13821b5ef80a..7d5f10efd76a7f8305463490822cb4e363472ec4 100644 (file)
--- a/src/osd/OSD.h
+++ b/src/osd/OSD.h
@@ -66,18 +66,22 @@ enum {
   l_osd_op_inb,
   l_osd_op_outb,
   l_osd_op_lat,
+  l_osd_op_process_lat,
   l_osd_op_r,
   l_osd_op_r_outb,
   l_osd_op_r_lat,
+  l_osd_op_r_process_lat,
   l_osd_op_w,
   l_osd_op_w_inb,
   l_osd_op_w_rlat,
   l_osd_op_w_lat,
+  l_osd_op_w_process_lat,
   l_osd_op_rw,
   l_osd_op_rw_inb,
   l_osd_op_rw_outb,
   l_osd_op_rw_rlat,
   l_osd_op_rw_lat,
+  l_osd_op_rw_process_lat,
 
   l_osd_sop,
   l_osd_sop_inb,

diff --git a/src/osd/OpRequest.h b/src/osd/OpRequest.h
index 96bb5a4864f6951503ea117278bb8b9337024566..d8ccf71d2eff1aac8509f38eeb445f99edd5c77d 100644 (file)
--- a/src/osd/OpRequest.h
+++ b/src/osd/OpRequest.h
@@ -78,6 +78,7 @@ private:
   osd_reqid_t reqid;
   uint8_t hit_flag_points;
   uint8_t latest_flag_point;
+  utime_t dequeued_time;
   static const uint8_t flag_queued_for_pg=1 << 0;
   static const uint8_t flag_reached_pg =  1 << 1;
   static const uint8_t flag_delayed =     1 << 2;
@@ -151,6 +152,13 @@ public:
     latest_flag_point = flag_commit_sent;
   }
 
+  utime_t get_dequeued_time() const {
+    return dequeued_time;
+  }
+  void set_dequeued_time(utime_t deq_time) {
+    dequeued_time = deq_time;
+  }
+
   osd_reqid_t get_reqid() const {
     return reqid;
   }

diff --git a/src/osd/ReplicatedPG.cc b/src/osd/ReplicatedPG.cc
index 8ec8509217a943753607345d6cd471e1a5f27ca0..d59731c8b99720d1530022685f017beb47d80675 100644 (file)
--- a/src/osd/ReplicatedPG.cc
+++ b/src/osd/ReplicatedPG.cc
@@ -1714,6 +1714,8 @@ void ReplicatedPG::log_op_stats(OpContext *ctx)
   utime_t now = ceph_clock_now(cct);
   utime_t latency = now;
   latency -= ctx->op->get_req()->get_recv_stamp();
+  utime_t process_latency = now;
+  process_latency -= ctx->op->get_dequeued_time();
 
   utime_t rlatency;
   if (ctx->readable_stamp != utime_t()) {
@@ -1729,6 +1731,7 @@ void ReplicatedPG::log_op_stats(OpContext *ctx)
   osd->logger->inc(l_osd_op_outb, outb);
   osd->logger->inc(l_osd_op_inb, inb);
   osd->logger->tinc(l_osd_op_lat, latency);
+  osd->logger->tinc(l_osd_op_process_lat, process_latency);
 
   if (op->may_read() && op->may_write()) {
     osd->logger->inc(l_osd_op_rw);
@@ -1736,15 +1739,18 @@ void ReplicatedPG::log_op_stats(OpContext *ctx)
     osd->logger->inc(l_osd_op_rw_outb, outb);
     osd->logger->tinc(l_osd_op_rw_rlat, rlatency);
     osd->logger->tinc(l_osd_op_rw_lat, latency);
+    osd->logger->tinc(l_osd_op_rw_process_lat, process_latency);
   } else if (op->may_read()) {
     osd->logger->inc(l_osd_op_r);
     osd->logger->inc(l_osd_op_r_outb, outb);
     osd->logger->tinc(l_osd_op_r_lat, latency);
+    osd->logger->tinc(l_osd_op_r_process_lat, process_latency);
   } else if (op->may_write() || op->may_cache()) {
     osd->logger->inc(l_osd_op_w);
     osd->logger->inc(l_osd_op_w_inb, inb);
     osd->logger->tinc(l_osd_op_w_rlat, rlatency);
     osd->logger->tinc(l_osd_op_w_lat, latency);
+    osd->logger->tinc(l_osd_op_w_process_lat, process_latency);
   } else
     assert(0);