caches: updated logging and some timings

vcsserver/lib/rc_cache/backends.py

@@ -265,7 +265,6 b' class BaseRedisBackend(redis_backend.Red'
     def get_mutex(self, key):
         if self.distributed_lock:
             lock_key = redis_backend.u('_lock_{0}').format(key)
-            log.debug('Trying to acquire Redis lock for key %s', lock_key)
             return get_mutex_lock(self.client, lock_key, self._lock_timeout,
                                   auto_renewal=self._lock_auto_renewal)
         else:
@@ -298,12 +297,22 b' def get_mutex_lock(client, lock_key, loc'
                 strict=True,
             )
 
+        def __repr__(self):
+            return "{}:{}".format(self.__class__.__name__, lock_key)
+
+        def __str__(self):
+            return "{}:{}".format(self.__class__.__name__, lock_key)
+
         def __init__(self):
             self.lock = self.get_lock()
+            self.lock_key = lock_key
 
         def acquire(self, wait=True):
+            log.debug('Trying to acquire Redis lock for key %s', self.lock_key)
             try:
-                return self.lock.acquire(wait)
+                acquired = self.lock.acquire(wait)
+                log.debug('Got lock for key %s, %s', self.lock_key, acquired)
+                return acquired
             except redis_lock.AlreadyAcquired:
                 return False
             except redis_lock.AlreadyStarted:

vcsserver/lib/rc_cache/utils.py

@@ -18,6 +18,8 b''
 import os
 import logging
 import functools
+import time
+
 from decorator import decorate
 
 from dogpile.cache import CacheRegion
@@ -52,7 +54,11 b' class RhodeCodeCacheRegion(CacheRegion):'
 
             if not condition:
                 log.debug('Calling un-cached func:%s', user_func.func_name)
-                return user_func(*arg, **kw)
+                start = time.time()
+                result = user_func(*arg, **kw)
+                total = time.time() - start
+                log.debug('un-cached func:%s took %.4fs', user_func.func_name, total)
+                return result
 
             key = key_generator(*arg, **kw)
 
@@ -98,7 +104,6 b' class RhodeCodeCacheRegion(CacheRegion):'
             user_func.original = user_func
 
             # Use `decorate` to preserve the signature of :param:`user_func`.
-
             return decorate(user_func, functools.partial(
                 get_or_create_for_user_func, key_generator))