From dbe779a5687b52c83dfc341ad632a8f9d09b81c8 Mon Sep 17 00:00:00 2001
From: Sage Weil <sage@newdream.net>
Date: Wed, 18 Apr 2012 14:39:18 -0700
Subject: [PATCH] osd: dump old ops singly rather than all at once.

Fixes #2269. Convert the OpTracker::check_ops_in_flight interface
to take a vector<string> and create a separate warning for each old
Op, and dump those singly to the clog in the OSD.

Signed-off-by: Greg Farnum <gregory.farnum@dreamhost.com>
Reviewed-by: Sage Weil <sage@newdream.net>
---
 src/osd/OSD.cc       | 11 ++++++++---
 src/osd/OpRequest.cc | 22 +++++++++++++---------
 src/osd/OpRequest.h  | 12 +++++++++++-
 3 files changed, 32 insertions(+), 13 deletions(-)

diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc
index 7f158ed926123..af9b2f09759a9 100644
--- a/src/osd/OSD.cc
+++ b/src/osd/OSD.cc
@@ -1780,9 +1780,14 @@ void OSD::tick()
 
 void OSD::check_ops_in_flight()
 {
-  stringstream ss;
-  if (op_tracker.check_ops_in_flight(ss))
-    clog.warn(ss);
+  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;
+    }
+  }
   return;
 }
 
diff --git a/src/osd/OpRequest.cc b/src/osd/OpRequest.cc
index 1a5262a28af0a..461231a47ed85 100644
--- a/src/osd/OpRequest.cc
+++ b/src/osd/OpRequest.cc
@@ -64,7 +64,7 @@ void OpTracker::unregister_inflight_op(xlist<OpRequest*>::item *i)
   i->remove_myself();
 }
 
-bool OpTracker::check_ops_in_flight(ostream &out)
+bool OpTracker::check_ops_in_flight(std::vector<string> &warning_vector)
 {
   Mutex::Locker locker(ops_in_flight_lock);
   if (!ops_in_flight.size())
@@ -73,23 +73,27 @@ bool OpTracker::check_ops_in_flight(ostream &out)
   utime_t now = ceph_clock_now(g_ceph_context);
   utime_t too_old = now;
   too_old -= g_conf->osd_op_complaint_time;
-  
+
   dout(10) << "ops_in_flight.size: " << ops_in_flight.size()
-	   << "; oldest is " << now - ops_in_flight.front()->received_time
-	   << " seconds old" << dendl;
+           << "; oldest is " << now - ops_in_flight.front()->received_time
+           << " seconds old" << dendl;
   xlist<OpRequest*>::iterator i = ops_in_flight.begin();
+  warning_vector.reserve(ops_in_flight.size());
+  int warning_num = 0;
   while (!i.end() && (*i)->received_time < too_old) {
     // exponential backoff of warning intervals
     if ( ( (*i)->received_time +
-	   (g_conf->osd_op_complaint_time *
-	    (*i)->warn_interval_multiplier) )< now) {
-      out << "old request " << *((*i)->request) << " received at "
-	  << (*i)->received_time << " currently " << (*i)->state_string();
+           (g_conf->osd_op_complaint_time *
+            (*i)->warn_interval_multiplier) )< now) {
+      stringstream ss;
+      ss << "old request " << *((*i)->request) << " received at "
+          << (*i)->received_time << " currently " << (*i)->state_string();
       (*i)->warn_interval_multiplier *= 2;
+      warning_vector[warning_num++] = ss.str();
     }
     ++i;
   }
-  return !i.end();
+  return warning_num;
 }
 
 void OpTracker::mark_event(OpRequest *op, const string &dest)
diff --git a/src/osd/OpRequest.h b/src/osd/OpRequest.h
index 8c776ce41307c..011bbb272bbc7 100644
--- a/src/osd/OpRequest.h
+++ b/src/osd/OpRequest.h
@@ -15,6 +15,8 @@
 #define OPREQUEST_H_
 #include <sstream>
 #include <stdint.h>
+#include <vector>
+
 #include <include/utime.h>
 #include "common/Mutex.h"
 #include "include/xlist.h"
@@ -42,7 +44,15 @@ public:
   void dump_ops_in_flight(std::ostream& ss);
   void register_inflight_op(xlist<OpRequest*>::item *i);
   void unregister_inflight_op(xlist<OpRequest*>::item *i);
-  bool check_ops_in_flight(std::ostream &out);
+  /**
+   * 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
+   * with a warning string for each old Op.
+   * @return True if there are any Ops to warn on, false otherwise.
+   */
+  bool check_ops_in_flight(std::vector<string> &warning_strings);
   void mark_event(OpRequest *op, const string &evt);
   void _mark_event(OpRequest *op, const string &evt, utime_t now);
   OpRequestRef create_request(Message *req);
-- 
2.39.5