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

@@ -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