From 5218e5ee6e741dd65b9d1c9b366c135b7b000b6b Mon Sep 17 00:00:00 2001
From: Igor Fedotov <ifedotov@suse.com>
Date: Wed, 17 Jul 2019 15:39:52 +0300
Subject: [PATCH] os/bluestore: add slow op detector for collection listing

Signed-off-by: Igor Fedotov <ifedotov@suse.com>
---
 src/common/legacy_config_opts.h |  1 +
 src/common/options.cc           |  4 ++++
 src/os/bluestore/BlueStore.cc   | 18 +++++++++++++++++-
 src/os/bluestore/BlueStore.h    |  1 +
 4 files changed, 23 insertions(+), 1 deletion(-)

diff --git a/src/common/legacy_config_opts.h b/src/common/legacy_config_opts.h
index bad93ac316e..f2ced8cf382 100644
--- 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 edbab7e6ed6..d6bc2ab10e3 100644
--- 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 fcc7e08f2bc..3375fe803ab 100644
--- 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 faa0a02debe..f711d0ceeac 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
 };
 
-- 
2.39.5