記一次 android 線上 oom 問題

背景

公司的主打產品是一款跨平台的 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 版本也需要同時連接兩個通道,哪個先連接上就用哪個。

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

連接端 偵聽端 結果
tcp local, tcp tcp 成功
local local, tcp local 成功
local, tcp tcp tcp 成功
local, tcp local, tcp local, tcp 均成功,一般 local 搶先

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

問題發生

全量兩天後,正式將特性分支合入 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 error
2021-10-30T20:55:19.84408116 [b61e7920] {netio} kernel_message_transmit:handle_io: pipeerror|system:24 type=1|channel=1
2021-10-30T20:55:19.84480116 [b61e7920] {netio} kernel_message_transmit:handle_io: pipeerror|system:24 type=1|channel=2
2021-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_channel
else
  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?