# HG changeset patch
# User RhodeCode Admin <admin@rhodecode.com>
# Date 2021-10-12 11:40:31
# Node ID 3c68f6b7e4b9fb5f62813d99ca7a3d13f8f2965d
# Parent  482b68901e94d44206a75aac1824bf3438c9a79f

caches: added debug and timings

diff --git a/rhodecode/lib/rc_cache/backends.py b/rhodecode/lib/rc_cache/backends.py
--- a/rhodecode/lib/rc_cache/backends.py
+++ b/rhodecode/lib/rc_cache/backends.py
@@ -300,7 +300,6 @@ 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:
@@ -333,12 +332,22 @@ 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:
diff --git a/rhodecode/lib/rc_cache/utils.py b/rhodecode/lib/rc_cache/utils.py
--- a/rhodecode/lib/rc_cache/utils.py
+++ b/rhodecode/lib/rc_cache/utils.py
@@ -122,7 +122,11 @@ 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)