我的线程池怎么没了？

事情的背景是这样的：我们有一个系统 A，通过 HTTP 请求到系统 B，系统 B 处理这个请求需要很长时间，并且请求频率也不同，有时候请求多，有时候请求少，所以会先返回给 A “HTTP 200 OK”, 然后再在一个线程池中继续处理这个请求。B 是一个 uWSGI app，线程池也是在 uWSGI 中开的线程池。

我们发现有一些请求处理到一般就没了，没有处理完成。但是即没有返回值，也没有 Exception 在日志里面。有问题的任务日志大体是这样子的（日志的格式是时间、module 名称、进程 ID、线程ID）：

这个问题蛋疼的地方在于，没有 Exception 日志，线程就这么罢工了，转而去处理下一个任务了。而且出现的频率大约是 5 分钟一次，我们有一个 staging 环境，一天大约四五次。俗话说如果一个 BUG 能重现，那么就约等于解决了。而这个问题，是我想了好几天都不知道该怎么复现的。出现的时候转瞬即逝，没有留下一丝痕迹……

我们先后尝试了加上更多的 log（但是没有什么用，task 停止的地方很随意，几乎没有什么规律），试图找出这些有问题的 task 的规律（也没有什么规律）。之前听一哥们讲过用 settrace 打印出来所有的调用和执行日志，我写好了 settrace 的代码，打算要用这个东西了，但是试了一下打出来这个日志是在是太慢了，3s 处理完成的任务，开了 settrace 要 40s 才能完成。所以就暂时没有尝试这个方法，打算实在没什么办法了再考虑开这个日志。

今天看 log 的时候，发现线程 ID 虽然一样，但是进程 ID 已经变了。这个进程是 uWSGI 的进程，于是我怀疑是 uWSGI 销毁了这个进程，并且一并销毁了进程里面的线程池。我的理由是：因为 uWSGI 是一个 HTTP 服务器，它只关心我的所有的 HTTP 请求是否处理完了。我们的模型是先返回 HTTP Response，然后再在线程池处理。对于 uWSGI 来说，它看到已经返回 Response 了，就认为这个请求已经处理完了，我就可以关闭这个进程了。

那么 uWSGI 什么情况下会销毁并重启进程呢？我去翻了文档，发现有几个让 uWSGI respawn 的参数，其中有一个是：

max-requests
argument: required_argument

shortcut: -R

parser: uwsgi_opt_set_64bit

help: reload workers after the specified amount of managed requests

uWSGI 在一个 process 处理的请求书达到了 max-reqeusts 就会 respawn 这个 process。

我在本地尝试了一个，开一个 uWSGI 设置 –max-requests=10，发现确实请求数在 10 左右（不是精确的10，比如说下面的日志就是 14）的时候，这个进程会被 respawn，日志如下：

这个时候也确实留下了没有处理完的任务。

OK，这个问题找到了，那么之前的现象也都解释通了，线程不是自己退出的，是父进程被杀掉了，所以没有留下 traceback。

解决的办法

虽然文档和 uWSGI 代码中将 max-reqeusts 作为了一个 required arg，但是从代码的实现上看，如果设置为 0 的话，这一行 if 是永远不会执行的，也就是说 worker process 就不会被重启。于是我在 uWSGI 的配置文件中将 max-requests 选项给删掉了。临时解决了这个问题。

其实这并不是最好的方案，uWSGI 作为一个 HTTP 服务器，应该只用来处理 HTTP 请求。文档里这样说：

During the life-cycle of your webapp you will reload it hundreds of times.

You need reloading for code updates, you need reloading for changes in the uWSGI configuration, you need reloading to reset the state of your app.

Basically, reloading is one of the most simple, frequent and dangerous operation you do every time.

禁用 max-requests 虽然能保证正常情况下 process 不会被 respawn ，但是在不正常的情况，还是有可能出现的。

像是这种耗时的任务，应该通过中间件发往一个专门的 worker 来处理的，通过任务执行的框架来保证每一个任务都被执行到了。

即使不用消息，也可以用 uWSGI 的 spooler 来处理耗时的任务。

被浪费掉的时间

其实如果我早一点去看一下 uWSGI 的日志，应该是可以发现规律的，每 5000 个请求进程被杀一次，而这也正好是未处理完的任务出现的时间。但是我觉得 uWSGI 日志没有什么有用的信息，有 Nginx + django 日志就够了，所以不久前将 uWSGI 的日志 disable 了。现在看来这部分日志还是有用的，毕竟运行的 Nginx 和 uWSGI，这两个进程的运行状态很重要。至于 Django 的日志，属于业务的日志。

另外从日志可以看到，任务被中断之后，Process ID 已经不一样了，但是 Thread ID 一样，我误以为是线程一直存在，只不过线程自己出了问题。试图在线下重现的时候，我也一直用的 Django 的 runserver 模式，而忽略了服务器上跑的进程其实是 uWSGI 的事实。两个进程都不一样，根本不可能重现。

但是这个 BUG 的根本原因，我归咎于我没有仔细看 uWSGI 的文档。文档和外面的 example 几乎都带上了 max-requests 这个参数，于是我也在自己的配置文件里面写上了。但是我误以为它的意思是：uWSGI 等待队列的最大长度，而不是处理过这么多 requests 就重启。

mrluanma 说：

抄东西过来不看是很不好的习惯。我是会把每个选项是否需要都想清楚的。

uWSGI 文档中的 The Art of Graceful Reloading 说：

Finally: Do not blindly copy & paste!

Please, turn on your brain and try to adapt shown configs to your needs, or invent new ones.

Each app and system is different from the others.

Experiment before making a choice.

记住了。

---