From f824bc05654756d93c70b6b25951ab5bc47376bb Mon Sep 17 00:00:00 2001
From: Gorka Eguileor <geguileo@redhat.com>
Date: Thu, 26 Jan 2017 16:51:30 +0100
Subject: [PATCH] Add lock acquire/release debug messages

Before we introduced the DLM synchronization mechanism in the Cinder
volume manager we were using Oslo Concurrency synchronized method that
logs, at debug level, all lock acquisition and releases, but now that we
are using our own synchronized decorator we have lost those logs.

Now that we are almost ready to do Active/Active, these log messages
will be even more relevant and important.

This patch adds debug log messages with the exact same message used in
Oslo concurrency for convenience.

TrivialFix

Change-Id: I7e6aa5b28f289ecf067b4d399bd2fb2ffb189a5f
---
 cinder/coordination.py | 33 ++++++++++++++++++++++++++++++---
 1 file changed, 30 insertions(+), 3 deletions(-)

diff --git a/cinder/coordination.py b/cinder/coordination.py
index a6d6f683aa9..b4dc212fd6c 100644
--- a/cinder/coordination.py
+++ b/cinder/coordination.py
@@ -26,6 +26,7 @@ from eventlet import tpool
 import itertools
 from oslo_config import cfg
 from oslo_log import log
+from oslo_utils import timeutils
 import six
 from tooz import coordination
 from tooz import locking
@@ -212,7 +213,12 @@ class Lock(locking.Lock):
     def _prepare_lock(self, lock_name, lock_data):
         if not isinstance(lock_name, six.string_types):
             raise ValueError(_('Not a valid string: %s') % lock_name)
-        return self.coordinator.get_lock(lock_name.format(**lock_data))
+        self._name = lock_name.format(**lock_data)
+        return self.coordinator.get_lock(self._name)
+
+    @property
+    def name(self):
+        return self._name
 
     def acquire(self, blocking=None):
         """Attempts to acquire lock.
@@ -282,6 +288,27 @@ def synchronized(lock_name, blocking=True, coordinator=None):
         call_args = inspect.getcallargs(f, *a, **k)
         call_args['f_name'] = f.__name__
         lock = Lock(lock_name, call_args, coordinator)
-        with lock(blocking):
-            return f(*a, **k)
+        t1 = timeutils.now()
+        t2 = None
+        try:
+            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)})
+                return f(*a, **k)
+        finally:
+            t3 = timeutils.now()
+            if t2 is None:
+                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})
+
     return _synchronized