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

分享之前我還是要推薦下我自己建的Python開發(fā)學習群：628979297豪诲，群里都是學Python開發(fā)的顶捷，如果你正在學習Python ，小編歡迎你加入屎篱，今天分享的這個案例已經上傳到群文件服赎，大家都是軟件開發(fā)黨，不定期分享干貨（只有Python軟件開發(fā)相關的）交播，包括我自己整理的一份2018最新的Python進階資料和高級開發(fā)教程重虑，歡迎進階中和進想深入Python的小伙伴。

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

uWSGI和Python并發(fā)模型

首先簡單介紹一下 Python 與其它語言在并發(fā)處理上的不同。熟悉 Python 的同學知道嗜价，Python 2.x 的官方實現版本是有一個 GIL 的艇抠，即全局解釋鎖。在 Python 代碼執(zhí)行的大部分時間里炭剪，線程都會持有這個鎖练链，這樣不能簡單通過開多線程的方式充分利用多核的優(yōu)勢翔脱。有人嘗試把 GIL 改成更細粒度的鎖奴拦，但是發(fā)現在單線程場景下運行效率有明顯下降。

為了解決 Python 并發(fā)的問題届吁，有人實現了其它方案错妖，比如 gevent，tornado 等疚沐，不過用起來多少都有些別扭暂氯，或者容易掉坑里。

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

而多進程模型就需要在進程管理上做一些處理。整體上來說 uWSGI 是一個宿主究流，用來承載其它服務辣吃。uWSGI 會先啟動一個 master 進程，然后再啟動各個 worker 進程和單獨的 spooler 進程芬探，并監(jiān)控這些進程的運行狀態(tài)神得。不過通常我們主要用 uWSGI 作為 Web Server，管理 Python 寫的 Web Application偷仿。而不會使用 uWSGI 的 LB 之類的功能哩簿。

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

初步查看

少量uWSGI日志

線上報 502 之后别智，先查看 uWSGI 日志宗苍，發(fā)現會有少量 worker 崩潰的情況。平時業(yè)務出現問題亿遂，一般是 Python 層面邏輯不對浓若，比如出現 Exception渺杉，請求超時之類的，比較少有進程直接掛掉的情況挪钓。而且我印象里 RPC Server 不太會有這種崩潰的情況是越，以前簡單看過一眼 uWSGI 的 C 擴展部分，不過沒有看細節(jié)碌上，當時就覺得這些對對象引用計數的處理部分挺容易出錯的倚评，其它邏輯倒還好。所以我的第一直覺是 C 擴展部分寫的有問題馏予，而且很可能是 Python 對象引用計數錯誤導致的天梧。

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

這里除了能知道是 master 進程發(fā)現 worker 進程掛了霞丧，然后又拉起來一個臀突，其它重要信息就是 signal 11 和 signal 6 了。

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

而 Abort（signal 6）就好一點了突那，可能是程序主動為之挫酿。而且 GC object already tracked 這條信息非常關鍵，應該是 Python 虛擬機發(fā)現狀態(tài)異常主動拋出來的愕难。

于是翻出 Python 源碼：

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

直覺

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

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

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

找到一個有問題的點

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

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

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

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

不過仔細看另外獲得的 has negative ref count 日志發(fā)現卖宠，錯誤出現同在一個地方。

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

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

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

這里把整個函數全放上來拇惋，是因為這段代碼非常關鍵周偎。

先簡單解釋一下這里在處理什么邏輯：

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

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

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

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

把這個 list 掃描一遍助琐，確保 tuple 的兩個元素 key value 都是 str 類型吴藻，并且把內容塞到 buffer 里邊

釋放 GIL

把 buffer 里的內容和可能傳進來的 body 塞到共享內存并且釋放 buffer

重新獲取 GIL

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

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

因為在 1969 行這一步的時候弓柱，并沒有給 zero 增加引用計數沟堡。

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

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

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

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

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

直覺

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

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

1. spooler 執(zhí)行到的地方即 uWSGI worker 線程在循環(huán)執(zhí)行的過程中把 tuple 放回了對象池

2. 釋放 GIL

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

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

5. 另外那個線程繼續(xù)用這個 tuple蹭劈，增加了其引用計數

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

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

其實如果沒有 uWSGI log 里面那條額外的提示多矮，我猜測的最后幾步順序可能不是這樣，而是稍微簡單一點祟蚀，比如第 4 步把對象放回對象池之后工窍，接著 GC 把對象池清空了，然后第 5 步繼續(xù)使用這個 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 呢铃剔。程序內部到底是什么樣一個過程導致線上崩潰呢。畢竟上面出現崩潰的過程只是一個猜想查刻，實際上并不一定完全是這樣键兜。

復現

現在就需要在線下穩(wěn)定復現這個問題了。實際上復現的過程比找到問題還要麻煩一些穗泵。

搭建線下環(huán)境

于是我用業(yè)務 HTTP 代碼改了一下普气，只留一個接口，并且在接口內部處理的時候盡量精簡佃延，大概只是調用了 spooler 一次现诀，然后隨便折騰用了幾個 tuple，看看隨意的多樣的使用這些 tuple 對象會不會把崩潰的概率提高一些履肃。

由于之前分析過仔沿，這個 bug 跟 Python 多線程有關，所以要想復現這個問題尺棋，要盡量把多線程相關的操作貼近線上環(huán)境封锉，否則折騰半天復現不出來，都不好說哪里的問題膘螟。

業(yè)務方自己并沒有使用多線程成福，唯一用到的地方就是框架中另啟了一個線程去輪詢 consul 以獲取下游的地址列表。所以我把這個 API 的下游全 dump 出來荆残，在接口的入口處先主動調用了一下對應函數奴艾，把列表加到緩存里邊讓線程開始輪詢。這里沒有直接放在初始化的地方内斯，是想讓進程啟動的時候盡量少做事情蕴潦，讓虛擬機內部狀態(tài)簡單可控一些像啼。

嘗試主動清空對象池

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

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

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

之后分析脊串，才發(fā)現這樣嘗試是有問題的辫呻。這個涉及到了 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撵孤。

于是迈着，我非常暴力的加了個循環(huán)：在 dict 里面另外加了 50 個 key value（當然最后精準復現問題的時候是不需要這樣額外加的）。

于是邪码，測試進程頻繁出 core裕菠。復現過程終于有一些進展了。

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

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

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

1. sleep 一下，等待手工打入一條請求昂勉，觸發(fā)寫 spooler 操作

2. 生成五六個 tuple

3. sleep 2s 切回 spooler 進程

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

5. 再生成幾個 tuple

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

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

精準復現

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

GC object already tracked

然后回頭去看代碼迫吐，才發(fā)現原來自己以前對 Python 對象在內存中的布局理解一直有點偏差库菲，那就是記錄一個對象是不是 Tracked 的狀態(tài)的標記是放在對象所在內存的前面，而 refcnt 是在對象的頭部志膀，即所有 Python 對象都有的 PyObject 頭熙宇。

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

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

最后寫出這樣一段代碼：

終于诞吱，每次手動打進來一個請求舟奠，worker 就會崩潰。

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

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

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

總結

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

而復現的時候需要控制兩個線程的執(zhí)行順序，線程交叉兩次獲取 tuple 對象卻三次放回對象池坠宴，然后再連續(xù)嘗試兩次拿出來使用以躯，才可以穩(wěn)定讓程序崩潰。

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