added some warning for long exclusive and semaphore locks

Author: sanderegg

packages/service-library/src/servicelib/redis/_constants.py

@@ -3,6 +3,9 @@
 
 from pydantic import NonNegativeInt
 
+DEFAULT_EXPECTED_LOCK_OVERALL_TIME: Final[datetime.timedelta] = datetime.timedelta(
+    seconds=30
+)
 DEFAULT_LOCK_TTL: Final[datetime.timedelta] = datetime.timedelta(seconds=10)
 DEFAULT_SOCKET_TIMEOUT: Final[datetime.timedelta] = datetime.timedelta(seconds=30)
 

packages/service-library/src/servicelib/redis/_decorators.py

@@ -14,7 +14,7 @@
 
 from ..background_task import periodic
 from ._client import RedisClientSDK
-from ._constants import DEFAULT_LOCK_TTL
+from ._constants import DEFAULT_EXPECTED_LOCK_OVERALL_TIME, DEFAULT_LOCK_TTL
 from ._errors import CouldNotAcquireLockError, LockLostError
 from ._utils import auto_extend_lock
 
@@ -95,6 +95,7 @@ async def _wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
             ):
                 raise CouldNotAcquireLockError(lock=lock)
 
+            lock_acquisition_time = arrow.utcnow()
             try:
                 async with asyncio.TaskGroup() as tg:
                     started_event = asyncio.Event()
@@ -157,6 +158,19 @@ async def _wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
                             "Look for synchronous code that prevents refreshing the lock or asyncio loop overload.",
                         )
                     )
+                finally:
+                    lock_release_time = arrow.utcnow()
+                    locking_time = lock_release_time - lock_acquisition_time
+                    if locking_time > DEFAULT_EXPECTED_LOCK_OVERALL_TIME:
+                        _logger.warning(
+                            "Lock `%s'for %s was held for %s which is longer than the expected (%s). "
+                            "TIP: consider reducing the locking time by optimizing the code inside "
+                            "the critical section or increasing the default locking time",
+                            redis_lock_key,
+                            coro.__name__,
+                            locking_time,
+                            DEFAULT_EXPECTED_LOCK_OVERALL_TIME,
+                        )
 
         return _wrapper
 

packages/service-library/src/servicelib/redis/_semaphore_decorator.py

@@ -7,12 +7,14 @@
 from contextlib import AbstractAsyncContextManager, asynccontextmanager
 from typing import Any, ParamSpec, TypeVar
 
+import arrow
 from common_library.async_tools import cancel_wait_task
 from common_library.logging.logging_errors import create_troubleshooting_log_kwargs
 
 from ..background_task import periodic
 from ._client import RedisClientSDK
 from ._constants import (
+    DEFAULT_EXPECTED_LOCK_OVERALL_TIME,
     DEFAULT_SEMAPHORE_TTL,
     DEFAULT_SOCKET_TIMEOUT,
 )
@@ -42,6 +44,7 @@ async def _managed_semaphore_execution(
     if not await semaphore.acquire():
         raise SemaphoreAcquisitionError(name=semaphore_key, capacity=semaphore.capacity)
 
+    lock_acquisition_time = arrow.utcnow()
     try:
         # NOTE: Use TaskGroup for proper exception propagation, this ensures that in case of error the context manager will be properly exited
         # and the semaphore released.
@@ -100,6 +103,18 @@ async def _periodic_renewer() -> None:
                     "Look for synchronous code that prevents refreshing the semaphore or asyncio loop overload.",
                 )
             )
+        finally:
+            lock_release_time = arrow.utcnow()
+            locking_time = lock_release_time - lock_acquisition_time
+            if locking_time > DEFAULT_EXPECTED_LOCK_OVERALL_TIME:
+                _logger.warning(
+                    "Semaphore '%s' was held for %s which is longer than expected (%s). "
+                    "TIP: consider reducing the locking time by optimizing the code inside "
+                    "the critical section or increasing the default locking time",
+                    semaphore_key,
+                    locking_time,
+                    DEFAULT_EXPECTED_LOCK_OVERALL_TIME,
+                )
 
 
 def _create_semaphore(