以下文章來源于阿里云開發(fā)者，作者竹一

導(dǎo)讀

一個(gè)特殊請求引發(fā)服務(wù)器內(nèi)存用量暴漲進(jìn)而導(dǎo)致進(jìn)程 OOM 的慘案。

問題背景

埋點(diǎn)網(wǎng)關(guān)是螞蟻基于 nginx 開發(fā)的接入網(wǎng)關(guān)應(yīng)用，作為應(yīng)用接入層網(wǎng)關(guān)負(fù)責(zé)移動(dòng)端埋點(diǎn)數(shù)據(jù)采集，從去年年底開始有偶現(xiàn)的進(jìn)程 crash 問題。

好在 nginx 設(shè)計(jì)中 worker 進(jìn)程閃退后 master 進(jìn)程會(huì)重新拉起新的進(jìn)程處理請求，埋點(diǎn)客戶端也有重試機(jī)制，偶現(xiàn)閃退沒有造成大的影響。

初步分析

說實(shí)話作為 C 語言應(yīng)用，crash 也沒什么好奇怪的 ：），第一反應(yīng)當(dāng)然是業(yè)務(wù)代碼有問題，查看機(jī)器內(nèi)存的占用也沒有大的起伏。

所以先排除了內(nèi)存泄漏最終 OOM 導(dǎo)致進(jìn)程閃退。大概率是內(nèi)存沒用好，內(nèi)存越界訪問導(dǎo)致的。這種問題排查起來也挺簡單，找部分機(jī)器開啟 core-dump，拿到 core 文件一看就知道是哪里跪了。說干就干，線上找了部分機(jī)器開啟開關(guān)，等問題復(fù)現(xiàn)后登錄，就遇到了第一個(gè)難題：沒有生成核心轉(zhuǎn)儲(chǔ)文件。

反復(fù)檢查 core-dump 開關(guān)確認(rèn)已經(jīng)正確打開，再回頭檢查了一遍最近的代碼變更，也沒看出什么疑點(diǎn)，這時(shí)候就有點(diǎn)一籌莫展了。

如果不是

在走迷宮時(shí)，如果發(fā)現(xiàn)前面無路可走，就得回頭思考前面哪一步是不是走錯(cuò)了。

一開始排除了內(nèi)存泄漏導(dǎo)致的 OOM 問題，是因?yàn)閺谋O(jiān)控上看內(nèi)存占用水位只有 40% 不到，并沒有上漲到內(nèi)存用完。然而這里的監(jiān)控是分鐘級(jí)的，如果內(nèi)存在短時(shí)間內(nèi)暴漲，秒級(jí)尖刺體現(xiàn)到分鐘級(jí)監(jiān)控上很可能被平均值抹平。

再結(jié)合沒有產(chǎn)生 core-dump 文件的現(xiàn)象，如果是內(nèi)存耗盡導(dǎo)致進(jìn)程被 oom-killer 進(jìn)程殺死是說得通的。因?yàn)閛om-killer 進(jìn)程使用SIGKILL信號(hào)強(qiáng)制殺死進(jìn)程，查看 Linux 信號(hào)手冊，根據(jù) POSIX.1-1990 標(biāo)準(zhǔn)，SIGKILL信號(hào)意味著進(jìn)程被強(qiáng)制結(jié)束并且不進(jìn)行核心轉(zhuǎn)儲(chǔ)。

Signal   Standard  Action  Comment
 ────────────────────────────────────────────────────────────────────────
 ...
 SIGIOT     -    Core  IOT trap. A synonym for SIGABRT
 SIGKILL   P1990   Term  Kill signal
 SIGLOST    -    Term  File lock lost (unused)
 ...

問題查到這里，好消息是排查方向總算對了，壞消息是 OOM 進(jìn)程閃退只是問題的表現(xiàn)，而導(dǎo)致內(nèi)存飆升的根本原因還是沒什么頭緒。

