PSJay Blog

#FIXME, seriously

Logging,gevent 与死锁

| Comments

前一段时间在工作中遇到了这样一个问题:升级完的一个离线计算任务后,它跑着跑着就会 hang 住,然后服务器的 load 骤降,用 strace 查看系统调用,最后一条指令类似于:FUTEX(0x7ffff79b3e00, FUTEX_WAKE_PRIVATE,...。显然,死锁发生了。

而这次升级,最主要的改动就是将一段比较耗时的 IO 逻辑通过 gevent 和它提供的 Monkey Patch 方法并行化了。代码回滚之后,问题就不存在了。但是奇怪的地方在于,同样的一段并行化的代码,如果是跑在在线请求的环境下,完全不会出现死锁现象,这让我怀疑问题的原因可能并不在于那段代码本身。

于是第二天就和 reAsOn2010 继续调查原因。几经周折后发现,程序在执行最后的 FUTEX 指令之前,一定会执行一条 WRITE 指令,而 WRITE 的内容只是一条简单的日志。

然后,我们发现,程序最终是卡在了 Python 内置 logging 模块的 Handlerhandle 方法中的一行:

1
2
3
4
5
6
7
8
9
def handle(self, record):
    rv = self.filter(record)
    if rv:
        self.acquire() # 卡在了这里!
        try:
            self.emit(record)
        finally:
            self.release()
    return rv

这时,我们才想到,我们的离线任务框架在运行任务之前,会配置 logging 的行为,是不是和这个有关系呢?于是我们把框架中配置 logging 的相关代码注释掉,重启程序,果然,一切正常,没有死锁。

离线任务框架给 root logger 配置了一个 Handler,这个 Handler 会用某种策略将日志通过 socket 发送出去。

这个时候,我们意识到,这段逻辑是在 Monkey Patch 之前运行的!离线任务框架会在做完这些逻辑之后,载入我们编写的 package 并且运行。而 Monkey Patch 的位置,却是在 mypackage/__init__.py 中。

于是我们 hack 了离线任务框架,让 Monkey Patch 在框架的起始位置运行。果然,问题解决,没有死锁。

于是,问题就可以简化成以下模型:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
import sys
import logging
import time

import gevent


class HinderHandler(logging.StreamHandler):

    def emit(self, record):
        r = super(HinderHandler, self).emit(record)
        time.sleep(0.001)  # sleep 1 ms.
        return r


def log_msg(msg):
    logging.info(msg)


def main():
    # Framework configure the root logger
    handler = HinderHandler(stream=sys.stdout)
    logger = logging.getLogger()
    logger.setLevel(logging.INFO)
    logger.addHandler(handler)

    # Framework start to load our application package
    from gevent import monkey; monkey.patch_all()

    jobs = [gevent.spawn(log_msg, i) for i in range(20)]
    gevent.joinall(jobs)


if __name__ == '__main__':
    main()

HinderHandler 模拟了那个向 socket 发送日志的 Handler,在 Monkey Patch 之前,程序就配置了这个 Handler。

毫无疑问,上面这段代码一旦运行,就会死锁。把 Monkey Patch 那一行移到文件的最上部分,问题就能得到解决。

我们来探究一下到底是怎么回事。

Logging Handler 中的这把锁,是这样创建的:

1
2
3
4
5
def createLock(self):
    if thread:
        self.lock = threading.RLock()
    else:
        self.lock = None

也就是说,这是一把 RLock。对于同一个线程来说,RLock 是可以重入的。gevent 并不会为我们创建真正的「线程」,那为什么依然会发生死锁呢?

这里是 RLock 的 acquire 方法的实现:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
def acquire(self, blocking=1):
    me = _get_ident()
    if self.__owner == me:
        self.__count = self.__count + 1
        if __debug__:
            self._note("%s.acquire(%s): recursive success", self, blocking)
        return 1
    rc = self.__block.acquire(blocking)
    if rc:
        self.__owner = me
        self.__count = 1
        if __debug__:
            self._note("%s.acquire(%s): initial success", self, blocking)
    else:
        if __debug__:
            self._note("%s.acquire(%s): failure", self, blocking)
    return rc

每次 acquire 执行的时候,都会运行 _get_ident 函数得到当前执行单元的 id。在被 patch 之前,它返回线程的 id,但是在被 patch 之后,它会返回 gevent 协程的 id!

于是,悲剧就发生了,一把并未被 patch 的 RLock,每次在 acquire 的时候会调用一个被 patch 的方法(即 _get_indent)来决定行为,于是死锁发生了。

理解了问题发生的原因,解决起来就是分分钟的事情了。

–EOF–

Comments