From 00af2c411dec6c8a70f4a2c8e4b0398e348fd037 Mon Sep 17 00:00:00 2001
From: Igor Fedotov <ifedotov@suse.com>
Date: Wed, 17 Jul 2019 14:53:19 +0300
Subject: [PATCH] os/bluestore: parametrize latency threshold for log_latency
 funcs..

Signed-off-by: Igor Fedotov <ifedotov@suse.com>
---
 src/common/options.cc         |  2 +-
 src/os/bluestore/BlueStore.cc | 67 +++++++++++++++++++++++++----------
 src/os/bluestore/BlueStore.h  |  2 ++
 3 files changed, 52 insertions(+), 19 deletions(-)

diff --git a/src/common/options.cc b/src/common/options.cc
index 47cf024462d..edbab7e6ed6 100644
--- a/src/common/options.cc
+++ b/src/common/options.cc
@@ -4826,7 +4826,7 @@ std::vector<Option> get_global_options() {
     .set_description("log operation if it's slower than this age (seconds)"),
 
     Option("bluestore_log_omap_iterator_age", Option::TYPE_FLOAT, Option::LEVEL_ADVANCED)
-    .set_default(1)
+    .set_default(5)
     .set_description("log omap iteration operation if it's slower than this age (seconds)"),
 
     Option("bluestore_debug_enforce_settings", Option::TYPE_STR, Option::LEVEL_DEV)
diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc
index 9037b64d4d6..fcc7e08f2bc 100644
--- a/src/os/bluestore/BlueStore.cc
+++ b/src/os/bluestore/BlueStore.cc
@@ -3795,7 +3795,8 @@ int BlueStore::OmapIteratorImpl::seek_to_first()
   c->store->log_latency(
     __func__,
     l_bluestore_omap_seek_to_first_lat,
-    mono_clock::now() - start1);
+    mono_clock::now() - start1,
+    c->store->cct->_conf->bluestore_log_omap_iterator_age);
 
   return 0;
 }
@@ -3817,6 +3818,7 @@ int BlueStore::OmapIteratorImpl::upper_bound(const string& after)
     __func__,
     l_bluestore_omap_upper_bound_lat,
     mono_clock::now() - start1,
+    c->store->cct->_conf->bluestore_log_omap_iterator_age,
     [&] (const ceph::timespan& lat) {
       return ", after = " + after +
 	_stringify();
@@ -3842,6 +3844,7 @@ int BlueStore::OmapIteratorImpl::lower_bound(const string& to)
     __func__,
     l_bluestore_omap_lower_bound_lat,
     mono_clock::now() - start1,
+    c->store->cct->_conf->bluestore_log_omap_iterator_age,
     [&] (const ceph::timespan& lat) {
       return ", to = " + to +
 	_stringify();
@@ -3875,7 +3878,8 @@ int BlueStore::OmapIteratorImpl::next()
   c->store->log_latency(
     __func__,
     l_bluestore_omap_next_lat,
-    mono_clock::now() - start1);
+    mono_clock::now() - start1,
+    c->store->cct->_conf->bluestore_log_omap_iterator_age);
 
   return r;
 }
@@ -8395,7 +8399,9 @@ int BlueStore::read(
     auto start1 = mono_clock::now();
     OnodeRef o = c->get_onode(oid, false);
     log_latency("get_onode@read",
-      l_bluestore_read_onode_meta_lat, mono_clock::now() - start1);
+      l_bluestore_read_onode_meta_lat,
+      mono_clock::now() - start1,
+      cct->_conf->bluestore_log_op_age);
     if (!o || !o->exists) {
       r = -ENOENT;
       goto out;
@@ -8425,7 +8431,9 @@ int BlueStore::read(
 	   << " 0x" << std::hex << offset << "~" << length << std::dec
 	   << " = " << r << dendl;
   log_latency(__func__,
-    l_bluestore_read_lat, mono_clock::now() - start);
+    l_bluestore_read_lat,
+    mono_clock::now() - start,
+    cct->_conf->bluestore_log_op_age);
   return r;
 }
 
@@ -8518,7 +8526,9 @@ int BlueStore::_do_read(
   auto start = mono_clock::now();
   o->extent_map.fault_range(db, offset, length);
   log_latency(__func__,
-    l_bluestore_read_onode_meta_lat, mono_clock::now() - start);
+    l_bluestore_read_onode_meta_lat,
+    mono_clock::now() - start,
+    cct->_conf->bluestore_log_op_age);
   _dump_onode<30>(cct, *o);
 
   ready_regions_t ready_regions;
@@ -8716,6 +8726,7 @@ int BlueStore::_do_read(
   log_latency_fn(__func__,
     l_bluestore_read_wait_aio_lat,
     mono_clock::now() - start,
+    cct->_conf->bluestore_log_op_age,
     [&](auto lat) { return ", num_ios = " + stringify(num_ios); }
   );
 
@@ -8864,7 +8875,9 @@ int BlueStore::_verify_csum(OnodeRef& o,
     }
   }
   log_latency(__func__,
-    l_bluestore_csum_lat, mono_clock::now() - start);
+    l_bluestore_csum_lat,
+    mono_clock::now() - start,
+    cct->_conf->bluestore_log_op_age);
   if (cct->_conf->bluestore_ignore_data_csum) {
     return 0;
   }
