概述

今日頭條目前大部分 Python 的 HTTP 服務都是用 uWSGI 託管 Python 多進程的 Django 或者 Flask 框架的 App。而多進程模型就會有進程間通信的問題，對此 uWSGI 提供了 spooler 功能用於讓不同 worker 進程把數據通過共享內存傳給單獨進程以集中進行處理的功能。但是 uWSGI 的 Python C 擴展實現有 bug，對 Python tuple 對象的引用計數處理是錯誤的，會在多線程環境下有小概率導致進程崩潰，從而造成線上 HTTP 請求返回 502 錯誤。

經過幾天的分析排查和復現，最終修復了導致對象引用計數出錯的代碼。整個過程涉及到 uWSGI 和 Python 虛擬機中內置類型的實現、對象引用計數和對象池、GC、多線程 GIL、內存管理及 GDB 使用等。本文記錄了主要的排查過程，並在涉及到虛擬機實現的地方介紹對應的細節。

uWSGI和Python併發模型

首先簡單介紹一下 Python 與其它語言在併發處理上的不同。熟悉 Python 的同學知道，Python 2.x 的官方實現版本是有一個 GIL 的，即全局解釋鎖。在 Python 代碼執行的大部分時間裡，線程都會持有這個鎖，這樣不能簡單通過開多線程的方式充分利用多核的優勢。有人嘗試把 GIL 改成更細粒度的鎖，但是發現在單線程場景下運行效率有明顯下降。

為了解決 Python 併發的問題，有人實現了其它方案，比如 gevent，tornado 等，不過用起來多少都有些彆扭，或者容易掉坑裡。

所以對於 Python 2 建議的用法是多進程模型。小計算量的 IO 操作可以開在另外一個線程裡邊。

而多進程模型就需要在進程管理上做一些處理。整體上來說 uWSGI 是一個宿主，用來承載其它服務。uWSGI 會先啟動一個 master 進程，然後再啟動各個 worker 進程和單獨的 spooler 進程，並監控這些進程的運行狀態。不過通常我們主要用 uWSGI 作為 Web Server，管理 Python 寫的 Web Application。而不會使用 uWSGI 的 LB 之類的功能。

而由 uWSGI 管理多進程，同時進程內有不止一個線程的情況下，由於 C 擴展部分的實現有 bug，會導致 uWSGI 進程有小概率在請求處理過程中崩潰。

初步查看

少量uWSGI日誌

線上報 502 之後，先查看 uWSGI 日誌，發現會有少量 worker 崩潰的情況。平時業務出現問題，一般是 Python 層面邏輯不對，比如出現 Exception，請求超時之類的，比較少有進程直接掛掉的情況。而且我印象裡 RPC Server 不太會有這種崩潰的情況，以前簡單看過一眼 uWSGI 的 C 擴展部分，不過沒有看細節，當時就覺得這些對對象引用計數的處理部分挺容易出錯的，其它邏輯倒還好。所以我的第一直覺是 C 擴展部分寫的有問題，而且很可能是 Python 對象引用計數錯誤導致的。

而具體到 log 能直接看到的內容並不多，大概是這樣幾行：

這裡除了能知道是 master 進程發現 worker 進程掛了，然後又拉起來一個，其它重要信息就是 signal 11 和 signal 6 了。

一般來說出現 Segmentation Fault（signal 11）這種情況是比較麻煩的，出事的地方往往不是第一現場，有可能是另外的代碼已經把內存狀態跑錯了。

而 Abort（signal 6）就好一點了，可能是程序主動為之。而且 GC object already tracked 這條信息非常關鍵，應該是 Python 虛擬機發現狀態異常主動拋出來的。

於是翻出 Python 源碼：

從這個宏中可以看出來，是在向 Python 虛擬機申請一個對象的時候，發現其引用計數不是 PyGCREFS_UNTRACKED。

直覺

GC_TRACK 這個宏是把對象加入 GC 鏈裡邊，是申請對象的時候的操作。看起來似乎不是減少引用計數釋放內存的時候出現的問題啊。

