diff --git a/swift/common/memcached.py b/swift/common/memcached.py index 6a953852c6..74ec8efc77 100644 --- a/swift/common/memcached.py +++ b/swift/common/memcached.py @@ -57,7 +57,8 @@ from eventlet import Timeout from six.moves import range from six.moves.configparser import ConfigParser, NoSectionError, NoOptionError from swift.common import utils -from swift.common.utils import md5, human_readable, config_true_value +from swift.common.utils import md5, human_readable, config_true_value, \ + memcached_timing_stats DEFAULT_MEMCACHED_PORT = 11211 @@ -75,6 +76,11 @@ ERROR_LIMIT_COUNT = 10 ERROR_LIMIT_TIME = ERROR_LIMIT_DURATION = 60 DEFAULT_ITEM_SIZE_WARNING_THRESHOLD = -1 +# Different sample rates for emitting Memcached timing stats. +TIMING_SAMPLE_RATE_HIGH = 0.1 +TIMING_SAMPLE_RATE_MEDIUM = 0.01 +TIMING_SAMPLE_RATE_LOW = 0.001 + def md5hash(key): if not isinstance(key, bytes): @@ -292,6 +298,9 @@ class MemcacheRing(object): """Returns a server connection to the pool.""" self._client_cache[server].put((fp, sock)) + # Sample rates of different memcached operations are based on generic + # swift usage patterns. + @memcached_timing_stats(sample_rate=TIMING_SAMPLE_RATE_HIGH) def set(self, key, value, serialize=True, time=0, min_compress_len=0, raise_on_error=False): """ @@ -348,6 +357,7 @@ class MemcacheRing(object): raise MemcacheConnectionError( "No memcached connections succeeded.") + @memcached_timing_stats(sample_rate=TIMING_SAMPLE_RATE_MEDIUM) def get(self, key, raise_on_error=False): """ Gets the object specified by key. It will also unserialize the object @@ -387,6 +397,7 @@ class MemcacheRing(object): raise MemcacheConnectionError( "No memcached connections succeeded.") + @memcached_timing_stats(sample_rate=TIMING_SAMPLE_RATE_LOW) def incr(self, key, delta=1, time=0): """ Increments a key which has a numeric value by delta. @@ -442,6 +453,7 @@ class MemcacheRing(object): self._exception_occurred(server, e, sock=sock, fp=fp) raise MemcacheConnectionError("No Memcached connections succeeded.") + @memcached_timing_stats(sample_rate=TIMING_SAMPLE_RATE_LOW) def decr(self, key, delta=1, time=0): """ Decrements a key which has a numeric value by delta. Calls incr with @@ -457,6 +469,7 @@ class MemcacheRing(object): """ return self.incr(key, delta=-delta, time=time) + @memcached_timing_stats(sample_rate=TIMING_SAMPLE_RATE_HIGH) def delete(self, key, server_key=None): """ Deletes a key/value pair from memcache. @@ -478,6 +491,7 @@ class MemcacheRing(object): except (Exception, Timeout) as e: self._exception_occurred(server, e, sock=sock, fp=fp) + @memcached_timing_stats(sample_rate=TIMING_SAMPLE_RATE_HIGH) def set_multi(self, mapping, server_key, serialize=True, time=0, min_compress_len=0): """ @@ -518,6 +532,7 @@ class MemcacheRing(object): except (Exception, Timeout) as e: self._exception_occurred(server, e, sock=sock, fp=fp) + @memcached_timing_stats(sample_rate=TIMING_SAMPLE_RATE_HIGH) def get_multi(self, keys, server_key): """ Gets multiple values from memcache for the given keys. diff --git a/swift/common/utils.py b/swift/common/utils.py index 6fb492a773..35698dc4e6 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -2035,6 +2035,26 @@ def timing_stats(**dec_kwargs): return decorating_func +def memcached_timing_stats(**dec_kwargs): + """ + Returns a decorator that logs timing events or errors for public methods in + MemcacheRing class, such as memcached set, get and etc. + """ + def decorating_func(func): + method = func.__name__ + + @functools.wraps(func) + def _timing_stats(cache, *args, **kwargs): + start_time = time.time() + result = func(cache, *args, **kwargs) + cache.logger.timing_since( + 'memcached.' + method + '.timing', start_time, **dec_kwargs) + return result + + return _timing_stats + return decorating_func + + class SwiftLoggerAdapter(logging.LoggerAdapter): """ A logging.LoggerAdapter subclass that also passes through StatsD method diff --git a/test/probe/test_sharder.py b/test/probe/test_sharder.py index 757dda84c9..552c77ba9b 100644 --- a/test/probe/test_sharder.py +++ b/test/probe/test_sharder.py @@ -38,6 +38,7 @@ from swiftclient import client, get_auth, ClientException from swift.proxy.controllers.base import get_cache_key from swift.proxy.controllers.obj import num_container_updates from test import annotate_failure +from test.debug_logger import debug_logger from test.probe import PROXY_BASE_URL from test.probe.brain import BrainSplitter from test.probe.common import ReplProbeTest, get_server_number, \ @@ -126,7 +127,8 @@ class BaseTestContainerSharding(ReplProbeTest): self.init_brain(self.container_name) self.sharders = Manager(['container-sharder']) self.internal_client = self.make_internal_client() - self.memcache = MemcacheRing(['127.0.0.1:11211']) + self.logger = debug_logger('sharder-test') + self.memcache = MemcacheRing(['127.0.0.1:11211'], logger=self.logger) self.container_replicators = Manager(['container-replicator']) def init_brain(self, container_name): diff --git a/test/unit/common/test_memcached.py b/test/unit/common/test_memcached.py index 75786d8632..ace7f30084 100644 --- a/test/unit/common/test_memcached.py +++ b/test/unit/common/test_memcached.py @@ -1048,6 +1048,56 @@ class TestMemcached(unittest.TestCase): # Let's do a big number do_test('1' * 2048576, 1000000, True) + def test_operations_timing_stats(self): + memcache_client = memcached.MemcacheRing(['1.2.3.4:11211'], + logger=self.logger) + mock = MockMemcached() + memcache_client._client_cache['1.2.3.4:11211'] = MockedMemcachePool( + [(mock, mock)] * 2) + + with patch('time.time',) as mock_time: + mock_time.return_value = 1000.99 + memcache_client.set('some_key', [1, 2, 3]) + last_stats = self.logger.log_dict['timing_since'][-1] + self.assertEqual('memcached.set.timing', last_stats[0][0]) + self.assertEqual(last_stats[0][1], 1000.99) + mock_time.return_value = 2000.99 + self.assertEqual(memcache_client.get('some_key'), [1, 2, 3]) + last_stats = self.logger.log_dict['timing_since'][-1] + self.assertEqual('memcached.get.timing', last_stats[0][0]) + self.assertEqual(last_stats[0][1], 2000.99) + mock_time.return_value = 3000.99 + self.assertEqual(memcache_client.decr('decr_key', delta=5), 0) + last_stats = self.logger.log_dict['timing_since'][-1] + self.assertEqual('memcached.decr.timing', last_stats[0][0]) + self.assertEqual(last_stats[0][1], 3000.99) + mock_time.return_value = 4000.99 + self.assertEqual(memcache_client.incr('decr_key', delta=5), 5) + last_stats = self.logger.log_dict['timing_since'][-1] + self.assertEqual('memcached.incr.timing', last_stats[0][0]) + self.assertEqual(last_stats[0][1], 4000.99) + mock_time.return_value = 5000.99 + memcache_client.set_multi( + {'some_key1': [1, 2, 3], 'some_key2': [4, 5, 6]}, 'multi_key') + last_stats = self.logger.log_dict['timing_since'][-1] + self.assertEqual('memcached.set_multi.timing', last_stats[0][0]) + self.assertEqual(last_stats[0][1], 5000.99) + mock_time.return_value = 6000.99 + self.assertEqual( + memcache_client.get_multi( + ('some_key2', 'some_key1'), + 'multi_key'), + [[4, 5, 6], + [1, 2, 3]]) + last_stats = self.logger.log_dict['timing_since'][-1] + self.assertEqual('memcached.get_multi.timing', last_stats[0][0]) + self.assertEqual(last_stats[0][1], 6000.99) + mock_time.return_value = 7000.99 + memcache_client.delete('some_key') + last_stats = self.logger.log_dict['timing_since'][-1] + self.assertEqual('memcached.delete.timing', last_stats[0][0]) + self.assertEqual(last_stats[0][1], 7000.99) + class ExcConfigParser(object): diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index 02b32f8330..b0e8d51c71 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -5763,6 +5763,40 @@ class TestStatsdLogging(unittest.TestCase): self.assertEqual(mock_controller.args[0], 'METHOD.errors.timing') self.assertTrue(mock_controller.args[1] > 0) + def test_memcached_timing_stats(self): + class MockMemcached(object): + def __init__(self): + self.logger = self + self.args = () + self.called = 'UNKNOWN' + + def timing_since(self, *args): + self.called = 'timing' + self.args = args + + @utils.memcached_timing_stats() + def set(cache): + pass + + @utils.memcached_timing_stats() + def get(cache): + pass + + mock_cache = MockMemcached() + with patch('time.time',) as mock_time: + mock_time.return_value = 1000.99 + set(mock_cache) + self.assertEqual(mock_cache.called, 'timing') + self.assertEqual(len(mock_cache.args), 2) + self.assertEqual(mock_cache.args[0], 'memcached.set.timing') + self.assertEqual(mock_cache.args[1], 1000.99) + mock_time.return_value = 2000.99 + get(mock_cache) + self.assertEqual(mock_cache.called, 'timing') + self.assertEqual(len(mock_cache.args), 2) + self.assertEqual(mock_cache.args[0], 'memcached.get.timing') + self.assertEqual(mock_cache.args[1], 2000.99) + class UnsafeXrange(object): """