懷疑有異常的攻擊流量，然而查看閃退前后該機(jī)器的網(wǎng)絡(luò)流量，inbytes 和 outbytes 并沒有波動(dòng)，所以也基本排除了被突發(fā)流量攻擊；懷疑是網(wǎng)關(guān)上 ip geo 信息查詢的二分查找邏輯有死循環(huán)，經(jīng)過代碼檢查和測試也沒發(fā)現(xiàn)這里有問題；甚至懷疑系統(tǒng)跑久了有內(nèi)存碎片，但經(jīng)過排查也排除了這種可能，今年之前也沒出現(xiàn)這種問題。

所以目前的情況就是在沒有任何外部攻擊的情況下，系統(tǒng)內(nèi)存突然就爆了。這還真是見了鬼，排查了這么多問題，如此詭異的情況也是少見。

core-dump!

core-dump 文件是進(jìn)程閃退前最后的“遺照”，類似尸檢之于法醫(yī)，對于查問題能提供非常多線索。拿不到轉(zhuǎn)儲(chǔ)文件真是兩眼一抹黑 —— 全靠猜。所以痛定思痛，決定想辦法把 core-dump 文件拿到。

既然閃退是因?yàn)閮?nèi)存占用過高，而被 oom-killer 殺死又不會(huì)進(jìn)行核心轉(zhuǎn)儲(chǔ)，總不能到 Linux 內(nèi)核里修改 oom-killer 發(fā)送的信號(hào)。在跟師兄討論時(shí)，師兄提出一個(gè)思路：在用戶態(tài)實(shí)現(xiàn)一個(gè) oom-killer（青春版），當(dāng)然沒有復(fù)雜的打分邏輯，只需要檢測目標(biāo)進(jìn)程的內(nèi)存用量，到閾值之后發(fā)送一個(gè)可以產(chǎn)生內(nèi)核轉(zhuǎn)儲(chǔ)行為的信號(hào)來殺死進(jìn)程，通過主動(dòng)殺死進(jìn)程的方式產(chǎn)生 core-dump 文件。

后面師兄抽空幫忙寫了一個(gè) nginx 輔助進(jìn)程，邏輯是每秒檢測一次所有 worker 進(jìn)程的內(nèi)存用量，如果超過一定閾值就發(fā)送SIGABORT信號(hào)主動(dòng)殺死對應(yīng)進(jìn)程。當(dāng)然為了防止工具誤殺導(dǎo)致更嚴(yán)重的問題，限制在應(yīng)用重啟后的生命周期內(nèi)最多只會(huì)觸發(fā)一次。

找了部分機(jī)器部署之后，還真給拿到了 core-dump 文件，不過還有個(gè)小插曲，第一次拿到的文件過大發(fā)生了截?cái)啵罄m(xù)又將單進(jìn)程的內(nèi)存閾值從 8GB 調(diào)整為 4GB，終于拿到了完整可用的 core-dump！

如上圖可以看到程序的堆棧，這種通過自殺產(chǎn)生的內(nèi)核堆棧不像內(nèi)存越界的堆棧直接指向了程序崩潰點(diǎn)，當(dāng)前的堆棧只能反應(yīng)程序在異常時(shí)執(zhí)行的代碼，不一定是準(zhǔn)確的問題點(diǎn)，但也能提供非常多的線索。從堆棧結(jié)合代碼可以看出程序正在進(jìn)行數(shù)據(jù)攢批寫出， 再往前是 schema 埋點(diǎn)數(shù)據(jù)的拆分，攢批寫出時(shí)恰好在調(diào)用 ngx_pcalloc 函數(shù)從內(nèi)存池中申請內(nèi)存，所以很可能是在 schema 埋點(diǎn)數(shù)據(jù)拆分之后的攢批發(fā)送時(shí)內(nèi)存分配出了問題。

合理猜測

