[RFC PATCH 2/6] common/Throttle: track sleep/wake sequences in Throttle, report them for policy throttler

["Jim Schutt" <jaschut@xxxxxxxxxx>]

This simplifies post-processing logs to discover to what extent message
wait time in the policy throttler is due to thread wakeup order.

Use get()/wait() arguments rather than an accessor function to minimize
confusion from inconsistent reporting caused by racing on the Throttle mutex.

Signed-off-by: Jim Schutt <jaschut@xxxxxxxxxx>
---
 src/common/Throttle.h      |   24 ++++++++++++++++++++----
 src/msg/SimpleMessenger.cc |    6 +++++-
 2 files changed, 25 insertions(+), 5 deletions(-)

diff --git a/src/common/Throttle.h b/src/common/Throttle.h
index f13fde0..10560bf 100644
--- a/src/common/Throttle.h
+++ b/src/common/Throttle.h
@@ -6,11 +6,12 @@
 
 class Throttle {
   int64_t count, max, waiting;
+  uint64_t sseq, wseq;
   Mutex lock;
   Cond cond;
   
 public:
-  Throttle(int64_t m = 0) : count(0), max(m), waiting(0),
+  Throttle(int64_t m = 0) : count(0), max(m), waiting(0), sseq(0), wseq(0),
 			  lock("Throttle::lock") {
     assert(m >= 0);
   }
@@ -52,13 +53,21 @@ public:
 
   int64_t get_max() { return max; }
 
-  bool wait(int64_t m = 0) {
+  bool wait(int64_t m = 0,
+	    uint64_t *sleep_seq = NULL, uint64_t *wake_seq = NULL) {
     Mutex::Locker l(lock);
+    sseq++;
+    if (sleep_seq)
+      *sleep_seq = sseq;
     if (m) {
       assert(m > 0);
       _reset_max(m);
     }
-    return _wait(0);
+    bool r = _wait(0);
+    wseq++;
+    if (wake_seq)
+      *wake_seq = wseq;
+    return r;
   }
 
   int64_t take(int64_t c = 1) {
@@ -68,15 +77,22 @@ public:
     return count;
   }
 
-  void get(int64_t c = 1, int64_t m = 0) {
+  void get(int64_t c = 1, int64_t m = 0,
+	   uint64_t *sleep_seq = NULL, uint64_t *wake_seq = NULL) {
     assert(c >= 0);
     Mutex::Locker l(lock);
+    sseq++;
+    if (sleep_seq)
+      *sleep_seq = sseq;
     if (m) {
       assert(m > 0);
       _reset_max(m);
     }
     _wait(c);
     count += c;
+    wseq++;
+    if (wake_seq)
+      *wake_seq = wseq;
   }
 
   /* Returns true if it successfully got the requested amount,
diff --git a/src/msg/SimpleMessenger.cc b/src/msg/SimpleMessenger.cc
index 952ed7c..259d3b7 100644
--- a/src/msg/SimpleMessenger.cc
+++ b/src/msg/SimpleMessenger.cc
@@ -1898,7 +1898,11 @@ int SimpleMessenger::Pipe::read_message(Message **pm)
       ldout(msgr->cct,10) << "reader wants " << message_size << " from policy throttler "
 	       << policy.throttler->get_current() << "/"
 	       << policy.throttler->get_max() << dendl;
-      policy.throttler->get(message_size);
+      uint64_t sseq, wseq;
+      policy.throttler->get(message_size, 0, &sseq, &wseq);
+      ldout(msgr->cct,10) << "reader got " << message_size << " from policy throttler "
+	     <<  policy.throttler->get_current() << "/" << policy.throttler->get_max()
+	     << " " << sseq << "/" << wseq << dendl;
     }
 
     // throttle total bytes waiting for dispatch.  do this _after_ the
-- 
1.7.1


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html