diff options
author | Gorka Eguileor <geguileo@redhat.com> | 2022-06-22 18:47:53 +0200 |
---|---|---|
committer | Gorka Eguileor <geguileo@redhat.com> | 2022-07-07 20:01:48 +0200 |
commit | 9800d58cb3e7315a1941629c3dd961cfa3b63f25 (patch) | |
tree | 4b0b32e4dc427628d50b3f4fef13c5ccaf44a12e /oslo_concurrency | |
parent | e158ca49bee76c767ac55cf1397e13e54911fdb4 (diff) | |
download | oslo-concurrency-9800d58cb3e7315a1941629c3dd961cfa3b63f25.tar.gz |
Log when waiting to acquire lock
We currently have no log entry when we start trying to acquire a lock.
In general this is ok, but there are cases where it can be problematic,
for example if we have a deadlock situation or if a lock takes a very
long time to be acquired.
In those scenarios looking at the logs we would see the operation
proceed normally and suddenly go completely silent without knowing that
it's waiting for a lock to be freed.
This patch adds a debug log message right before trying to acquire the
lock so we can detect those situations.
Change-Id: I1354dfb98b0927ae167802ecc4ab1d34f6b4d720
Diffstat (limited to 'oslo_concurrency')
-rw-r--r-- | oslo_concurrency/lockutils.py | 8 |
1 files changed, 6 insertions, 2 deletions
diff --git a/oslo_concurrency/lockutils.py b/oslo_concurrency/lockutils.py index c75d3a3..4b085c4 100644 --- a/oslo_concurrency/lockutils.py +++ b/oslo_concurrency/lockutils.py @@ -289,6 +289,8 @@ def lock(name, lock_file_prefix=None, external=False, lock_path=None, else: int_lock = internal_lock(name, semaphores=semaphores, blocking=blocking) + if do_log: + LOG.debug('Acquiring lock "%s"', name) with int_lock: if do_log: LOG.debug('Acquired lock "%(lock)s"', {'lock': name}) @@ -378,7 +380,9 @@ def synchronized(name, lock_file_prefix=None, external=False, lock_path=None, t1 = timeutils.now() t2 = None gotten = True + f_name = reflection.get_callable_name(f) try: + LOG.debug('Acquiring lock "%s" by "%s"', name, f_name) with lock(name, lock_file_prefix, external, lock_path, do_log=False, semaphores=semaphores, delay=delay, fair=fair, blocking=blocking): @@ -386,7 +390,7 @@ def synchronized(name, lock_file_prefix=None, external=False, lock_path=None, LOG.debug('Lock "%(name)s" acquired by "%(function)s" :: ' 'waited %(wait_secs)0.3fs', {'name': name, - 'function': reflection.get_callable_name(f), + 'function': f_name, 'wait_secs': (t2 - t1)}) return f(*args, **kwargs) except AcquireLockFailedException: @@ -401,7 +405,7 @@ def synchronized(name, lock_file_prefix=None, external=False, lock_path=None, ' held %(held_secs)s', {'name': name, 'gotten': 'released' if gotten else 'unacquired', - 'function': reflection.get_callable_name(f), + 'function': f_name, 'held_secs': held_secs}) return inner |