osd: Add op_process_latency in perf counter

Fixes: #7167

Signed-off-by: Ray Lv <xiangyulv@gmail.com>
This commit is contained in:
Ray Lv 2014-01-21 11:05:26 +08:00
parent 368f17362d
commit 78150bd9fe
4 changed files with 25 additions and 1 deletions

View File

@ -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

View File

@ -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,

View File

@ -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;
}

View File

@ -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);