其實也不一定，因為既然需要在使用前對對象進行 check，那大概說明這個對象的類在內部實現是有對象池的（之前只看了 int 對象池細節，但是知道很多內置類型有對象池），而對象在被放回對象池的時候有問題，當時沒有發現，而再拿出來用的時候出錯了也合理。

而收到 signal 11 時內存越界錯誤不一定跟這個有關，可能是另外的問題，也可能是相同的原因。反正內存被亂寫，誰知道會發生啥呢。這個方向不好直接查。

找到一個有問題的點

可以說幹猜大概只能猜到這裡了。下面得用工具具體調試一下出現問題的現場了。

從線上看，單臺機器上 10 分鐘左右會出現一次崩潰，於是在一臺機器上打開 core dump 文件配置（ulimit 和/proc/sys/kernel/core_pattern），重新編譯 Python，加上–with-pydebug 選項，放到線上去跑。

而用這個版本在線上跑的時候，出現了另外一種情況：每次出錯的接口請求打進來，worker 就掛了。

之前是偶爾掛掉，現在是每次請求都崩潰，難道是編譯的有問題？

不過仔細看另外獲得的 has negative ref count 日誌發現，錯誤出現同在一個地方。

這個代碼的意思是，虛擬機在對一個對象減少引用計數的時候，如果正好減到了 0，那麼就該回收這個對象了。而在打開 PyREFDEBUG 的情況下，會檢查是不是已經把引用計數減成負的了，減成負數說明虛擬機內部狀態不正常。這個選項是在打開–with-pydebug 才有的。

也就是說調用到這裡的代碼有問題。到底是不是引起崩潰的主要原因不好確定。

從 gdb 查看崩潰時候的調用棧，可以找到對應的 C 代碼如下：

這裡把整個函數全放上來，是因為這段代碼非常關鍵。

先簡單解釋一下這裡在處理什麼邏輯：

這個函數是 uWSGI 的 C 擴展，綁定到 Python 層的 uwsgi.spool 函數，現在我們在 uWSGI 裡面用 spooler 功能的時候，是在 Python 邏輯處理函數上面套一層 decorator，本進程做的事情是把參數還有函數名等封裝成一個 dict 整體扔到共享內存裡邊，然後由 uWSGI 另外啟的 spooler 進程拿到數據，再調用被修飾的函數體。

回頭看上面的 C 擴展的大概流程

1. 先做一些檢查，比如 spool_dict 這個是不是從 Python 層面以 dict 形式傳進來的，dict 中有沒有超長的 value 以”body”為 key 傳進來

2. 把 dict 轉換成 list，每個元素是原始 dict 的 (key, value) 組成的 tuple。類似於調用了一次 dict.items() 函數

3. 把這個 list 掃描一遍，確保 tuple 的兩個元素 key value 都是 str 類型，並且把內容塞到 buffer 裡邊

4. 釋放 GIL

5. 把 buffer 裡的內容和可能傳進來的 body 塞到共享內存並且釋放 buffer

6. 重新獲取 GIL

7. 對剛才轉換出來的 list 釋放一次引用 PyDECREF(spoolvars);

其中在第 3 步掃描每個 tuple 的過程中（pyuwsgisend_spool 2018 行），錯誤的多減少了一次引用計數：

因為在 1969 行這一步的時候，並沒有給 zero 增加引用計數。

到這裡可以簡單提一下 Python 中對象管理的方式了。跟大部分 GC 實現不一樣，Python 主要用了引用計數的方式來自動回收內存，即在把一個對象賦值給一個變量、被另外一個容器引用、作為參數傳遞等的時候引用計數加 1，離開作用域（即不再被變量指向）、不被容器引用等時候減少引用計數。用 Mark And Sweep 解決循環引用的問題，同時用了分代等優化手段。這樣實現的 GC 代碼在實際運行起來比通常的方式會慢一點，不過對象大部分時間會第一時間被釋放（當然可能只是釋放後回到對象池）。

回到對 tuple 引用計數部分，在上面這個函數最後執行 PyDECREF(spoolvars) 的時候，其實是對其所有的引用對象又釋放了一遍的。

