# HG changeset patch
# User RhodeCode Admin <admin@rhodecode.com>
# Date 2021-10-12 11:35:55
# Node ID c609b34efbae19367cc24c3b68bc8fa1244522cf
# Parent  5b697e93fbd4484166200d594a67ba61ec87dcdc

caches: updated logging and some timings

diff --git a/vcsserver/lib/rc_cache/backends.py b/vcsserver/lib/rc_cache/backends.py
--- a/vcsserver/lib/rc_cache/backends.py
+++ b/vcsserver/lib/rc_cache/backends.py
@@ -265,7 +265,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:
@@ -298,12 +297,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/vcsserver/lib/rc_cache/utils.py b/vcsserver/lib/rc_cache/utils.py
--- a/vcsserver/lib/rc_cache/utils.py
+++ b/vcsserver/lib/rc_cache/utils.py
@@ -18,6 +18,8 @@
 import os
 import logging
 import functools
+import time
+
 from decorator import decorate
 
 from dogpile.cache import CacheRegion
@@ -52,7 +54,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)
 
@@ -98,7 +104,6 @@ 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))