tornado服务死锁问题排查

python的tornado框架用到了io多路复用和协程的技术。由于tornado是单线程的异步框架，如果运行过程中产生了阻塞，后续的其它任务也就需要等待。在生产过程中，如果tornado进程产生了假死问题该如何排查呢？

问题描述

运营在使用后台的时候，偶尔会反馈后台报错，而且是大部分时候是好的，只是有时会出问题，刷新之后可能不会报错，可能还会报错。

问题排查

1.nginx

我们在后端服务之前加了nginx代理，所以先查看nginx日志，发现upstream到特定的进程时就会报错，如果其它进程处理则不会报错，而且报错的错误是timeout

2.tornado

后端服务底层框架是tornado。使用curl http://127.0.0.1:port 时超时。查看该进程对应的日志，发现有一段时间没有输出日志了。利用ls -l查看日志最后的更新时间，发现停留在1个小时之前。

3.strace

使用strace -p pid命令查看tornado进程当时的系统调用，输出fcntl(0x...,)，并且一直停留在该系统调用。利用fcntl系统调用可以实现文件锁的功能，所以大致可以确定该tornado进程产生了死锁。

4.pyrasite

pyrasite是python进程注入的工具。pip install pyrasite安装之后，pyrasite-shell pid注入到tornado进程，这时进入到python shell的环境

5.sys与traceback

sys._current_frames（）返回一个字典，将每个线程的标识符映射到调用该函数时该线程中当前活动的最顶层堆栈帧。
这对于调试死锁是最有用的：这个函数不需要死锁线程的协作，只要这些线程的调用堆栈保持死锁，它们就会被冻结。对于非死锁线程返回的帧在调用代码检查帧时可能与该线程的当前活动没有关系。
traceback.extract_stack(stack)提取栈代码，以及相关的文件路径和行号等

def stacktraces(exclude=()):
    code = []
    current_frames = [(key, value) for key, value in sys._current_frames().items() if key not in exclude]
    for threadId, stack in current_frames:
        code.append("\n# ThreadID: %s" % threadId)
        for filename, lineno, name, line in traceback.extract_stack(stack):
            code.append('File: "%s", line %d, in %s' % (filename, lineno, name))
            if line:
                code.append("  %s" % (line.strip()))
        print threadId
        print code

可执行stacktraces打印tornado线程栈代码

6.tornado log_stack

对5中打印的日志进行分析，确定是由于项目代码在打印日志的时候，tornado进程接到到了打印block log的信号，由于python的logging日志模块是通过thread lock保证线程安全的，在项目代码acquire了tread lock之后但是还未释放时，block log又尝试去acquire thread lock，该调用是阻塞调用，由此产生了死锁。由此也可知在linux平台python的thread lock是通过fcntl系统调用实现的。

后续

知道了问题产生的根本原因，那么这个问题也就解决了一大半了。上述的问题该如何解决呢？可以留个言探讨一下！

追加

之前用到的pyrasite-shell需要注入到python进程中并且还需要执行代码非常不友好，在后续的工作中发现了另一个工具：pystack-debugger，安装之后使用命令pystack pid即可打印出当时的堆栈信息，类似于java的jstack，对于排查python进程死锁问题有非常好的效果。