但是平時為什麼不會每次調用都出現崩潰的問題呢。這裡涉及到了 Python 多線程的問題。前面提到 Python 為了保證單線程場景下執行效率還有 C 擴展編寫容易，一直保持了 GIL 即全局解釋鎖的實現，Python 大部分線程代碼在執行的時候，都是持有這個鎖的，也就是通常一個進程內只有一個線程在執行。有幾種情況會釋放掉這個鎖，比如顯式釋放、IO 調用，連續執行 byte code 到達一定數量（默認 100 條）。

由於有 GIL 鎖的限制，上面這段代碼只在非常短的時間窗口內會跟其它線程出現交替執行的情況。就是上面提到的第 5 步。而另外一個線程是 10s 才去請求一次 Consul 獲取下游服務地址列表的，其它時間在 sleep。所以線上不會太頻繁的出錯。

平時大部分時間執行都挺好的，而在打開 REF 檢查的時候才出錯，大概可以猜測如果這裡沒有這個小的時候窗口讓線程切換，就算多減了一次引用計數也不會有問題。具體可以參考最上面的宏實現，Python 代碼在把一個對象引用計數減到 0 的時候會主動對其釋放，再減成負的也不會額外作處理。

直覺

雖然之前沒有直接看過 tuple 對象池的代碼，但是看過 int 對象池的實現，對於 Python 的對象管理和內存管理有一定理解，加上看到有 GIL 釋放的處理，還有

這條非常關鍵的 log 提示，我又大膽進行了一次猜測，出現 core dump 的地方很可能是這樣一個順序

1. spooler 執行到的地方即 uWSGI worker 線程在循環執行的過程中把 tuple 放回了對象池

2. 釋放 GIL

3. 另外一個線程需要使用 tuple，於是從對象池中拿出了這個對象

4. 使用 spooler 的線程又把這個 tuple 的引用計數減了 1，又放回了對象池

5. 另外那個線程繼續用這個 tuple，增加了其引用計數

6. 另外那個線程本身或者再切到第三個線程，需要用 tuple 對象，嘗試從對象池裡面取

7. 檢查到 PyGCHeadREFS(g) != PyGCREFS_UNTRACKED 條件不滿足，崩潰

其實如果沒有 uWSGI log 裡面那條額外的提示，我猜測的最後幾步順序可能不是這樣，而是稍微簡單一點，比如第 4 步把對象放回對象池之後，接著 GC 把對象池清空了，然後第 5 步繼續使用這個 tuple 就已經足夠讓程序崩潰了。當然這樣收到的信號最可能是 signal 11。

GDB 展示調用棧

有了一個大概的猜想，下面就是拿工具和代碼來驗證實際是不是這樣一個場景了。

從某 core 文件裡面可以看到這樣一個棧信息

從調用棧大概可以看出，出現問題的地方是一個 Python 虛擬機在解釋 byte code 的過程當中，一個 callable object（大概可能是實現了 call 的對象）被調用，想要使用一個 tuple，然後調用了 PyTupleNew，但是遇到了上面提到過的 PyObjectGCTRACK 這個宏不滿足條件，主動調用了 abort()。

不過由於上面只是猜想，而且過程需要繞幾個彎才能真正在線上出現問題，概率很低，還需要一些手段來驗證當時的場景是不是這樣。

uWSGI C 擴展修復

既然已經找到了一個 bug，而且看起來進程崩潰跟這個很可能有關，那就先改一下好了。

整體上改動並不是很多。既然代碼中錯誤的多減少了 zero 的引用計數，那把相應的幾行去掉就好了。這樣就不會在主動釋放 spool_vars 的時候再減一次了 。

不過需要注意的一點是後面有個 error 的 label，在這個後面需要再對 spool_vars 處理一下，防止內存洩漏。

把修改過的二進制版本放到一臺機器上去測試，一整天都沒有出現 core dump。難道 bug 就這樣修復了？會不會還有其它隱藏的 bug 呢。程序內部到底是什麼樣一個過程導致線上崩潰呢。畢竟上面出現崩潰的過程只是一個猜想，實際上並不一定完全是這樣。

復現

現在就需要在線下穩定復現這個問題了。實際上覆現的過程比找到問題還要麻煩一些。

搭建線下環境

