osd/: add per-op latency averages for each recovery related message

Signed-off-by: Samuel Just <sjust@redhat.com>

diff --git a/src/osd/osd_perf_counters.cc b/src/osd/osd_perf_counters.cc
index ed63b4d3f6784d3355f749098a92e6e89004fe0c..b1c1413bf61d9dea1cfdf9e4421fafb729b6fa9e 100644 (file)
--- a/src/osd/osd_perf_counters.cc
+++ b/src/osd/osd_perf_counters.cc
@@ -162,6 +162,31 @@ PerfCounters *build_osd_logger(CephContext *cct) {
    "recovery bytes",
    "rbt", PerfCountersBuilder::PRIO_INTERESTING);
 
+  osd_plb.add_time_avg(
+    l_osd_recovery_push_queue_lat,
+    "l_osd_recovery_push_queue_latency",
+    "MOSDPGPush queue latency");
+  osd_plb.add_time_avg(
+    l_osd_recovery_push_reply_queue_lat,
+    "l_osd_recovery_push_reply_queue_latency",
+    "MOSDPGPushReply queue latency");
+  osd_plb.add_time_avg(
+    l_osd_recovery_pull_queue_lat,
+    "l_osd_recovery_pull_queue_latency",
+    "MOSDPGPull queue latency");
+  osd_plb.add_time_avg(
+    l_osd_recovery_backfill_queue_lat,
+    "l_osd_recovery_backfill_queue_latency",
+    "MOSDPGBackfill queue latency");
+  osd_plb.add_time_avg(
+    l_osd_recovery_backfill_remove_queue_lat,
+    "l_osd_recovery_backfill_remove_queue_latency",
+    "MOSDPGBackfillDelete queue latency");
+  osd_plb.add_time_avg(
+    l_osd_recovery_scan_queue_lat,
+    "l_osd_recovery_scan_queue_latency",
+    "MOSDPGScan queue latency");
+
   osd_plb.add_u64(l_osd_loadavg, "loadavg", "CPU load");
   osd_plb.add_u64(
     l_osd_cached_crc, "cached_crc", "Total number getting crc from crc_cache");

diff --git a/src/osd/osd_perf_counters.h b/src/osd/osd_perf_counters.h
index 9966a7f7df3c2f357d70198a0905211f6b16fe48..f8af01e0e4f564e3d28f32a6d02346a05788b6a3 100644 (file)
--- a/src/osd/osd_perf_counters.h
+++ b/src/osd/osd_perf_counters.h
@@ -58,6 +58,13 @@ enum {
   l_osd_rop,
   l_osd_rbytes,
 
+  l_osd_recovery_push_queue_lat,
+  l_osd_recovery_push_reply_queue_lat,
+  l_osd_recovery_pull_queue_lat,
+  l_osd_recovery_backfill_queue_lat,
+  l_osd_recovery_backfill_remove_queue_lat,
+  l_osd_recovery_scan_queue_lat,
+
   l_osd_loadavg,
   l_osd_cached_crc,
   l_osd_cached_crc_adjusted,

diff --git a/src/osd/scheduler/OpSchedulerItem.cc b/src/osd/scheduler/OpSchedulerItem.cc
index 4eab93bd9c3506c1b8a7575c0d928c0cf9133051..f2cc3e3fd0217c506cbd86fe8beb86a7bd49e103 100644 (file)
--- a/src/osd/scheduler/OpSchedulerItem.cc
+++ b/src/osd/scheduler/OpSchedulerItem.cc
@@ -254,6 +254,21 @@ void PGRecoveryMsg::run(
   PGRef& pg,
   ThreadPool::TPHandle &handle)
 {
+  auto latency = time_queued - ceph_clock_now();
+  switch (op->get_req()->get_type()) {
+  case MSG_OSD_PG_PUSH:
+    osd->logger->tinc(l_osd_recovery_push_queue_lat, latency);
+  case MSG_OSD_PG_PUSH_REPLY:
+    osd->logger->tinc(l_osd_recovery_push_reply_queue_lat, latency);
+  case MSG_OSD_PG_PULL:
+    osd->logger->tinc(l_osd_recovery_pull_queue_lat, latency);
+  case MSG_OSD_PG_BACKFILL:
+    osd->logger->tinc(l_osd_recovery_backfill_queue_lat, latency);
+  case MSG_OSD_PG_BACKFILL_REMOVE:
+    osd->logger->tinc(l_osd_recovery_backfill_remove_queue_lat, latency);
+  case MSG_OSD_PG_SCAN:
+    osd->logger->tinc(l_osd_recovery_scan_queue_lat, latency);
+  }
   osd->dequeue_op(pg, op, handle);
   pg->unlock();
 }

diff --git a/src/osd/scheduler/OpSchedulerItem.h b/src/osd/scheduler/OpSchedulerItem.h
index 2bc251c4633a45136a16ec02a81379325c866cda..e3f3a1a67af0c3c40cd77fdfabe7afc4fc1f7827 100644 (file)
--- a/src/osd/scheduler/OpSchedulerItem.h
+++ b/src/osd/scheduler/OpSchedulerItem.h
@@ -572,10 +572,12 @@ public:
 };
 
 class PGRecoveryMsg : public PGOpQueueable {
+  utime_t time_queued;
   OpRequestRef op;
 
 public:
-  PGRecoveryMsg(spg_t pg, OpRequestRef op) : PGOpQueueable(pg), op(std::move(op)) {}
+  PGRecoveryMsg(spg_t pg, OpRequestRef op)
+    : PGOpQueueable(pg), time_queued(ceph_clock_now()), op(std::move(op)) {}
 
   static bool is_recovery_msg(OpRequestRef &op) {
     switch (op->get_req()->get_type()) {