From: Igor Fedotov <ifedotov@suse.com>
Date: Wed, 27 Feb 2019 11:38:31 +0000 (+0300)
Subject: os/bluestore: track omap iterator latencies.
X-Git-Tag: v14.1.1~34^2~2
X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=2263f454c1bdc5471e59ccfc507467fb4a23a29b;p=ceph.git

os/bluestore: track omap iterator latencies.

Signed-off-by: Igor Fedotov <ifedotov@suse.com>
---

diff --git a/src/common/legacy_config_opts.h b/src/common/legacy_config_opts.h
index 13d0ee87cc15..0d0f6fc65585 100644
--- a/src/common/legacy_config_opts.h
+++ b/src/common/legacy_config_opts.h
@@ -1073,6 +1073,7 @@ OPTION(bluestore_debug_inject_csum_err_probability, OPT_FLOAT)
 OPTION(bluestore_no_per_pool_stats_tolerance, OPT_STR)
 OPTION(bluestore_warn_on_bluefs_spillover, OPT_BOOL)
 OPTION(bluestore_log_op_age, OPT_DOUBLE)
+OPTION(bluestore_log_omap_iterator_age, OPT_DOUBLE)
 
 OPTION(kstore_max_ops, OPT_U64)
 OPTION(kstore_max_bytes, OPT_U64)
diff --git a/src/common/options.cc b/src/common/options.cc
index 9b7d8129c989..69cc13d58c45 100644
--- a/src/common/options.cc
+++ b/src/common/options.cc
@@ -4721,9 +4721,13 @@ std::vector<Option> get_global_options() {
     .set_description("Enable health indication on bluefs slow device usage"),
 
     Option("bluestore_log_op_age", Option::TYPE_FLOAT, Option::LEVEL_ADVANCED)
-    .set_default(1)
+    .set_default(5)
     .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_description("log omap iteration operation if it's slower than this age (seconds)"),
+
     // -----------------------------------------
     // kstore
 
diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc
index 803fcc29c9b5..cdf5ffc91df0 100644
--- a/src/os/bluestore/BlueStore.cc
+++ b/src/os/bluestore/BlueStore.cc
@@ -3791,20 +3791,38 @@ BlueStore::OmapIteratorImpl::OmapIteratorImpl(
   }
 }
 
+string BlueStore::OmapIteratorImpl::_stringify() const
+{
+  stringstream s;
+  s << " omap_iterator(cid = " << c->cid
+    <<", oid = " << o->oid << ")";
+  return s.str();
+}
+
 int BlueStore::OmapIteratorImpl::seek_to_first()
 {
   RWLock::RLocker l(c->lock);
+  auto start1 = mono_clock::now();
   if (o->onode.has_omap()) {
     it->lower_bound(head);
   } else {
     it = KeyValueDB::Iterator();
   }
+  c->store->log_latency_fn(
+    l_bluestore_omap_seek_to_first_lat,
+    mono_clock::now() - start1,
+    [&] (const ceph::timespan& lat) {
+      return ", lat = " + timespan_str(lat) + _stringify();
+    }
+  );
+
   return 0;
 }
 
 int BlueStore::OmapIteratorImpl::upper_bound(const string& after)
 {
   RWLock::RLocker l(c->lock);
+  auto start1 = mono_clock::now();
   if (o->onode.has_omap()) {
     string key;
     get_omap_key(o->onode.nid, after, &key);
@@ -3814,12 +3832,21 @@ int BlueStore::OmapIteratorImpl::upper_bound(const string& after)
   } else {
     it = KeyValueDB::Iterator();
   }
+  c->store->log_latency_fn(
+    l_bluestore_omap_upper_bound_lat,
+    mono_clock::now() - start1,
+    [&] (const ceph::timespan& lat) {
+      return ", after = " + after + ", lat = " + timespan_str(lat) +
+	_stringify();
+    }
+  );
   return 0;
 }
 
 int BlueStore::OmapIteratorImpl::lower_bound(const string& to)
 {
   RWLock::RLocker l(c->lock);
+  auto start1 = mono_clock::now();
   if (o->onode.has_omap()) {
     string key;
     get_omap_key(o->onode.nid, to, &key);
@@ -3829,6 +3856,14 @@ int BlueStore::OmapIteratorImpl::lower_bound(const string& to)
   } else {
     it = KeyValueDB::Iterator();
   }
+  c->store->log_latency_fn(
+    l_bluestore_omap_lower_bound_lat,
+    mono_clock::now() - start1,
+    [&] (const ceph::timespan& lat) {
+      return ", to = " + to + ", lat = " + timespan_str(lat) +
+	_stringify();
+    }
+  );
   return 0;
 }
 