於是我用業務 HTTP 代碼改了一下，只留一個接口，並且在接口內部處理的時候儘量精簡，大概只是調用了 spooler 一次，然後隨便折騰用了幾個 tuple，看看隨意的多樣的使用這些 tuple 對象會不會把崩潰的概率提高一些。

由於之前分析過，這個 bug 跟 Python 多線程有關，所以要想復現這個問題，要儘量把多線程相關的操作貼近線上環境，否則折騰半天覆現不出來，都不好說哪裡的問題。

業務方自己並沒有使用多線程，唯一用到的地方就是框架中另啟了一個線程去輪詢 consul 以獲取下游的地址列表。所以我把這個 API 的下游全 dump 出來，在接口的入口處先主動調用了一下對應函數，把列表加到緩存裡邊讓線程開始輪詢。這裡沒有直接放在初始化的地方，是想讓進程啟動的時候儘量少做事情，讓虛擬機內部狀態簡單可控一些。

嘗試主動清空對象池

在嘗試復現這個問題的過程中，我也走了一些彎路。

我在想既然是主 worker 線程把對象放回對象池後其它線程會出現問題，那如果在剛剛把對象放回對象池之後，就把對象池清空，是不是至少不會出現在 GC untrack 的時候出錯進而調用 abort() 呢（當然既然真的多減引用計數了，所以內存使用錯誤 signal 11 還是有可能收到的）。

於是我在 C 代碼中加入了對 PyTuple_ClearFreeList 的調用，把這個函數綁定到 Python 層面進行調用，在 worker 線程 Python 代碼中主動調用 gc.collect()。幾種組合操作，都沒有明顯效果，還是兩種 signal 帶來的崩潰都有。

之後分析，才發現這樣嘗試是有問題的。這個涉及到了 Python 中對於內置類型的對象管理和內存管理這兩層之間的關係。實際上對 tuple 對象的錯誤操作滲透到了底層內存第一層對象池 block 去了，即清理了 tuple 的對象池放回 block，然後需要生成 tuple 對象的時候由於 tuple 對象池己空所以又從 block 中拿出來一塊內存用作 tuple 對象。而此時虛擬機對這塊地址的錯誤引用問題依然存在，還是會非法修改其引用計數。實際上清理對象池之後，崩潰的時機不止在於對 tuple 的使用，因為也可能有其它類型需要從 block 池中拿相同大小的一塊內存。不過這種情況概率並不高，測試的時候沒有太注意。

打印被 spooler 使用的 tuple 對象 id

吃飯的時候想到一點，其實我首先可以簡單的把對象 id 打印出來，看看在 uWSGI 裡面被汙染的 tuple 是否包含了跟出現 core dump 的時候最後用到的 tuple 對象。萬一哪次不用，其實也就說明之前的猜想是有問題的。

於是我把 pyuwsgisend_spool 函數用到的所有 tuple 的內存地址都打了出來，再用 gdb 打開 core 文件，跟棧頂（不是最頂）最後一次用到的 tuple 的地址對比。

手動出現的四個 core 文件中，三個都是 pyuwsgisend_spool 函數最後放回對象池的對象跟棧頂對象一致，另外一個不是，不過也出現過。感覺安心了一點。

增加被 spooler 函數錯誤使用的 tuple 對象數量

突然想到，打印出來的對象 id 都是三個一組，每次 request 進來被汙染的對象其實並不多。這時才想起來上面提到的那個 decorator。仔細一看，原來每次扔進 C 函數的 dict 都是確定的三個 key，一個 fucntion name，另外兩個是 args 和 kwargs 被 pickle 之後的 str。

於是，我非常暴力的加了個循環：在 dict 裡面另外加了 50 個 key value（當然最後精準復現問題的時候是不需要這樣額外加的）。

於是，測試進程頻繁出 core。復現過程終於有一些進展了。

另寫線程折騰 tuple 大致復現問題

上面復現的過程是在線下把對接口請求的響應做到儘量精簡，並且增加被 spooler 用錯的 tuple 對象數來方便復現問題。但是另外一個線程跑的還是框架裡面的輪詢 consul 的代碼，有不少代碼邏輯並且有網絡調用，這樣中間過程哪些是對復現問題有用的，哪些沒有用並不清楚。