在繼續(xù)分析之前插入一個(gè)我們的業(yè)務(wù)流程，大致可以分為請求接收、數(shù)據(jù)處理、數(shù)據(jù)攢批、數(shù)據(jù)發(fā)送幾個(gè)階段，為了保護(hù)埋點(diǎn)網(wǎng)關(guān)，在這些階段分別設(shè)置了數(shù)據(jù)大小限制：

數(shù)據(jù)解壓前的 body 大小限制 4MB 以內(nèi)；

解壓后的數(shù)據(jù)限制 32MB 以內(nèi)；

而拆分后單條埋點(diǎn)大小限制根據(jù)業(yè)務(wù)類型動(dòng)態(tài)調(diào)整，最大支持 2MB；

既然程序申請了這么多內(nèi)存，也拿到了 core-dump，直接將內(nèi)存 dump 出來看看里面都裝了些什么數(shù)據(jù)，根據(jù)數(shù)據(jù)的內(nèi)容可以大概推測是哪個(gè)節(jié)點(diǎn)申請的內(nèi)存。再將之前的 core-dump 文件翻出來尋找蛛絲馬跡，從內(nèi)存中看到大量攢批完成準(zhǔn)備發(fā)送的日志內(nèi)容，說明很可能是數(shù)據(jù)攢批發(fā)送階段占用了大量內(nèi)存。

數(shù)據(jù)從攢批到發(fā)送階段的內(nèi)存管理使用了內(nèi)存池，開始攢批時(shí)創(chuàng)建內(nèi)存池，在攢批完成后會(huì)將數(shù)據(jù)打包為 HTTP 協(xié)議發(fā)送出去，期間會(huì)經(jīng)過 ProtoBuf 序列化、壓縮、生成簽名等流程，最后數(shù)據(jù)寫出成功后將內(nèi)存池整體釋放。

仔細(xì)分析這里內(nèi)存相關(guān)的動(dòng)作，有一個(gè)問題是內(nèi)存的分配比較粗曠，因?yàn)橛胁糠謹(jǐn)?shù)據(jù)有單條超大埋點(diǎn)的需求，比如客戶端閃退堆棧數(shù)據(jù)，在數(shù)據(jù)攢批階段為了保證每次攢批至少能存放一條以上的數(shù)據(jù)，所以內(nèi)存池創(chuàng)建時(shí)的最低大小設(shè)置為攢批閾值 + 單條埋點(diǎn)最大限制 + 部分協(xié)議元數(shù)據(jù)大小，最終這個(gè)值大約是 3MB，意味著創(chuàng)建一個(gè)寫出請求至少會(huì)申請 3MB 內(nèi)存。但正常情況下數(shù)據(jù)發(fā)送相對數(shù)據(jù)流入的數(shù)量級(jí)會(huì)少很多，寫出請求的創(chuàng)建也會(huì)隨著請求流入和數(shù)據(jù)攢批打散，內(nèi)存池在數(shù)據(jù)寫出完成后就會(huì)釋放，內(nèi)存的輪轉(zhuǎn)速度非常快，所以網(wǎng)關(guān)的內(nèi)存占用并不高，僅有 30% 左右。

將目光轉(zhuǎn)向內(nèi)存池的釋放階段，該階段是在 HTTP 數(shù)據(jù)發(fā)送完成并收到響應(yīng)后做的，沒有提前釋放是因?yàn)槿魯?shù)據(jù)寫出失敗，網(wǎng)關(guān)需要將數(shù)據(jù)暫存到內(nèi)存或磁盤中，在后續(xù)進(jìn)行重試，看起來好像也沒有什么地方會(huì)有發(fā)生急性內(nèi)存泄漏。

