在多线程应用程序中记录锁获取和释放调用

Question

我正在尝试调试使用各种锁的多线程Python应用程序.

而不是在整个镜头中放置log.debug(...)语句来跟踪获取和释放锁的位置和时间,我的想法是装饰方法threading.Lock.acquire()和threading.Lock.release(),并使用以下内容为其调用添加前缀:

log.debug("lock::acquire() [%s.%s.%s]" %
          (currentThread().getName(),
           self.__class__.__name__,
           sys._getframe().f_code.co_name))

其中log是一些全局日志记录对象 - 为了讨论.

理想情况下,日志条目中的名称"lock"应该在运行时派生,这样无论在日志上调用这些方法的哪个锁定对象都将输出其名称,操作装饰,当前线程,类和函数,其中调用操作(获取|释放).

免责声明:我承认上面给出的代码对于任何这样的装饰器实现都是不够的.它仅用于提供我认为可以实现的内容.

有没有人知道我是否可以装饰标准库方法,而无需修改线程库的原始源代码,即从我的调用应用程序代码中查找？

也许我正在咆哮错误的树,有一种更好的方法来实现相同的目的,而不使用装饰器？如果情况确实如此,请提前感谢任何指导.

解决方案:(灵感来自lazyr)

以下代码记录了锁定操作,并给出了调用锁定操作的方法/函数的名称(我还调整了代码以使用条件及其附加的wait()和notify()方法):

# Class to wrap Lock and simplify logging of lock usage
class LogLock(object):
    """
    Wraps a standard Lock, so that attempts to use the
    lock according to its API are logged for debugging purposes

    """
    def __init__(self, name, log):
        self.name = str(name)
        self.log = log
        self.lock = threading.Lock()
        self.log.debug("{0} created {1}".format(
            inspect.stack()[1][3], self.name))

    def acquire(self, blocking=True):
        self.log.debug("{0} trying to acquire {1}".format(
            inspect.stack()[1][3], self.name))
        ret = self.lock.acquire(blocking)
        if ret == True:
            self.log.debug("{0} acquired {1}".format(
                inspect.stack()[1][3], self.name))
        else:
            self.log.debug("{0} non-blocking acquire of {1} lock failed".format(
                inspect.stack()[1][3], self.name))
        return ret

    def release(self):
        self.log.debug("{0} releasing {1}".format(inspect.stack()[1][3], self.name))
        self.lock.release()

    def __enter__(self):
        self.acquire()

    def __exit__(self, exc_type, exc_val, exc_tb):
        self.release()
        return False # Do not swallow exceptions

将日志实例传递给LogLock的位置.使用logging.Formatter定义init,如下给出了调用线程的标识:

# With the following format
log_format = \
        logging.Formatter('%(asctime)s %(levelname)s %(threadName)s %(message)s')

Answer 1

我最近遇到了你的问题.我将记录器设置为自动记录线程名称,就像在这个答案中一样.我发现不可能将Lock子类化,所以我必须将它包装起来,如下所示:

class LogLock(object):
    def __init__(self, name):
        self.name = str(name)
        self.lock = Lock()

    def acquire(self, blocking=True):
        log.debug("{0:x} Trying to acquire {1} lock".format(
            id(self), self.name))
        ret = self.lock.acquire(blocking)
        if ret == True:
            log.debug("{0:x} Acquired {1} lock".format(
                id(self), self.name))
        else:
            log.debug("{0:x} Non-blocking aquire of {1} lock failed".format(
                id(self), self.name))
        return ret

    def release(self):
        log.debug("{0:x} Releasing {1} lock".format(id(self), self.name))
        self.lock.release()

    def __enter__(self):
        self.acquire()

    def __exit__(self, exc_type, exc_val, exc_tb):
        self.release()
        return False    # Do not swallow exceptions

我记录了对象的id,因此我可以区分具有相同名称的多个锁,您可能不需要它.