os/bluestore: add some slow count for bluestore

Add slow count as below:
- l_bluestore_slow_aio_wait_count
- l_bluestore_slow_committed_kv_count
- l_bluestore_slow_read_onode_meta_count
- l_bluestore_slow_read_wait_aio_count

We can get a count while bluestore happens slowly,
in some cases, this is more useful than average latency.
Add it to prometheus, we can get it from the dashboard.

Signed-off-by: Yite Gu <yitegu0@gmail.com>

diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc
index e3e4833f1a2da2e563b0076f6de5fdc6fb023313..8fc75bee7aa8e4a1d56726aed60b2a9c05104928 100644 (file)
--- a/src/os/bluestore/BlueStore.cc
+++ b/src/os/bluestore/BlueStore.cc
@@ -5367,6 +5367,29 @@ void BlueStore::_init_logger()
     "tr_l", PerfCountersBuilder::PRIO_USEFUL);
   //****************************************
 
+  // slow op count
+  //****************************************
+  b.add_u64_counter(l_bluestore_slow_aio_wait_count,
+    "slow_aio_wait_count",
+    "Slow op count for aio wait",
+    "sawc",
+    PerfCountersBuilder::PRIO_USEFUL);
+  b.add_u64_counter(l_bluestore_slow_committed_kv_count,
+    "slow_committed_kv_count",
+    "Slow op count for committed kv",
+    "sckc",
+    PerfCountersBuilder::PRIO_USEFUL);
+  b.add_u64_counter(l_bluestore_slow_read_onode_meta_count,
+    "slow_read_onode_meta_count",
+    "Slow op count for read onode meta",
+    "sroc",
+    PerfCountersBuilder::PRIO_USEFUL);
+  b.add_u64_counter(l_bluestore_slow_read_wait_aio_count,
+    "slow_read_wait_aio_count",
+    "Slow op count for read wait aio",
+    "srwc",
+    PerfCountersBuilder::PRIO_USEFUL);
+
   // Resulting size axis configuration for op histograms, values are in bytes
   PerfHistogramCommon::axis_config_d alloc_hist_x_axis_config{
     "Given size (bytes)",
@@ -10861,7 +10884,8 @@ int BlueStore::read(
     log_latency("get_onode@read",
       l_bluestore_read_onode_meta_lat,
       mono_clock::now() - start1,
-      cct->_conf->bluestore_log_op_age);
+      cct->_conf->bluestore_log_op_age,
+      "", l_bluestore_slow_read_onode_meta_count);
     if (!o || !o->exists) {
       r = -ENOENT;
       goto out;
@@ -11200,7 +11224,8 @@ int BlueStore::_do_read(
   log_latency(__func__,
     l_bluestore_read_onode_meta_lat,
     mono_clock::now() - start,
-    cct->_conf->bluestore_log_op_age);
+    cct->_conf->bluestore_log_op_age,
+    "", l_bluestore_slow_read_onode_meta_count);
   _dump_onode<30>(cct, *o);
 
   // for deep-scrub, we only read dirty cache and bypass clean cache in
@@ -11243,7 +11268,8 @@ int BlueStore::_do_read(
     l_bluestore_read_wait_aio_lat,
     mono_clock::now() - start,
     cct->_conf->bluestore_log_op_age,
-    [&](auto lat) { return ", num_ios = " + stringify(num_ios); }
+    [&](auto lat) { return ", num_ios = " + stringify(num_ios); },
+    l_bluestore_slow_read_wait_aio_count
   );
 
   bool csum_error = false;
@@ -11565,7 +11591,8 @@ int BlueStore::_do_readv(
   log_latency(__func__,
     l_bluestore_read_onode_meta_lat,
     mono_clock::now() - start,
-    cct->_conf->bluestore_log_op_age);
+    cct->_conf->bluestore_log_op_age,
+    "", l_bluestore_slow_read_onode_meta_count);
   _dump_onode<30>(cct, *o);
 
   IOContext ioc(cct, NULL, !cct->_conf->bluestore_fail_eio);
@@ -11598,7 +11625,8 @@ int BlueStore::_do_readv(
     l_bluestore_read_wait_aio_lat,
     mono_clock::now() - start,
     cct->_conf->bluestore_log_op_age,
-    [&](auto lat) { return ", num_ios = " + stringify(num_ios); }
+    [&](auto lat) { return ", num_ios = " + stringify(num_ios); },
+    l_bluestore_slow_read_wait_aio_count
   );
 
   ceph_assert(raw_results.size() == (size_t)m.num_intervals());
@@ -12659,6 +12687,7 @@ void BlueStore::_txc_state_proc(TransContext *txc)
        mono_clock::duration lat = throttle.log_state_latency(
          *txc, logger, l_bluestore_state_aio_wait_lat);
        if (ceph::to_seconds<double>(lat) >= cct->_conf->bluestore_log_op_age) {
+         logger->inc(l_bluestore_slow_aio_wait_count);
          dout(0) << __func__ << " slow aio_wait, txc = " << txc
                  << ", latency = " << lat
                  << dendl;
@@ -12984,7 +13013,8 @@ void BlueStore::_txc_committed_kv(TransContext *txc)
     cct->_conf->bluestore_log_op_age,
     [&](auto lat) {
       return ", txc = " + stringify(txc);
-    }
+    },
+    l_bluestore_slow_committed_kv_count
   );
 }
 