但考慮極端情況，如果前面的數(shù)據(jù)攢批速度遠(yuǎn)超數(shù)據(jù)寫出呢？會(huì)一瞬間創(chuàng)建大量寫出請求，而數(shù)據(jù)發(fā)送到下游，同機(jī)房的一個(gè) rt 大約 20ms，如果從上海跨機(jī)房調(diào)用到河源，一個(gè) rt 就需要 40ms 了，若數(shù)據(jù)還沒來得及寫出完成并釋放內(nèi)存池，理論上有可能導(dǎo)致內(nèi)存占用飆升。但從之前的分析看，問題機(jī)器上并沒有大量數(shù)據(jù)涌入，若是單個(gè)請求過大，對于單個(gè)請求還有 4MB 的數(shù)據(jù)大小限制，怎么才能一瞬間將整個(gè)內(nèi)存超過 10GB 的空間打滿？

四兩撥千斤

以上都是猜測，既然懷疑是這里，干脆就加監(jiān)控指標(biāo)發(fā)上去看看內(nèi)存究竟申請了多少。上線后發(fā)現(xiàn)在問題機(jī)器閃退的時(shí)間點(diǎn)，創(chuàng)建寫出請求的數(shù)量確實(shí)出現(xiàn)了一個(gè)明顯尖刺，由于之前增加了進(jìn)程內(nèi)存限制，這里還沒有漲更高就因?yàn)橛|發(fā)閾值被殺死。到這里問題的直接原因算是定位到了：短時(shí)間內(nèi)創(chuàng)建了大量數(shù)據(jù)寫出請求，內(nèi)存池來不及釋放，導(dǎo)致內(nèi)存瞬間被打爆。

打破砂鍋問到底，又是什么場景下會(huì)集中創(chuàng)建寫出請求呢？兩種可能：

有大量上報(bào)請求流入。之前也提到過，從單機(jī)的網(wǎng)絡(luò)流量監(jiān)控來看，問題時(shí)間點(diǎn)并沒有波動(dòng)，并且這臺(tái)機(jī)器上的其他 worker 進(jìn)程也沒有問題，所以基本可以排除第一種場景。

單次上報(bào)請求中攜帶了非常多數(shù)據(jù)。而對于單次請求，網(wǎng)關(guān)有設(shè)置 4MB 的原始數(shù)據(jù)限制，攜帶超過 4MB 的數(shù)據(jù)上報(bào)會(huì)被直接拒絕服務(wù)。難道這不到 4MB 的數(shù)據(jù)經(jīng)過一系列處理和攢批，真就撬動(dòng)了超 10GB 的內(nèi)存消耗？

從之前的內(nèi)存 dump 中又發(fā)現(xiàn)了可疑的地方，一個(gè)用戶的 uid 在內(nèi)存里重復(fù)了 6 萬次！再細(xì)看重復(fù)的數(shù)據(jù)，大部分字段都是相同的，僅有 timestamp、startTime、endTime 等時(shí)間戳字段不同。到這里第一時(shí)間想到的是一種攻擊方式——壓縮炸彈。大量重復(fù)字符，意味著更高的數(shù)據(jù)壓縮率，因?yàn)椴徽撌?LZ77 算法、哈夫曼編碼還是字典編碼，壓縮算法的核心都是利用各種手段減少重復(fù)數(shù)據(jù)占用的存儲(chǔ)空間。

正常線上的請求壓縮率根據(jù)業(yè)務(wù)上報(bào)策略的差異平均會(huì)在 30% 左右，而如果數(shù)據(jù)大量重復(fù)，這個(gè)壓縮率則會(huì)非常高。根據(jù) dump 出來的數(shù)據(jù)，簡單擼了個(gè)腳本手動(dòng)構(gòu)造出類似的測試數(shù)據(jù)，時(shí)間戳隨機(jī)遞增，其他耗時(shí)相關(guān)的字段取隨機(jī)數(shù)，剩余字段用固定 mock 值。

