os/bluestore: add slow op detector for collection listing

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 bad93ac316e1981141dcecee56cec0d31ca27697..f2ced8cf382a13a12873ab195a7d05e2f0bfd865 100644 (file)
--- a/src/common/legacy_config_opts.h
+++ b/src/common/legacy_config_opts.h
@@ -1066,6 +1066,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(bluestore_debug_enforce_settings, OPT_STR)
 
 OPTION(kstore_max_ops, OPT_U64)

diff --git a/src/common/options.cc b/src/common/options.cc
index edbab7e6ed6a9b1625846ec13b56b1fd6c0ac9bd..d6bc2ab10e39885f223cc895dbd5b63ff2d63fd7 100644 (file)
--- a/src/common/options.cc
+++ b/src/common/options.cc
@@ -4829,6 +4829,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)"),
+
     Option("bluestore_debug_enforce_settings", Option::TYPE_STR, Option::LEVEL_DEV)
     .set_default("default")
     .set_enum_allowed({"default", "hdd", "ssd"})

diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc
index fcc7e08f2bc5d4b750834af7c135757ba22f4f38..3375fe803abc6d23739e25c166c1e9abc1a0ad11 100644 (file)
--- a/src/os/bluestore/BlueStore.cc
+++ b/src/os/bluestore/BlueStore.cc
@@ -4448,6 +4448,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);
 }
@@ -9202,6 +9204,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;
@@ -9301,7 +9304,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 faa0a02debed6dfc571631b22cb3a6d4f9933553..f711d0ceeacb2f7d8d55b5616a975064fb79ce3e 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
 };