From 78150bd9fea1fb170d7149fd43d9446bdd69261f Mon Sep 17 00:00:00 2001 From: Ray Lv Date: Tue, 21 Jan 2014 11:05:26 +0800 Subject: [PATCH] osd: Add op_process_latency in perf counter Fixes: #7167 Signed-off-by: Ray Lv --- src/osd/OSD.cc | 8 +++++++- src/osd/OSD.h | 4 ++++ src/osd/OpRequest.h | 8 ++++++++ src/osd/ReplicatedPG.cc | 6 ++++++ 4 files changed, 25 insertions(+), 1 deletion(-) diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc index f192f479c2e..2537371d8d0 100644 --- 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 889822b3994..7d5f10efd76 100644 --- 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 96bb5a4864f..d8ccf71d2ef 100644 --- 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 8ec8509217a..d59731c8b99 100644 --- 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); -- 2.47.3