common/OpTracker: refactor check_ops_in_flight()

* add a function visit_ops_in_flight() so it accepts a std::function,
  which can be applied to all ops in flight. and is used to count
  slow ops. the # of slow ops will be sent to mgr.
* add a function with_slow_ops_in_flight(), so we can use it to
  implement command like "dump_slow_ops_in_flight". unlike the
  existing feature which dumps slow ops to clog periodically, it
  will dump the slow ops on demand. and backoff the warning
  interval only when the slow ops are dumped.

Signed-off-by: Kefu Chai <kchai@redhat.com>

diff --git a/src/common/TrackedOp.cc b/src/common/TrackedOp.cc
index c89be0b60a333054b7d63a4576ffd648334197fa..2948bfe0e967db9b5a7ff5f70c639f05913e9a52 100644 (file)
--- a/src/common/TrackedOp.cc
+++ b/src/common/TrackedOp.cc
@@ -284,21 +284,19 @@ void OpTracker::unregister_inflight_op(TrackedOp *i)
   }
 }
 
-bool OpTracker::check_ops_in_flight(std::vector<string> &warning_vector, int *slow)
+bool OpTracker::visit_ops_in_flight(utime_t* oldest_secs,
+                                   std::function<bool(TrackedOp&)>&& visit)
 {
   if (!tracking_enabled)
     return false;
 
-  RWLock::RLocker l(lock);
-  utime_t now = ceph_clock_now();
-  utime_t too_old = now;
-  too_old -= complaint_time;
+  const utime_t now = ceph_clock_now();
   utime_t oldest_op = now;
   uint64_t total_ops_in_flight = 0;
 
-  for (uint32_t i = 0; i < num_optracker_shards; i++) {
-    ShardedTrackingData* sdata = sharded_in_flight_list[i];
-    assert(NULL != sdata);
+  RWLock::RLocker l(lock);
+  for (const auto sdata : sharded_in_flight_list) {
+    assert(sdata);
     Mutex::Locker locker(sdata->ops_in_flight_lock_sharded);
     if (!sdata->ops_in_flight_sharded.empty()) {
       utime_t oldest_op_tmp =
@@ -309,72 +307,102 @@ bool OpTracker::check_ops_in_flight(std::vector<string> &warning_vector, int *sl
     }
     total_ops_in_flight += sdata->ops_in_flight_sharded.size();
   }
-
-  if (0 == total_ops_in_flight)
+  if (!total_ops_in_flight)
     return false;
-
-  utime_t oldest_secs = now - oldest_op;
-
+  *oldest_secs = now - oldest_op;
   dout(10) << "ops_in_flight.size: " << total_ops_in_flight
-           << "; oldest is " << oldest_secs
+           << "; oldest is " << *oldest_secs
            << " seconds old" << dendl;
 
-  if (oldest_secs < complaint_time)
+  if (*oldest_secs < complaint_time)
     return false;
 
-  warning_vector.reserve(log_threshold + 1);
-  //store summary message
-  warning_vector.push_back("");
-
-  int _slow = 0;    // total slow
-  if (!slow)
-    slow = &_slow; 
-  else
-    *slow = _slow;  // start from 0 anyway
-  int warned = 0;   // total logged
   for (uint32_t iter = 0; iter < num_optracker_shards; iter++) {
     ShardedTrackingData* sdata = sharded_in_flight_list[iter];
     assert(NULL != sdata);
     Mutex::Locker locker(sdata->ops_in_flight_lock_sharded);
-    if (sdata->ops_in_flight_sharded.empty())
-      continue;
-    auto i = sdata->ops_in_flight_sharded.begin();
-    while (i != sdata->ops_in_flight_sharded.end() &&
-          i->get_initiated() < too_old) {
-      (*slow)++;
-
-      // exponential backoff of warning intervals
-      if (warned < log_threshold &&
-         (i->get_initiated() + (complaint_time *
-                                i->warn_interval_multiplier)) < now) {
-        // will warn, increase counter
-        warned++;
-
-        utime_t age = now - i->get_initiated();
-        stringstream ss;
-        ss << "slow request " << age << " seconds old, received at "
-           << i->get_initiated() << ": " << i->get_desc()
-          << " currently "
-          << (i->current ? i->current : i->state_string());
-        warning_vector.push_back(ss.str());
-
-        // only those that have been shown will backoff
-        i->warn_interval_multiplier *= 2;
-      }
-      ++i;
+    for (auto& op : sdata->ops_in_flight_sharded) {
+      if (!visit(op))
+       break;
     }
   }
+  return true;
+}
 
-  // only summarize if we warn about any.  if everything has backed
-  // off, we will stay silent.
-  if (warned > 0) {
+bool OpTracker::with_slow_ops_in_flight(utime_t* oldest_secs,
+                                       int* num_slow_ops,
+                                       std::function<void(TrackedOp&)>&& on_warn)
+{
+  const utime_t now = ceph_clock_now();
+  auto too_old = now;
+  too_old -= complaint_time;
+  int slow = 0;
+  int warned = 0;
+  auto check = [&](TrackedOp& op) {
+    if (op.get_initiated() >= too_old) {
+      // no more slow ops in flight
+      return false;
+    }
+    slow++;
+    if (warned >= log_threshold) {
+      // enough samples of slow ops
+      return true;
+    }
+    auto time_to_complain = (op.get_initiated() +
+                            complaint_time * op.warn_interval_multiplier);
+    if (time_to_complain >= now) {
+      // complain later if the op is still in flight
+      return true;
+    }
+    // will warn, increase counter
+    warned++;
+    on_warn(op);
+    return true;
+  };
+  if (visit_ops_in_flight(oldest_secs, check)) {
+    if (num_slow_ops) {
+      *num_slow_ops = slow;
+    }
+    return true;
+  } else {
+    return false;
+  }
+}
+
+bool OpTracker::check_ops_in_flight(std::string* summary,
+                                   std::vector<string> &warnings,
+                                   int *num_slow_ops)
+{
+  const utime_t now = ceph_clock_now();
+  auto too_old = now;
+  too_old -= complaint_time;
+  int warned = 0;
+  utime_t oldest_secs;
+  auto warn_on_slow_op = [&](TrackedOp& op) {
+    stringstream ss;
+    utime_t age = now - op.get_initiated();
+    ss << "slow request " << age << " seconds old, received at "
+       << op.get_initiated() << ": " << op.get_desc()
+       << " currently "
+        << (op.current ? op.current : op.state_string());
+    warnings.push_back(ss.str());
+    // only those that have been shown will backoff
+    op.warn_interval_multiplier *= 2;
+  };
+  int slow = 0;
+  if (with_slow_ops_in_flight(&oldest_secs, &slow, warn_on_slow_op)) {
     stringstream ss;
-    ss << *slow << " slow requests, " << warned << " included below; oldest blocked for > "
+    ss << slow << " slow requests, "
+       << warned << " included below; oldest blocked for > "
        << oldest_secs << " secs";
-    warning_vector[0] = ss.str();
+    *summary = ss.str();
+    if (num_slow_ops) {
+      *num_slow_ops = slow;
+    }
+    return true;
+  } else {
+    return false;
   }
-
-  return warned > 0;
 }
 
 void OpTracker::get_age_ms_histogram(pow2_hist_t *h)

diff --git a/src/common/TrackedOp.h b/src/common/TrackedOp.h
index 710b3bdacaf379da5aa93691c3448a83a5372094..c4731642c8b80b7ea94f88d671295e8111b696b5 100644 (file)
--- a/src/common/TrackedOp.h
+++ b/src/common/TrackedOp.h
@@ -100,16 +100,41 @@ public:
 
   void get_age_ms_histogram(pow2_hist_t *h);
 
+  /**
+   * walk through ops in flight
+   *
+   * @param oldest_sec the amount of time since the oldest op was initiated
+   * @param check a function consuming tracked ops, the function returns
+   *              false if it don't want to be fed with more ops
+   * @return True if there are any Ops to warn on, false otherwise
+   */
+  bool visit_ops_in_flight(utime_t* oldest_secs,
+                          std::function<bool(TrackedOp&)>&& visit);
+  /**
+   * walk through slow ops in flight
+   *
+   * @param[out] oldest_sec the amount of time since the oldest op was initiated
+   * @param[out] num_slow_ops total number of slow ops
+   * @param on_warn a function consuming tracked ops, the function returns
+   *                false if it don't want to be fed with more ops
+   * @return True if there are any Ops to warn on, false otherwise
+   */
+  bool with_slow_ops_in_flight(utime_t* oldest_secs,
+                              int* num_slow_ops,
+                              std::function<void(TrackedOp&)>&& on_warn);
   /**
    * Look for Ops which are too old, and insert warning
    * strings for each Op that is too old.
    *
-   * @param warning_strings A vector<string> reference which is filled
+   * @param summary[out] a string summarizing slow Ops.
+   * @param warning_strings[out] A vector<string> reference which is filled
    * with a warning string for each old Op.
+   * @param slow[out] total number of slow ops
    * @return True if there are any Ops to warn on, false otherwise.
    */
-  bool check_ops_in_flight(std::vector<string> &warning_strings,
-                          int *slow = NULL);
+  bool check_ops_in_flight(std::string* summary,
+                          std::vector<string> &warning_strings,
+                          int* slow = nullptr);
 
   void on_shutdown() {
     history.on_shutdown();

diff --git a/src/mds/MDSRank.cc b/src/mds/MDSRank.cc
index 51ae378947f57f30fbb44557670b2ce98e36a775..82606474ce8681542546903479faabfd255bdb15 100644 (file)
--- a/src/mds/MDSRank.cc
+++ b/src/mds/MDSRank.cc
@@ -2637,13 +2637,13 @@ void MDSRank::create_logger()
 
 void MDSRank::check_ops_in_flight()
 {
+  string summary;
   vector<string> warnings;
   int slow = 0;
-  if (op_tracker.check_ops_in_flight(warnings, &slow)) {
-    for (vector<string>::iterator i = warnings.begin();
-        i != warnings.end();
-        ++i) {
-      clog->warn() << *i;
+  if (op_tracker.check_ops_in_flight(&summary, warnings, &slow)) {
+    clog->warn() << summary;
+    for (const auto& warning : warnings) {
+      clog->warn() << warning;
     }
   }
  

diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc
index 0c72845e44acb1c5df114fdb80c00a03c1ef70e7..dee9f7ab1eb93658bf7ab8d683880972e4682c53 100644 (file)
--- a/src/osd/OSD.cc
+++ b/src/osd/OSD.cc
@@ -5025,12 +5025,12 @@ void OSD::tick_without_osd_lock()
 
 void OSD::check_ops_in_flight()
 {
+  string summary;
   vector<string> warnings;
-  if (op_tracker.check_ops_in_flight(warnings)) {
-    for (vector<string>::iterator i = warnings.begin();
-        i != warnings.end();
-        ++i) {
-      clog->warn() << *i;
+  if (op_tracker.check_ops_in_flight(&summary, warnings)) {
+    clog->warn() << summary;
+    for (const auto& warning : warnings) {
+      clog->warn() << warning;
     }
   }
 }