執(zhí)行結(jié)果如下，單條埋點(diǎn)經(jīng)過 ProtoBuf 序列化后為 3.47KB，一萬條埋點(diǎn)打包后原始數(shù)據(jù)有 34.7MB，壓縮后只剩 1.2MB，壓縮率達(dá)到恐怖的 3.5%，這就能解釋為何前面有 4MB 的 body 大小限制但沒能防住超大數(shù)據(jù)上報(bào)。

origin data bytes: 34697723
compressed data bytes: 1214252

真相大白

將 mock 出的原始數(shù)據(jù)裁剪到 32MB 以內(nèi)再發(fā)送到埋點(diǎn)網(wǎng)關(guān)，果然復(fù)現(xiàn)了內(nèi)存暴漲并閃退的問題。埋點(diǎn)網(wǎng)關(guān)對于文本類埋點(diǎn)有單次請求最多攜帶的埋點(diǎn)條數(shù)限制，而對于 ProtoBuf 類型的 schema 埋點(diǎn)還沒有做限制。于是在生產(chǎn)環(huán)境先增加了對超量 schema 埋點(diǎn)上報(bào)的告警，發(fā)現(xiàn)確實(shí)存在零星攜帶超量埋點(diǎn)的請求，接著再對 schema 類型的埋點(diǎn)增加了條數(shù)限制后果然再?zèng)]有閃退，可以確認(rèn)根本原因是這里了。

但話說回來，這次上報(bào)雖然日志條數(shù)非常多，就算有重復(fù)數(shù)據(jù)的壓縮率高問題，解壓后最多也就 32MB 的原始數(shù)據(jù)，又是如何放大到超過 10GB 呢？

答案也在 dump 出的數(shù)據(jù)內(nèi)容中，可以看到大量重復(fù)數(shù)據(jù)的埋點(diǎn)業(yè)務(wù)碼，對應(yīng)業(yè)務(wù)對數(shù)據(jù)的時(shí)效性要求非常高，所以數(shù)據(jù)攢批閾值設(shè)置得很小，每攢夠 25.6KB 即會(huì)觸發(fā)一次日志寫出。意味著一個(gè) 32MB 原始數(shù)據(jù)的請求上來，在數(shù)據(jù)攢批發(fā)送時(shí)會(huì)瞬間創(chuàng)建出大約 1250 個(gè)寫出請求，每個(gè)寫出請求的內(nèi)存池至少 3MB，就會(huì)申請出總計(jì) 3.75GB 的內(nèi)存。

話又說回來，3.75GB 離 10GB 還是差很遠(yuǎn)，因?yàn)檫€沒完，端特征埋點(diǎn)因?yàn)橛袑?shí)時(shí)消費(fèi)需求，所以網(wǎng)關(guān)會(huì)同時(shí)寫出三份數(shù)據(jù)，一份寫出到 SLS，還有兩份分別發(fā)送到不同的應(yīng)用系統(tǒng)，每個(gè)寫出通道都有獨(dú)立的數(shù)據(jù)攢批發(fā)送流程，最終申請的內(nèi)存大小就是 3.75GB * 3 = 11.25GB。

排查到這里，問題的原因鏈條就比較完整了：

單次請求攜帶大量埋點(diǎn)數(shù)據(jù)，因?yàn)橹貜?fù)字段多壓縮率足夠高，所以繞過了前面對請求 body 的尺寸限制；

埋點(diǎn)網(wǎng)關(guān)在數(shù)據(jù)攢批發(fā)送階段的內(nèi)存池分配粗曠，默認(rèn)按鏈路的最大閾值來分配內(nèi)存，并且內(nèi)存池釋放依賴請求寫出完成，內(nèi)存釋放速度遠(yuǎn)小于數(shù)據(jù)流入速度；

高時(shí)效、多份寫出的業(yè)務(wù)特性，更是讓原本粗曠的內(nèi)存管理雪上加霜，這些因素疊加在一起，最終撬動(dòng)了超過 10GB 的內(nèi)存消耗；

話又又又說回來，以前為什么沒有出現(xiàn)這個(gè)情況？

