Merge lp:~david-goetz/swift/log_sleeps into lp:~hudson-openstack/swift/trunk

[David Goetz]

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

[gholt (gholt)]

review: Approve

[Chuck Thier (cthier)]

Makes J happy :)

review: Approve

=== modified file 'doc/source/ratelimit.rst'
--- doc/source/ratelimit.rst	2010-10-13 21:30:00 +0000
+++ doc/source/ratelimit.rst	2010-10-25 16:04:02 +0000
@@ -27,6 +27,9 @@
 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

=== modified file 'etc/proxy-server.conf-sample'
--- etc/proxy-server.conf-sample	2010-10-14 23:47:14 +0000
+++ etc/proxy-server.conf-sample	2010-10-25 16:04:02 +0000
@@ -60,7 +60,8 @@
 # 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
 

=== modified file 'swift/common/middleware/ratelimit.py'
--- swift/common/middleware/ratelimit.py	2010-10-20 17:31:50 +0000
+++ swift/common/middleware/ratelimit.py	2010-10-25 16:04:02 +0000
@@ -40,6 +40,8 @@
         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 @@
             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:

=== modified file 'test/unit/common/middleware/test_ratelimit.py'
--- test/unit/common/middleware/test_ratelimit.py	2010-10-20 18:05:38 +0000
+++ test/unit/common/middleware/test_ratelimit.py	2010-10-25 16:04:02 +0000
@@ -98,9 +98,12 @@
 
 
 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 @@
         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 @@
             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,