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 ecf0e6875e9eda0849f5de37bf4dde43b4c08a7e..f10270b9d917254186eda99737f1ffee318a1010 100644 (file)
--- 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 d79dd51fc9a811b492bfb1669741e983b824f801..97f1d378998216e4a1266219a10b7a64b5e1ff1d 100644 (file)
--- 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 2ba1e3a96fabba7af3351025d76195a19d0664db..42be0d02ae5748b5165500b60431d239a6f92ec0 100644 (file)
--- 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 1ec057c0253679a7e22620a208a9dcc45fbd6a14..84a6e3961c1013d43041646e07d3cdd751089096 100644 (file)
--- 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
 };