我的執行緒池怎麼沒了？

摘要： 事情的背景是這樣的：我們有一個系統 A，通過 HTTP 請求到系統 B，系統 B 處理這個請求需要很長時間，並且請求頻率也不同，有時候請求多，有時候請求少，所以會先返回給 A “HTTP 200 OK”, 然後再在一個執行緒池中繼續處理這個請求。B 是一個 uWSGI app，執行緒池也是在 ...

事情的背景是這樣的：我們有一個系統 A，通過 HTTP 請求到系統 B，系統 B 處理這個請求需要很長時間，並且請求頻率也不同，有時候請求多，有時候請求少，所以會先返回給 A “HTTP 200 OK”, 然後再在一個執行緒池中繼續處理這個請求。B 是一個 uWSGI app，執行緒池也是在 uWSGI 中開的執行緒池。

我們發現有一些請求處理到一般就沒了，沒有處理完成。但是即沒有返回值，也沒有 Exception 在日誌裡面。有問題的任務日誌大體是這樣子的（日誌的格式是時間、module 名稱、程序 ID、執行緒ID）：

2019-02-26 14:41:33,023 app 19272 139889324566272 start task...
2019-02-26 14:41:33,025 app 19272 139889324566272 task log...
2019-02-26 14:42:30,815 app 18134 139889324566272 start task...

這個問題蛋疼的地方在於，沒有 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 的引數，其中有一個是：

uWSGI 在一個 process 處理的請求書達到了 max-reqeusts 就會 respawn 這個 process。

我在本地嘗試了一個，開一個 uWSGI 設定 –max-requests=10，發現確實請求數在 10 左右（不是精確的10，比如說下面的日誌就是 14）的時候，這個程序會被 respawn，日誌如下：

[pid: 65656|app: 0|req: 11/11] 127.0.0.1 () {28 vars in 292 bytes} [Thu Feb 28 13:42:17 2019] GET / => generated 26 bytes in 1 msecs (HTTP/1.1 200) 4 headers in 114 bytes (2 switches on core 0)
[pid: 65656|app: 0|req: 12/12] 127.0.0.1 () {28 vars in 292 bytes} [Thu Feb 28 13:42:18 2019] GET / => generated 26 bytes in 1 msecs (HTTP/1.1 200) 4 headers in 114 bytes (1 switches on core 0)
[pid: 65656|app: 0|req: 13/13] 127.0.0.1 () {28 vars in 292 bytes} [Thu Feb 28 13:42:19 2019] GET / => generated 26 bytes in 1 msecs (HTTP/1.1 200) 4 headers in 114 bytes (2 switches on core 0)
[pid: 65656|app: 0|req: 14/14] 127.0.0.1 () {28 vars in 292 bytes} [Thu Feb 28 13:42:20 2019] GET / => generated 26 bytes in 1 msecs (HTTP/1.1 200) 4 headers in 114 bytes (2 switches on core 0)
...The work of process 65656 is done. Seeya!
worker 1 killed successfully (pid: 65656)
Respawned uWSGI worker 1 (new pid: 65840)
[DEBUG]2019-02-28 13:42:25,693  font_manager1465 Using fontManager instance from /Users/laixintao/.matplotlib/fontList.json
[pid: 65840|app: 0|req: 15/15] 127.0.0.1 () {28 vars in 292 bytes} [Thu Feb 28 13:42:25 2019] GET / => generated 26 bytes in 299 msecs (HTTP/1.1 200) 4 headers in 114 bytes (1 switches on core 0)

這個時候也確實留下了沒有處理完的任務。

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 anddangerous 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 一樣，我誤以為是執行緒一直存在，只不過執行緒自己出了問題。

但是這個 BUG 的根本原因，我歸咎於我沒有仔細看 uWSGI 的文件。文件和外面的 example 幾乎都帶上了 max-requests 這個引數，於是我也在自己的配置檔案裡面寫上了。但是我誤以為它的意思是：uWSGI 等待佇列的最大長度，而不是處理過這麼多 requests 就重啟。

mrluanma 說：

抄東西過來不看是很不好的習慣。我是會把每個選項是否需要都想清楚的。

uWSGI 文件中的The Art of Graceful Reloading  說：

記住了。