From a423d9f9d5672fc92de2c6aae35f0c99140c408d Mon Sep 17 00:00:00 2001 From: Gorka Eguileor Date: Wed, 22 Jun 2022 18:09:06 +0200 Subject: [PATCH] Log when waiting to acquire coordinator 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 is 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: Ida70e9b6098b2e0426cc479811e08a164ed24899 --- cinder/coordination.py | 18 ++++++++---------- 1 file changed, 8 insertions(+), 10 deletions(-) diff --git a/cinder/coordination.py b/cinder/coordination.py index 9db79e80088..600f1e0b161 100644 --- a/cinder/coordination.py +++ b/cinder/coordination.py @@ -32,6 +32,7 @@ from tooz import coordination from cinder import exception from cinder.i18n import _ +from cinder import utils LOG = log.getLogger(__name__) @@ -183,16 +184,16 @@ def synchronized(lock_name: str, call_args = inspect.getcallargs(f, *a, **k) call_args['f_name'] = f.__name__ lock = coordinator.get_lock(lock_name.format(**call_args)) + name = utils.convert_str(lock.name) + f_name = f.__name__ t1 = timeutils.now() t2 = None try: + LOG.debug(f'Acquiring lock "{name}" by "{f_name}"') with lock(blocking): t2 = timeutils.now() - LOG.debug('Lock "%(name)s" acquired by "%(function)s" :: ' - 'waited %(wait_secs)0.3fs', - {'name': lock.name, - 'function': f.__name__, - 'wait_secs': (t2 - t1)}) + LOG.debug(f'Lock "{name}" acquired by "{f_name}" :: ' + f'waited {t2 - t1:0.3f}s') return f(*a, **k) finally: t3 = timeutils.now() @@ -200,10 +201,7 @@ def synchronized(lock_name: str, held_secs = "N/A" else: held_secs = "%0.3fs" % (t3 - t2) - LOG.debug('Lock "%(name)s" released by "%(function)s" :: held ' - '%(held_secs)s', - {'name': lock.name, - 'function': f.__name__, - 'held_secs': held_secs}) + LOG.debug( + f'Lock "{name}" released by "{f_name}" :: held {held_secs}') return _synchronized