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

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是一个全局的logging对象——为了讨论方便。

理想情况下，日志中的"lock"名称应该在运行时生成，这样无论这些方法是在哪个锁对象上调用，日志都会输出锁的名称、操作类型、当前线程、类和调用这个操作的函数（获取 | 释放）。

免责声明：我承认上面的代码并不足以实现任何装饰器的功能。它只是为了给大家一个我认为可以实现的效果的感觉。

有没有人知道我是否可以在不修改threading库的原始源代码的情况下装饰标准库的方法，也就是说，可以在我的调用应用程序代码中实现？

也许我在错误的方向上探索，还有没有更好的方法来实现同样的目的，而不使用装饰器？如果真是这样，非常感谢任何指导。

解决方案：（受到lazyr的启发）

以下代码记录了锁操作，并给我提供了调用锁操作的方法/函数的名称（我还在调整代码以便与Conditions及其额外的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.init的日志实例是用logging.Formatter定义的，如下所示，以便给我调用线程的身份：

# 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，这样我就能区分多个名字相同的锁，你可能不需要这样做。