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 | |
| 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
| -rw-r--r-- | oslo_concurrency/lockutils.py | 8 | ||||
| -rw-r--r-- | releasenotes/notes/log_acquiring_lock-1b224c0b1562ec97.yaml | 5 |
2 files changed, 11 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 diff --git a/releasenotes/notes/log_acquiring_lock-1b224c0b1562ec97.yaml b/releasenotes/notes/log_acquiring_lock-1b224c0b1562ec97.yaml new file mode 100644 index 0000000..12fd7e6 --- /dev/null +++ b/releasenotes/notes/log_acquiring_lock-1b224c0b1562ec97.yaml @@ -0,0 +1,5 @@ +--- +features: + - | + Log before trying to acquire a lock to help detect deadlocks and long waits + to acquire locks. |