From: Igor Fedotov <ifedotov@suse.com>
Date: Wed, 17 Jul 2019 12:39:52 +0000 (+0300)
Subject: os/bluestore: add slow op detector for collection listing
X-Git-Tag: v14.2.3~118^2
X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=refs%2Fpull%2F29227%2Fhead;p=ceph.git

os/bluestore: add slow op detector for collection listing

Signed-off-by: Igor Fedotov <ifedotov@suse.com>
(cherry picked from commit 5218e5ee6e741dd65b9d1c9b366c135b7b000b6b)

 Conflicts:
	src/common/legacy_config_opts.h
	src/common/options.cc
trivial
---

diff --git a/src/common/legacy_config_opts.h b/src/common/legacy_config_opts.h
index ecf0e6875e9ed..f10270b9d9172 100644
--- a/src/common/legacy_config_opts.h
+++ b/src/common/legacy_config_opts.h
@@ -1076,6 +1076,7 @@ OPTION(bluestore_warn_on_bluefs_spillover, OPT_BOOL)
 OPTION(bluestore_warn_on_legacy_statfs, OPT_BOOL)
 OPTION(bluestore_log_op_age, OPT_DOUBLE)
 OPTION(bluestore_log_omap_iterator_age, OPT_DOUBLE)
+OPTION(bluestore_log_collection_list_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 d79dd51fc9a81..97f1d37899821 100644
--- a/src/common/options.cc
+++ b/src/common/options.cc
@@ -4830,6 +4830,10 @@ std::vector<Option> get_global_options() {
     .set_default(5)
     .set_description("log omap iteration operation if it's slower than this age (seconds)"),
 
+    Option("bluestore_log_collection_list_age", Option::TYPE_FLOAT, Option::LEVEL_ADVANCED)
+    .set_default(60)
+    .set_description("log collection list 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 2ba1e3a96fabb..42be0d02ae574 100644
--- a/src/os/bluestore/BlueStore.cc
+++ b/src/os/bluestore/BlueStore.cc
@@ -4514,6 +4514,8 @@ void BlueStore::_init_logger()
     "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");
+  b.add_time_avg(l_bluestore_clist_lat, "clist_lat",
+    "Average collection listing latency");
   logger = b.create_perf_counters();
   cct->get_perfcounters_collection()->add(logger);
 }
@@ -9227,6 +9229,7 @@ int BlueStore::_collection_list(
   if (!c->exists)
     return -ENOENT;
 
+  auto start_time = mono_clock::now();
   int r = 0;
   ghobject_t static_next;
   KeyValueDB::Iterator it;
@@ -9326,7 +9329,20 @@ out:
   if (!set_next) {
     *pnext = ghobject_t::get_max();
   }
-
+  log_latency_fn(
+    __func__,
+    l_bluestore_clist_lat,
+    mono_clock::now() - start_time,
+    cct->_conf->bluestore_log_collection_list_age,
+    [&] (const ceph::timespan& lat) {
+      ostringstream ostr;
+      ostr << ", lat = " << timespan_str(lat)
+           << " cid =" << c->cid
+           << " start " << start << " end " << end
+           << " max " << max;
+      return ostr.str();
+    }
+  );
   return r;
 }
 
diff --git a/src/os/bluestore/BlueStore.h b/src/os/bluestore/BlueStore.h
index 1ec057c025367..84a6e3961c101 100644
--- a/src/os/bluestore/BlueStore.h
+++ b/src/os/bluestore/BlueStore.h
@@ -127,6 +127,7 @@ enum {
   l_bluestore_omap_upper_bound_lat,
   l_bluestore_omap_lower_bound_lat,
   l_bluestore_omap_next_lat,
+  l_bluestore_clist_lat,
   l_bluestore_last
 };