因?yàn)槁顸c(diǎn)網(wǎng)關(guān)的數(shù)據(jù)大小限制經(jīng)歷了幾次調(diào)整，為了支持客戶端閃退這類超大埋點(diǎn)的上報(bào)，網(wǎng)關(guān)分別將數(shù)據(jù)大小限制從壓縮后 2MB、解壓后 16MB、單條埋點(diǎn) 256KB 調(diào)整到了當(dāng)前的壓縮后 4MB、解壓后 32MB、單條埋點(diǎn)限制支持根據(jù)業(yè)務(wù)動(dòng)態(tài)調(diào)整，也就間接達(dá)成了原因鏈條里的第二個(gè)因素。

解決方案

之前為 schema 埋點(diǎn)增加了單次請求最多攜帶的埋點(diǎn)條數(shù)限制，閃退問題雖然已經(jīng)解決，但排查下來可以發(fā)現(xiàn)閃退是各種因素疊加在一起導(dǎo)致的結(jié)果，這些地方都還有優(yōu)化空間，對于埋點(diǎn)網(wǎng)關(guān)這種百萬 QPS 的在線服務(wù)，性能和穩(wěn)定性的優(yōu)化非常有必要。

對于數(shù)據(jù)攢批發(fā)送，內(nèi)存池很大一部分空間被原始數(shù)據(jù)占用，其實(shí)原始數(shù)據(jù)在經(jīng)過 Protobuf 序列化及壓縮后就不再需要了，因?yàn)?HTTP 請求發(fā)送和后續(xù)的失敗緩存使用的都是壓縮后數(shù)據(jù)。原始數(shù)據(jù)使用的這塊內(nèi)存可以提前到請求發(fā)送之前就釋放，不用等待請求結(jié)束才能釋放內(nèi)存。而壓縮之后的數(shù)據(jù)量大約只有原始數(shù)據(jù)的十分之一，大幅提升內(nèi)存的輪轉(zhuǎn)效率。

內(nèi)存的分配其實(shí)也可以更精細(xì)，之前為每個(gè)寫出請求分配了 3MB 內(nèi)存，是為了支持單條超大埋點(diǎn)，例如客戶端閃退埋點(diǎn)一條最大可能達(dá)到 2MB，為了保證攢批時(shí)至少能存一條埋點(diǎn)，并且網(wǎng)關(guān)的內(nèi)存資源比較寬裕，這塊內(nèi)存池創(chuàng)建得很大，實(shí)際使用中大部分業(yè)務(wù)攢批都用不到這么大的內(nèi)存，可以改為根據(jù)攢批數(shù)據(jù)量動(dòng)態(tài)擴(kuò)容。

除了這些縫縫補(bǔ)補(bǔ)，我們也在探索使用內(nèi)存安全的語言比如 Rust 來實(shí)現(xiàn)更多能力，這里不過多展開。

小結(jié)

歷時(shí)半年之久，經(jīng)過反復(fù)猜測、修改、驗(yàn)證，終于將網(wǎng)關(guān)上這個(gè)“定時(shí)炸彈”成功拆除，在成功復(fù)現(xiàn)并定位到根因后真是長舒一口氣，總結(jié)下來一點(diǎn)小小的心得（主要還是心理層面的，技術(shù)方面還需要一題一議，不具有普適參考價(jià)值）：

堅(jiān)信任何現(xiàn)象都有其背后的原因，在排查時(shí)苦于找不到方向，屢次道心破碎想過放棄，但線上的閃退告警時(shí)刻提醒著“革命尚未成功，同志仍需努力”。

沒有思路時(shí)可以拿出來和別人討論案情，思維碰撞中往往會(huì)有靈光乍現(xiàn)。

大膽假設(shè)，小心求證。通過現(xiàn)象推測可能的原因并一一驗(yàn)證，同時(shí)要有將之前的假設(shè)都推翻重來的勇氣。