@@ -8900,7 +8913,9 @@ int BlueStore::_decompress(bufferlist& source, bufferlist* result)
     }
   }
   log_latency(__func__,
-    l_bluestore_decompress_lat, mono_clock::now() - start);
+    l_bluestore_decompress_lat,
+    mono_clock::now() - start,
+    cct->_conf->bluestore_log_op_age);
   return r;
 }
 
@@ -10095,6 +10110,7 @@ void BlueStore::_txc_committed_kv(TransContext *txc)
     __func__,
     l_bluestore_commit_lat,
     ceph::make_timespan(ceph_clock_now() - txc->start),
+    cct->_conf->bluestore_log_op_age,
     [&](auto lat) {
       return ", txc = " + stringify(txc);
     }
@@ -10604,11 +10620,17 @@ void BlueStore::_kv_sync_thread()
 	  << " (" << dur_flush << " flush + " << dur_kv << " kv commit)"
 	  << dendl;
 	log_latency("kv_flush",
-	  l_bluestore_kv_flush_lat, dur_flush);
+	  l_bluestore_kv_flush_lat,
+	  dur_flush,
+	  cct->_conf->bluestore_log_op_age);
 	log_latency("kv_commit",
-	  l_bluestore_kv_commit_lat, dur_kv);
+	  l_bluestore_kv_commit_lat,
+	  dur_kv,
+	  cct->_conf->bluestore_log_op_age);
 	log_latency("kv_sync",
-	  l_bluestore_kv_sync_lat, dur);
+	  l_bluestore_kv_sync_lat,
+	  dur,
+	  cct->_conf->bluestore_log_op_age);
       }
 
       if (bluefs) {
@@ -10703,7 +10725,9 @@ void BlueStore::_kv_finalize_thread()
 	  (uint64_t)(alloc->get_fragmentation(min_alloc_size) * 1000));
 
       log_latency("kv_final",
-	l_bluestore_kv_final_lat, mono_clock::now() - start);
+	l_bluestore_kv_final_lat,
+	mono_clock::now() - start,
+	cct->_conf->bluestore_log_op_age);
 
       l.lock();
     }
@@ -11032,9 +11056,13 @@ int BlueStore::queue_transactions(
   }
 
   log_latency("submit_transact",
-    l_bluestore_submit_lat, mono_clock::now() - start);
+    l_bluestore_submit_lat,
+    mono_clock::now() - start,
+    cct->_conf->bluestore_log_op_age);
   log_latency("throttle_transact",
-    l_bluestore_throttle_lat, tend - tstart);
+    l_bluestore_throttle_lat,
+    tend - tstart,
+    cct->_conf->bluestore_log_op_age);
   return 0;
 }
 
@@ -12080,7 +12108,8 @@ int BlueStore::_do_alloc_write(
       }
       log_latency("compress@_do_alloc_write",
 	l_bluestore_compress_lat,
-        mono_clock::now() - start);
+        mono_clock::now() - start,
+	cct->_conf->bluestore_log_op_age );
     } else {
       need += wi.blob_length;
     }
@@ -13580,11 +13609,12 @@ void BlueStore::log_latency(
   const char* name,
   int idx,
   const ceph::timespan& l,
+  double lat_threshold,
   const char* info) const
 {
   logger->tinc(idx, l);
-  if (cct->_conf->bluestore_log_op_age > 0.0 &&
-      l >= make_timespan(cct->_conf->bluestore_log_op_age)) {
+  if (lat_threshold > 0.0 &&
+      l >= make_timespan(lat_threshold)) {
     dout(0) << __func__ << " slow operation observed for " << name
       << ", latency = " << l
       << info
@@ -13596,11 +13626,12 @@ void BlueStore::log_latency_fn(
   const char* name,
   int idx,
   const ceph::timespan& l,
+  double lat_threshold,
   std::function<string (const ceph::timespan& lat)> fn) const
 {
   logger->tinc(idx, l);
-  if (cct->_conf->bluestore_log_op_age > 0.0 &&
-      l >= make_timespan(cct->_conf->bluestore_log_op_age)) {
+  if (lat_threshold > 0.0 &&
+      l >= make_timespan(lat_threshold)) {
     dout(0) << __func__ << " slow operation observed for " << name
       << ", latency = " << l
       << fn(l)
diff --git a/src/os/bluestore/BlueStore.h b/src/os/bluestore/BlueStore.h
index f56bf677bda..faa0a02debe 100644
--- a/src/os/bluestore/BlueStore.h
+++ b/src/os/bluestore/BlueStore.h
@@ -2686,11 +2686,13 @@ public:
   inline void log_latency(const char* name,
     int idx,
     const ceph::timespan& lat,
+    double lat_threshold,
     const char* info = "") const;
 
   inline void log_latency_fn(const char* name,
     int idx,
     const ceph::timespan& lat,
+    double lat_threshold,
     std::function<string (const ceph::timespan& lat)> fn) const;
 
 private:
-- 
2.39.5