摘要：問題分析隨著回滾版本的放量，主端崩潰逐漸回歸正常，進一步坐實了新版本存在問題。內容非常多但都是重復的，看起來進程沒有啟動，導致連接端一直在進行重連。

背景

公司的主打產品是一款跨平臺的 App，我的部門負責為它提供底層的 sdk 用于數據傳輸，我負責的是 Adnroid 端的 sdk 開發。

sdk 并不直接加載在 App 主進程，而是隔離在一個多帶帶進程中，然后兩個進程通過 tcp 連接進行通信的，這樣做的目的是減少因 sdk 的崩潰帶來的主進程 crash，為用戶帶來更好的體驗。

如上圖所示，sdk 主要實現于 service.so 中被 Work 進程加載，kernel.so 通過 jni 嵌入在 App 主進程，前者作為偵聽端，后者是連接端。

不過這樣做有一個問題，當偵聽端口被占用時，兩個進程就無法建立通信了，導致數據無法傳輸。為了解決這個問題，打算用本地 socket (unix domain socket) 代替 tcp socket，因為前者不依賴端口號，只依賴文件路徑，而 Android 中的私有存儲可以有效的防止文件沖突。

這個替換過程也不能一蹴而就，因為 App 進程加載的 so 與 Work 進程加載的可能并不是一個版本，考慮到向后兼容，新的 service 版本需要同時偵聽 tcp 與 local 兩個通道，新的 kernel 版本也需要同時連接兩個通道，哪個先連接上就用哪個。

開發完成的自測階段一切正常，驗證了以下組合：

結果符合預期，提測階段也順利通過，于是通過版本灰度，逐漸替換線上的舊版本，各個灰度階段觀察正常，最后正式全量發布。

問題發生

全量兩天后，正式將特性分支合入 master，結果合入沒 30 分鐘，QA 反饋主端 oom (out of memory) 崩潰異常升高，需要回滾版本驗證。

了解了一下情況，發現主端的全部版本崩潰率確實從 0.01％ 升高到了 0.05％~0.07% 的水平，且大量新增的崩潰類型堆棧顯示 oom 信息，最關鍵的是崩潰升高的趨勢和 sdk 灰度的節奏完全吻合，而這期間主端也沒有發布新的版本，于是只能回滾 sdk 版本嘗試。

糟糕的是剛剛合入代碼，使用 revert 回滾提交的幾個 commit，又出現了一大堆沖突提示。正在解決沖突的過程中，QA 等不急了，建議從之前合入的位置直接拉分支打版本，一頓操作猛于虎，很快就打好了回滾版本，當天就通過測試小流量了。

第二天來了一看，崩潰率果然應聲下降，于是 QA 開啟全量修復。同時研究了一個短平快的 master 回滾方案：新建一個目錄，clone 并 checkout 到合入前的代碼，將 .git 目錄刪除后用這個目錄覆蓋舊的工作目錄，最后將所有 modified 的文件作為新版本直接提交。這樣做的好處是可以得到與合入前完全一樣的代碼，防止手工處理沖突引入新的變更。

問題分析

隨著回滾版本的放量，主端 oom 崩潰逐漸回歸正常，進一步坐實了新版本存在問題。oom 問題非常不好排查，原因是崩潰時的堆棧與引入 bug 的地方已經相差了十萬八千里，不能直接定位問題點。

好在這個版本之前做過一次小流量，看當時的崩潰率沒有明顯升高，在準備全量前，合入了 master 上的最新修改、ios 平臺的一些代碼等，因此重點排查兩個版本的差異部分，應該就可以定位引入問題的點了。

走查了一遍，沒有發現明顯的內存泄漏代碼：

• master 是穩定版本，不存在內存泄漏；
• ios 平臺代碼通過宏定義作了隔離，對 android 沒有影響；

只有一個地方非常可疑——這是一個日志上報操作，只在特定場景下發生，日志上報時并不是直接上報到服務器，而是放入一個隊列，再由專門的線程負責上傳。一次上報并不會占用太多內存，但關鍵是一旦進入這個特定場景，日志就會一直產生，而主端會在傳輸數據的過程中頻繁調用這個接口，導致大量的日志進入隊列，特別是當用戶處于非 WIFI 環境下，日志上報會被關閉來節省流量，進一步加劇了隊列積壓，最終導致隊列瘋狂增長耗盡內存……

知道了原因，改起來就簡單了，加一個 bool 標記，上報過后設置這個標記下次就不再上報了，因為這類日志有一條用來排查問題就足夠了。

問題定位

修復版都打好準備送測了，老大的一句話提醒了我——最好能在本地復現一下。于是基于有問題的版本，稍加修改讓它一啟動就不停上報日志，關閉 WIFI 打開 4G，用這個版本在測試機上跑了一整天，進程居然沒崩潰！

于是不得不評估一下日志上報的泄漏規模，按一條日志最大 300 字節、主端 2 次/秒的調用頻率計算，一天占用內存為 300 * 2 * 3600 * 24 = 51840000 B < 50 MB，雖然也不小了，但是對于動轍 4~8 GB 的智能手機而言，實在不算什么，要想泄漏 4 GB 得不關機運行將近 82 天，不要說現在沒有這樣一直不關機的用戶，即使有，Android 的后臺進程優化功能也早就將 App 殺了上萬遍了，哪容你泄漏這么久～ 別說你不是微信，就是微信系統該殺也就殺了~

與同事一起研究這個問題后，自己又提出來一個疑點：假如是因為日志泄漏導致的 oom，那應該是 Work 進程崩潰，而不是出現大量的 App 進程崩潰。如果是因為內存耗盡導致系統上所有進程崩潰，那也至少是崩潰率一起升高，而不像現在只有 App 進程崩潰率升高，所以越看越不像是這個原因導致的。