@@ -17332,7 +17362,8 @@ void BlueStore::log_latency(
   int idx,
   const ceph::timespan& l,
   double lat_threshold,
-  const char* info) const
+  const char* info,
+  int idx2) const
 {
   logger->tinc(idx, l);
   if (lat_threshold > 0.0 &&
@@ -17341,6 +17372,9 @@ void BlueStore::log_latency(
       << ", latency = " << l
       << info
       << dendl;
+    if (idx2 > l_bluestore_first && idx2 < l_bluestore_last) {
+      logger->inc(idx2);
+    }
   }
 }
 
@@ -17349,7 +17383,8 @@ void BlueStore::log_latency_fn(
   int idx,
   const ceph::timespan& l,
   double lat_threshold,
-  std::function<string (const ceph::timespan& lat)> fn) const
+  std::function<string (const ceph::timespan& lat)> fn,
+  int idx2) const
 {
   logger->tinc(idx, l);
   if (lat_threshold > 0.0 &&
@@ -17358,6 +17393,9 @@ void BlueStore::log_latency_fn(
       << ", latency = " << l
       << fn(l)
       << dendl;
+    if (idx2 > l_bluestore_first && idx2 < l_bluestore_last) {
+      logger->inc(idx2);
+    }
   }
 }
 

diff --git a/src/os/bluestore/BlueStore.h b/src/os/bluestore/BlueStore.h
index c3c53264ec1de1b6e78eaf86bb436e659e8cb433..46c1213231b18bbe50514d43cc374fd5fe4c79e7 100644 (file)
--- a/src/os/bluestore/BlueStore.h
+++ b/src/os/bluestore/BlueStore.h
@@ -214,6 +214,14 @@ enum {
   //****************************************
   l_bluestore_allocate_hist,
   //****************************************
+
+  // slow op counter
+  //****************************************
+  l_bluestore_slow_aio_wait_count,
+  l_bluestore_slow_committed_kv_count,
+  l_bluestore_slow_read_onode_meta_count,
+  l_bluestore_slow_read_wait_aio_count,
+  //****************************************
   l_bluestore_last
 };
 
@@ -3303,13 +3311,15 @@ public:
     int idx,
     const ceph::timespan& lat,
     double lat_threshold,
-    const char* info = "") const;
+    const char* info = "",
+    int idx2 = l_bluestore_first) const;
 
   inline void log_latency_fn(const char* name,
     int idx,
     const ceph::timespan& lat,
     double lat_threshold,
-    std::function<std::string (const ceph::timespan& lat)> fn) const;
+    std::function<std::string (const ceph::timespan& lat)> fn,
+    int idx2 = l_bluestore_first) const;
 
 private:
   bool _debug_data_eio(const ghobject_t& o) {