Allow visibility into ratelimit sleeps by logging sleeps that exceed a given config value.

doc/source/ratelimit.rst

@@ -27,6 +27,9 @@ clock_accuracy           1000       Represents how accurate the proxy servers'
 max_sleep_time_seconds   60         App will immediately return a 498 response
                                     if the necessary sleep time ever exceeds
                                     the given max_sleep_time_seconds.
+log_sleep_time_seconds   0          To allow visibility into rate limiting set
+                                    this value > 0 and all sleeps greater than
+                                    the number will be logged.
 account_ratelimit        0          If set, will limit all requests to
                                     /account_name and PUTs to
                                     /account_name/container_name. Number is in

etc/proxy-server.conf-sample

@@ -60,7 +60,8 @@ use = egg:swift#ratelimit
 # clock accuracy.
 # clock_accuracy = 1000
 # max_sleep_time_seconds = 60
-
+# log_sleep_time_seconds of 0 means disabled
+# log_sleep_time_seconds = 0
 # account_ratelimit of 0 means disabled
 # account_ratelimit = 0
 

swift/common/middleware/ratelimit.py

@@ -40,6 +40,8 @@ class RateLimitMiddleware(object):
         self.account_ratelimit = float(conf.get('account_ratelimit', 0))
         self.max_sleep_time_seconds = float(conf.get('max_sleep_time_seconds',
                                                    60))
+        self.log_sleep_time_seconds = float(conf.get('log_sleep_time_seconds',
+                                                   0))
         self.clock_accuracy = int(conf.get('clock_accuracy', 1000))
         self.ratelimit_whitelist = [acc.strip() for acc in
             conf.get('account_whitelist', '').split(',')
@@ -176,6 +178,11 @@ class RateLimitMiddleware(object):
             obj_name=obj_name):
             try:
                 need_to_sleep = self._get_sleep_time(key, max_rate)
+                if self.log_sleep_time_seconds and \
+                        need_to_sleep > self.log_sleep_time_seconds:
+                    self.logger.info("Ratelimit sleep log: %s for %s/%s/%s" % (
+                            need_to_sleep, account_name,
+                            container_name, obj_name))
                 if need_to_sleep > 0:
                     eventlet.sleep(need_to_sleep)
             except MaxSleepTimeHit, e:

test/unit/common/middleware/test_ratelimit.py

@@ -98,9 +98,12 @@ class FakeApp(object):
 
 
 class FakeLogger(object):
+    # a thread safe logger
 
     def error(self, msg):
-        # a thread safe logger
+        pass
+
+    def info(self, msg):
         pass
 
 
@@ -289,7 +292,7 @@ class TestRateLimit(unittest.TestCase):
         the_498s = [t for t in all_results if t.startswith('Slow down')]
         self.assertEquals(len(the_498s), 2)
         time_took = time.time() - begin
-        self.assert_(1.5 <= round(time_took,1) < 1.7, time_took)
+        self.assert_(1.5 <= round(time_took, 1) < 1.7, time_took)
 
     def test_ratelimit_max_rate_multiple_acc(self):
         num_calls = 4
@@ -326,7 +329,7 @@ class TestRateLimit(unittest.TestCase):
             thread.join()
         time_took = time.time() - begin
         # the all 15 threads still take 1.5 secs
-        self.assert_(1.5 <= round(time_took,1) < 1.7)
+        self.assert_(1.5 <= round(time_took, 1) < 1.7)
 
     def test_ratelimit_acc_vrs_container(self):
         conf_dict = {'clock_accuracy': 1000,