問題根因

正當排查方向一片迷茫的時候，同事的一句話提醒了我——如果能抓到崩潰現場的日志就好辦了。可是怎么抓呢？崩潰平臺記錄的是崩潰時間和 CUID，后者用于標識一次唯一的崩潰事件；日志抓取需要時間范圍和用戶 UID，而崩潰平臺并不提供 UID。

這時同事神秘兮兮的祭出了一條鏈接，點開一看：ID-Mapping，可以將各種系統的 ID 進行批量轉換，其中就包括 CUID 向 UID 的轉換，好家伙，這不就是我想要的？老同事真的渾身都是寶，摸著他們過河錯不了~

大部分 UID 沒有撈取到日志，只有兩個用戶有日志。內容非常多但都是重復的，看起來 Work 進程沒有啟動，導致連接端一直在進行重連。在連接后期都發現了這樣的日志：

2021-10-30T20:55:19.84255454 [b61e7920] {netio} LocalHandler::post_connect: local endpoint failed with system:24, fatal error2021-10-30T20:55:19.84408116 [b61e7920] {netio} kernel_message_transmit:handle_io: pipeerror|system:24 type=1|channel=12021-10-30T20:55:19.84480116 [b61e7920] {netio} kernel_message_transmit:handle_io: pipeerror|system:24 type=1|channel=22021-10-30T20:55:31.05991064 [b61e7920] {netio} kernel_service_interface:on_ready_timeout: restart! running=1, channel=0

查了下系統錯誤碼：

#define EMFILE      24  /* Too many open files */

這種錯誤一般是打開的句柄超過 linux 進程的最大打開文件句柄數 (一般是 1024)，這個值對于服務器程序來說一般是不夠用的，需要通過系統設置來拉高上限。但對于 App 進程是足夠了，怎么會超限呢？難道是出現了句柄泄漏。于是馬上去走查了連接關閉的代碼：

if channel=local then   close local_channel else if channel=tcp then   close tcp_channelelse  nothing        channel = none

這里使用了偽代碼來說明大意，其中 channel 標記當前使用的連接方式，初始時設置為 none，連接時兩種方式同時發送異步連接請求，先收到應答的連接將設置對應的 channel 值并關閉另一種連接通道，連接建立成功后 channel 必為兩種方式之一 (local | tcp)。

上面推演的是正常的場景，當 Work 進程沒有啟動而導致兩個通道都無法完成連接時，channel 將一直保持 none 值直到超時，在連接重啟前，會嘗試使用上面這段代碼清理資源，此時就會命中最后的 else 邏輯——什么也不做——從而導致連接句柄被泄漏。以 10 秒重連、6 秒超時一次計算，每 16 秒就泄漏 2 個句柄，1024 個句柄泄漏光只需要不到 2 小時！

為了驗證，專門修改了一版代碼，人為制造 Work 進程不啟動的場景，果然跑了沒多久 App 進程就崩潰重啟了。確定了問題根因，再回顧一下現象，之前那幾個疑問就能得到解釋了：

• 問題表現為打開文件、創建線程均失敗的 oom 問題，實際是 oof (out of fd)，句柄泄漏的表現和內存泄漏有相似的地方
• 問題存在于 kernel，當 kernel 耗光句柄后對應的 App 進程會因 EMFILE 錯誤崩潰，Work 進程反而是沒什么事，所以表現為 App 進程崩潰率多帶帶升高
• 只影響一部分 Work 進程長時間不啟動的用戶，這部分用戶占比較少，所以崩潰率升高有限
• 之前小流量的那版也有問題，只是放量較少所以崩潰率升高不明顯而已

問題的修復非常簡單，就是在關閉清理資源時，不再根據 channel 判斷，直接 close 所有句柄。打好的修復版本在 Work 進程不啟動的場景下運行了一天也沒有出現崩潰，對外灰度后，觀察 App 崩潰率正常，逐步全量覆蓋線上版本，最后合入 master。

結語

復盤整個 oom 問題產生的過程，為何在灰度階段沒有發現 App 進程崩潰率異常升高呢？原來在看崩潰數據時是過濾了 sdk 版本號的，而實際發生異常升高的版本號卻是奇特的 0.0.0.1 版本，因而沒有觀察到。

為何 oom 問題會集中在 0.0.0.1 版本中？進一步排查發現并非只有 oom 崩潰是這樣，90% 的崩潰都歸類在了這個版本下面，原因竟然是 App 在初始化時沒有處理好先后關系，從 sdk 拿版本號時 sdk 還未初始化，所以得到了一個無效的版本值。更嚴重的是，該問題幾乎一直存在，而我們之前過濾版本號的做法幾乎可以肯定是不正確的，想到這里不由得背上直冒冷汗！幸好有這次問題的復盤，不然這個問題要繼續存在多久還是個未知數~

最后總結一下 oom 問題的處理方法，首先不要心慌，特別是在不經求證的情況下靠猜測來定位問題、靠不斷發小版本在線上驗證問題，這樣做一來不嚴謹，二來效率比較低，最終很可能還會定位不到問題。最好的辦法是通過現場日志來定位出錯的場景，可以極大的縮小排查范圍；另外 oom 與 oof 在 Java 崩潰堆棧中有相似的表現，因此遇到這類問題可以多考慮下句柄泄漏的可能性，而不是一味觀察內存的分配與釋放。

另外可能還有人對 Work 進程為何沒有啟動感興趣，但這就屬于另外一個問題了，可以多帶帶寫篇文章了。目前仍在排查中，真的是應了那句：生命不息，debug 不止~~

參考

[1]. Git 如何優雅地回退代碼，用 reset 還是 revert？