@@ -3847,13 +3882,22 @@ bool BlueStore::OmapIteratorImpl::valid()
 
 int BlueStore::OmapIteratorImpl::next()
 {
+  int r = -1;
   RWLock::RLocker l(c->lock);
+  auto start1 = mono_clock::now();
   if (o->onode.has_omap()) {
     it->next();
-    return 0;
-  } else {
-    return -1;
+    r = 0;
   }
+  c->store->log_latency_fn(
+    l_bluestore_omap_next_lat,
+    mono_clock::now() - start1,
+    [&] (const ceph::timespan& lat) {
+      return ", lat = " + timespan_str(lat) + _stringify();
+    }
+  );
+
+  return r;
 }
 
 string BlueStore::OmapIteratorImpl::key()
@@ -4387,6 +4431,14 @@ void BlueStore::_init_logger()
                     "Read operations that required at least one retry due to failed checksum validation");
   b.add_u64(l_bluestore_fragmentation, "bluestore_fragmentation_micros",
             "How fragmented bluestore free space is (free extents / max possible number of free extents) * 1000");
+  b.add_time_avg(l_bluestore_omap_seek_to_first_lat, "omap_seek_to_first_lat",
+    "Average omap iterator seek_to_first call latency");
+  b.add_time_avg(l_bluestore_omap_upper_bound_lat, "omap_upper_bound_lat",
+    "Average omap iterator upper_bound call latency");
+  b.add_time_avg(l_bluestore_omap_lower_bound_lat, "omap_lower_bound_lat",
+    "Average omap iterator lower_bound call latency");
+  b.add_time_avg(l_bluestore_omap_next_lat, "omap_next_lat",
+    "Average omap iterator next call latency");
   logger = b.create_perf_counters();
   cct->get_perfcounters_collection()->add(logger);
 }
@@ -13393,6 +13445,13 @@ int BlueStore::_merge_collection(
   return r;
 }
 
+void BlueStore::log_latency_fn(
+  int idx,
+  const ceph::timespan& l,
+  std::function<string (const ceph::timespan& lat)> fn)
+{
+  LOG_LATENCY_FN(logger, cct, idx, l, fn);
+}
 
 
 // DB key value Histogram
diff --git a/src/os/bluestore/BlueStore.h b/src/os/bluestore/BlueStore.h
index ed1cbbe15ea4..7dbe29706b27 100644
--- a/src/os/bluestore/BlueStore.h
+++ b/src/os/bluestore/BlueStore.h
@@ -123,6 +123,10 @@ enum {
   l_bluestore_read_eio,
   l_bluestore_reads_with_retries,
   l_bluestore_fragmentation,
+  l_bluestore_omap_seek_to_first_lat,
+  l_bluestore_omap_upper_bound_lat,
+  l_bluestore_omap_lower_bound_lat,
+  l_bluestore_omap_next_lat,
   l_bluestore_last
 };
 
@@ -1431,6 +1435,9 @@ public:
     OnodeRef o;
     KeyValueDB::Iterator it;
     string head, tail;
+
+    string _stringify() const;
+
   public:
     OmapIteratorImpl(CollectionRef c, OnodeRef o, KeyValueDB::Iterator it);
     int seek_to_first() override;
@@ -2656,6 +2663,10 @@ public:
   */
   int allocate_bluefs_freespace(uint64_t size, PExtentVector* extents);
 
+  void log_latency_fn(int idx,
+		      const ceph::timespan& lat,
+		      std::function<string (const ceph::timespan& lat)> fn);
+
 private:
   bool _debug_data_eio(const ghobject_t& o) {
     if (!cct->_conf->bluestore_debug_inject_read_err) {