我先在 spooler 的 C 代碼中釋放 GIL 之後加了一行 sleep(2)，讓另外一個線程比較方便的執行一些操作。而在另外這個線程中把之前請求 consul 的代碼去掉，只留線程的殼子，改成一段簡單的 Python 代碼，大概按照順序做這樣幾件事情：

1. sleep 一下，等待手工打入一條請求，觸發寫 spooler 操作

2. 生成五六個 tuple

3. sleep 2s 切回 spooler 進程

4. 用兩個對象引用這五六個 tuple

5. 再生成幾個 tuple

這樣請求打進來幾次，程序就崩潰了。比之間復現頻率高了非常多。

但是，之前的猜想是在第 5 步再從對象池申請使用 tuple 的時候就該崩潰了啊，為啥程序還在繼續跑，而處理過幾次請求之後才崩潰呢？

精準復現

這個問題實在猜不出來為啥了，這時候回頭想上面那行關鍵的提示：

GC object already tracked

然後回頭去看代碼，才發現原來自己以前對 Python 對象在內存中的佈局理解一直有點偏差，那就是記錄一個對象是不是 Tracked 的狀態的標記是放在對象所在內存的前面，而 refcnt 是在對象的頭部，即所有 Python 對象都有的 PyObject 頭。

對象放回對象池的時候，是 Tracked 標記的位置改成 UNTRACKED，這時候如果 GC 開始，那就會被回收掉（我之前還嘗試手動 GC 來回收的，不過忘了標記位在這裡）。而我把對象從對象池拿出來，然後切換線程去減掉其引用計數，再在 Python 代碼裡面增加引用計數等操作，對引起崩潰都不是最直接的做法。

直接跟 GC object already tracked 相關的問題在於一個對象從對象池裡被拿出來被標記為 Tracked 之後，又被拿出來一次才會被檢查到不正常。也就是說，我需要把一個 tuple 對象在兩個線程裡邊交叉兩次獲取卻三次放回對象池，然後連續嘗試兩次拿出來才會出現 uWSGI log 裡面的錯誤提示。

最後寫出這樣一段代碼：

終於，每次手動打進來一個請求，worker 就會崩潰。

這段看似挺正常而沒什麼作用的 Python 代碼，其實每一行的操作和前後順序都非常重要。尤其 11 和 13 兩行代碼就是在 spooler 線程已經把 t 放回對象池之後，又把其引用計數加一再減一，又一次放回對象池。那麼在最後連續申請 tuple 對象的時候就出錯了。

兩個線程的交替時序可以用下圖展示：

問題復現到這裡，想出現另外一種 Segmentation Fault 的崩潰現象也是比較簡單的。不讓程序連接申請 tuple 對象立即出上面的錯誤，再跑一會兒就掛了。讓多減一次引用計數這個操作影響到 tuple 相關內存以外的代碼就行。

總結

整體上來說問題出現的原因在於 uWSGI 的 C 擴展存在 bug 導致 Python 虛擬機中 tuple 對象被不正常的重複放回對象池而引起其引用計數錯誤。其中大部分崩潰的情況是程序試圖把對象從 tuple 對象池中重新拿出來使用的時候虛擬機檢查到 GC 狀態不正常，主動調用了 abort()，小部分情況是被放回 tuple 對象池的內存回到內存池後被其它代碼使用過程中被異常修改內容，導致程序在執行過程中不確定的位置邏輯異常，最終導致內存越界。

而復現的時候需要控制兩個線程的執行順序，線程交叉兩次獲取 tuple 對象卻三次放回對象池，然後再連續嘗試兩次拿出來使用，才可以穩定讓程序崩潰。

整體上查找修復並復現這個問題，除了基本工具的使用，對各種細節的理解，另外還需要一些猜想和嘗試。這種沒有固定 Pattern 可尋只能從有限的信息中找到線索，猜想出錯原因再去構建一種複雜執行順序驗證的過程還是比較鍛鍊思維的。

閱讀更多 今日頭條技術團隊 的文章

關鍵字: 錯誤 Python 多線程