openstack/oslo.concurrency
Code Issues Proposed changes

Cleanup and adding timing to lockutils logging

Browse Source 
* 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
This commit is contained in:
Brian D. Elliott 2014-09-17 14:25:00 +00:00
parent ca01f962c9
commit 103e60e9c0
1 changed files with 17 additions and 4 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

21
oslo/concurrency/lockutils.py
View File

@ -272,14 +272,27 @@ def synchronized(name, lock_file_prefix=None, external=False, lock_path=None):
def wrap(f): def wrap(f):
@functools.wraps(f) @functools.wraps(f)
def inner(*args, **kwargs): def inner(*args, **kwargs):
t1 = time.time()
t2 = None
try: try:
with lock(name, lock_file_prefix, external, lock_path): with lock(name, lock_file_prefix, external, lock_path):
LOG.debug('Got semaphore / lock "%(function)s"', t2 = time.time()
{'function': f.__name__}) 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) return f(*args, **kwargs)
finally: finally:
LOG.debug('Semaphore / lock released "%(function)s"', t3 = time.time()
{'function': f.__name__}) 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 inner
return wrap return wrap