From 103e60e9c0871d727d544e0719bc37b3cf0231b7 Mon Sep 17 00:00:00 2001
From: "Brian D. Elliott" <bdelliott@gmail.com>
Date: Wed, 17 Sep 2014 14:25:00 +0000
Subject: [PATCH] Cleanup and adding timing to lockutils logging

* Cleanup lockutils logging by showing lock name and function in
same line.  The enables easier parsing of information related to lock
acquisition from logs.

* Logs time a thread spent waiting on locks, as well as time spent
holding locks.  This will make it easier to debug suboptimal locking.

Change-Id: Ic310d84eb1ed75cc1c21c3d7861b4a3927ebaf23
---
 oslo/concurrency/lockutils.py | 21 +++++++++++++++++----
 1 file changed, 17 insertions(+), 4 deletions(-)

diff --git a/oslo/concurrency/lockutils.py b/oslo/concurrency/lockutils.py
index 5ac28a7..f82ee26 100644
--- a/oslo/concurrency/lockutils.py
+++ b/oslo/concurrency/lockutils.py
@@ -272,14 +272,27 @@ def synchronized(name, lock_file_prefix=None, external=False, lock_path=None):
     def wrap(f):
         @functools.wraps(f)
         def inner(*args, **kwargs):
+            t1 = time.time()
+            t2 = None
             try:
                 with lock(name, lock_file_prefix, external, lock_path):
-                    LOG.debug('Got semaphore / lock "%(function)s"',
-                              {'function': f.__name__})
+                    t2 = time.time()
+                    LOG.debug('Lock "%(name)s" acquired by "%(function)s" :: '
+                              'waited %(wait_secs)0.3fs',
+                              {'name': name, 'function': f.__name__,
+                               'wait_secs': (t2 - t1)})
                     return f(*args, **kwargs)
             finally:
-                LOG.debug('Semaphore / lock released "%(function)s"',
-                          {'function': f.__name__})
+                t3 = time.time()
+                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': name, 'function': f.__name__,
+                           'held_secs': held_secs})
         return inner
     return wrap