背景
今年上半年接手了一位離職同事負(fù)責(zé)的推薦項(xiàng)目，主要是圍繞智能推薦服務(wù)相關(guān)的內(nèi)容，包括了離線、實(shí)時(shí)數(shù)據(jù)處理和線上的預(yù)測服務(wù)。
這里的堆外內(nèi)存泄漏也是發(fā)生在預(yù)測服務(wù)這一塊，大概的表現(xiàn)情況就是線上服務(wù)運(yùn)行一段時(shí)間后，客戶端會(huì)發(fā)生大面積connect reset異常，并且在較短時(shí)間內(nèi)會(huì)發(fā)生雪崩的情況，下面就簡單回顧一下整個(gè)問題的排查過程。
環(huán)境
該服務(wù)運(yùn)行在公司內(nèi)部的微服務(wù)框架上，這套框架比較久遠(yuǎn)，依舊是基于HTTP1.X協(xié)議進(jìn)行通信的，傳輸?shù)男蛄谢玫氖莋oogle的Gson，Server端基于Netty自研了一套，Client端則是基于okhttp3開發(fā)的。
我們服務(wù)端目前部署了67臺節(jié)點(diǎn)，下游調(diào)用端超過100臺節(jié)點(diǎn)。
公司近期做了雙中心推廣，很多服務(wù)都進(jìn)行了雙中心部署。
Server節(jié)點(diǎn)配置信息：
8核 13G，系統(tǒng)版本Centos Linux realease 7.8.2003
服務(wù)性能指標(biāo)：
TP99：50ms
TP95：30ms
QPS：2000+（其實(shí)不高）
JVM啟動(dòng)參數(shù)：
這里就截取部分參數(shù)了
-Xms10240m -Xmx10240m -XX:NewSize=3072m -XX:MaxNewSize=3072m -XX:MaxDirectMemorySize=1024m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/skynet-xxx/xxx_heapDump.hprof -XX:+UseParNewGC -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1024M -XX:+ExplicitGCInvokesConcurrent -XX:-UseGCOverheadLimit -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=65 -XX:CMSFullGCsBeforeCompaction=2 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:/data/logs/skynet-xxx/xxx_gc.log
請求入?yún)⑸?，客戶端請求參?shù)大概在mb級別，小點(diǎn)的基本也在數(shù)十kb左右，這里入?yún)⑤^大的原因也是業(yè)務(wù)決定的，單次請求下，用戶需要組裝的Item集數(shù)量很大，并且推薦模型所用到的特征中，實(shí)時(shí)特征部分也大量依賴了實(shí)時(shí)的Item業(yè)務(wù)屬性，例如，兩程方案按照用戶請求動(dòng)態(tài)組合所計(jì)算出的特征會(huì)依賴Item的具體多個(gè)業(yè)務(wù)屬性，因此入?yún)?bào)文大也就可以理解了。
故障
先來看下當(dāng)天的故障監(jiān)控
8點(diǎn)半開始，下游調(diào)用方開始大面積訪問異常，并且出現(xiàn)雪崩的現(xiàn)象，當(dāng)時(shí)9點(diǎn)半收到通知報(bào)警（當(dāng)天正好是周五，美好的周五準(zhǔn)備晚點(diǎn)到公司，恰逢高架無限堵車，均速5碼，不知道大家能體會(huì)筆者當(dāng)時(shí)的心境不，唉，其實(shí)當(dāng)時(shí)不光滿心都是淚，三急也是呼之欲出的狀態(tài)，then，N minutes later......）。
到公司那一刻起，開始定位問題，調(diào)用方發(fā)現(xiàn)大面積拋connect reset
分析
1 查看日志
首先定位服務(wù)端日志異常，看下來，并沒有發(fā)現(xiàn)存在可疑異常，采樣了幾臺節(jié)點(diǎn)，通過jstack打印了線程棧，看了下，也并沒有看到blocked住的情況。
無奈去查看公共微服務(wù)日志文件夾下的日志，結(jié)果發(fā)現(xiàn)了端倪，Server端大量拋OOM。
2 問題分析
就OOM來看，是源于Netty堆外內(nèi)存溢出引起的，再看used：1056964615, max：1073741824，已用堆外內(nèi)存1056964615=1056964615/1024/1024>1008M，而max=1073741824/1024/1024=1024M，Netty再向堆外申請16777216=16777216/1024/1024=16M內(nèi)存時(shí)，明顯就不夠了，因此拋OOM。
這里回看本文開頭提到的JVM啟動(dòng)參數(shù)也可以對應(yīng)起來，-XX:MaxDirectMemorySize=1024m，剛好max也是1024M。
緊接著，我們就去查看了下Netty具體的溢出判定邏輯。
先看PlatformDependent類中的incrementMemoryCounter方法：
Netty內(nèi)部通過全局的DIRECT_MEMORY_COUNTER變量來統(tǒng)計(jì)應(yīng)用端已經(jīng)使用的堆外內(nèi)存空間，并且DIRECT_MEMORY_COUNTER也被申明為全局靜態(tài)變量，在allocateDirectNoCleaner和reallocateDirectNoCleaner會(huì)做compareAndSet(usedMemory, newUsedMemory)增加動(dòng)作，如exception則執(zhí)行decrementMemoryCounter，相當(dāng)于回滾；在freeDirectNoCleaner也會(huì)進(jìn)行decrementMemoryCounter，歸還已經(jīng)申請的空間。
其實(shí)到這里，業(yè)務(wù)訂單流失的壓力已經(jīng)很大了，為了優(yōu)先保障業(yè)務(wù)，這里保留了一臺線上故障節(jié)點(diǎn)的故障現(xiàn)場，先將所有故障節(jié)點(diǎn)進(jìn)行重啟，重啟前留了個(gè)心，將DIRECT_MEMORY_COUNTER變量進(jìn)行了監(jiān)控，監(jiān)控部分代碼也同時(shí)上線重啟，代碼如下：
@Component
public class DirectMemoryReporterImpl {
private AtomicLong directMemory;
@PostConstruct
public void init() {
Field field = ReflectionUtils.findField(PlatformDependent.class, "DIRECT_MEMORY_COUNTER");
field.setAccessible(true);
try {
directMemory = (AtomicLong) field.get(PlatformDependent.class);
} catch (IllegalAccessException ignored) {
}
ScheduledExecutorService scheduledExecutorService = Executors.newSingleThreadScheduledExecutor();
scheduledExecutorService.scheduleAtFixedRate(this::doReport, 0, 1, TimeUnit.SECONDS);
}
private void doReport() {
try {
long memory = directMemory.get();
SkyLogHelper.traceInfo(LogModule.Monitor, "DirectMemoryReporterImpl", "doReport", "DIRECT_MEMORY_COUNTER -> " + memory + "b", "");
} catch (Exception e) {
SkyLogHelper.traceError(LogModule.Monitor, "DirectMemoryReporterImpl", "doReport", "e", "", e);
}
}
}
重新部署期間，除了觀察線上調(diào)用側(cè)的異常指標(biāo)監(jiān)控外，又想了下，為什么會(huì)有16M的內(nèi)存申請呢，16M又是哪來的呢，然后繼續(xù)按照異常棧一步步跟源碼，到了PoolArena類的newChunk方法，并且這里的chunkSize是由PoolArena類的allocateNormal傳入，這里能看到DirectArena是PoolArena的實(shí)現(xiàn)，而調(diào)用其構(gòu)造方法的地方則是PooledByteBufAllocator的初始化方法。
PoolArena
PooledByteBufAllocator
validateAndCalculateChunkSize就是計(jì)算Chunk大小的方法，通過pageSize頁大小和maxOrder深度來計(jì)算的，在PooledByteBufAllocator內(nèi)部也有兩個(gè)地方有說明，如下：
具體Netty是如何管理PoolChunk的大家可以參考下這篇文章 [支撐百萬級并發(fā)，Netty如何實(shí)現(xiàn)高性能內(nèi)存管理]，講的還是比較不錯(cuò)的，這里就不額外展開了。
我們回到服務(wù)，接著聊，生產(chǎn)部署完成后，找了下具體新部署的節(jié)點(diǎn)，觀察下剛剛上線的DIRECT_MEMORY_COUNTER監(jiān)控，N hours later......
果然，存在持續(xù)緩慢增長的內(nèi)存泄漏問題，由于項(xiàng)目內(nèi)部并沒有存在持續(xù)的基于Netty的IO操作，因此將懷疑點(diǎn)下沉到底層組件。
復(fù)現(xiàn)
這里筆者將所有的業(yè)務(wù)邏輯代碼全部注掉，只保留微服務(wù)協(xié)議接口，方法內(nèi)部只做了一個(gè)Thread.sleep(50);然后返回結(jié)果，并將代碼在線下本地部署；sdk端使用公司client進(jìn)行了兩輪壓測，壓測邏輯分別為串行1000次超時(shí)200ms的調(diào)用和串行1000次1ms超時(shí)的調(diào)用（這里僅僅只是為了模擬成功和失敗的兩種場景）；請求入?yún)⑹褂昧艘粋€(gè)800kb的線上業(yè)務(wù)實(shí)體。
這里為了更便于復(fù)現(xiàn)，服務(wù)啟動(dòng)時(shí)啟用了
-Dio.netty.allocator.type=unpooled 使用非Pool池管理
-Dio.netty.leakDetectionLevel=paranoid 啟用Netty堆外內(nèi)存泄漏檢測工具，級別=paranoid
有意思的一幕發(fā)生了
1000次200ms超時(shí)調(diào)用：
1000次1ms超時(shí)調(diào)用：
實(shí)驗(yàn)2直接Netty檢測內(nèi)存泄漏了，問題到此復(fù)現(xiàn)成功。
定位
那么，為什么超時(shí)會(huì)造成堆外內(nèi)存泄漏呢，這里我們沒有別的辦法，只能閱讀公司組件源碼，找找原因了。
首先看下公司服務(wù)端組件Netty相關(guān)的初始化動(dòng)作，它繼承了ChannelInitializer，并在初始化階段追加了自定義的HttpHandler：
HttpHandler繼承了ChannelInboundHandlerAdapter，并且使用了CompositeByteBuf，這里由于涉及到公司內(nèi)部核心組件，因此，只能用偽代碼進(jìn)行展示了，這里我們只截取一些Netty相關(guān)通用代碼邏輯塊：
public class HttpHandler extends ChannelInboundHandlerAdapter {
private HttpRequest req;
private final CompositeByteBuf compositeByteBuf = Unpooled.compositeBuffer(32);
@Override
public void channelRead(ChannelHandlerContext ctx, Object msg) throws Exception {
if (msg instanceof HttpRequest) {
try {
req = (HttpRequest) msg;
context = initReq(ctx, msg, req);
if (!req.decoderResult().isSuccess()) {
WriteUtils.write("請求無效， 解碼失敗", HttpResponseStatus.BAD_REQUEST, context);
return;
}
。。。
} catch (Exception e) {
WriteUtils.write(e.getMessage(), HttpResponseStatus.INTERNAL_SERVER_ERROR, context);
return;
}
}
if (msg instanceof HttpContent) {
HttpContent content = (HttpContent) msg;
ByteBuf bytebuf = content.content();
compositeByteBuf.addComponent(true, bytebuf);
if (msg instanceof LastHttpContent) {
// 校驗(yàn)請求
if (!validRequest(ctx, context)) return;
context.getInvocation().setRequestBody(compositeByteBuf.toString(CharsetUtil.UTF_8));
compositeByteBuf.clear();
compositeByteBuf.removeComponents(0, compositeByteBuf.numComponents());
// 具體業(yè)務(wù)行為傳遞
buildChainHandler().handle(context);
}
}
}
。。。
}
看到這里，我們就必須了解下Netty對于Http協(xié)議的抽象定義了，推薦這篇文章netty對http協(xié)議解析原理解析，這里就簡單提下對于Http的幾種內(nèi)容的包裝：
HttpMethod：主要是對method的封裝，包含method序列化的操作
HttpVersion: 對version的封裝，netty包含1.0和1.1的版本
QueryStringDecoder: 主要是對url進(jìn)行封裝，解析path和url上面的參數(shù)。(Tips：在tomcat中如果提交的post請求是application/x-www-form-urlencoded，則getParameter獲取的是包含url后面和body里面所有的參數(shù)，而在netty中，獲取的僅僅是url上面的參數(shù))
HttpHeaders：包含對header的內(nèi)容進(jìn)行封裝及操作
HttpContent：是對body進(jìn)行封裝，本質(zhì)上就是一個(gè)ByteBuf。如果ByteBuf的長度是固定的，則請求的body過大，可能包含多個(gè)HttpContent，其中最后一個(gè)為LastHttpContent(空的HttpContent),用來說明body的結(jié)束。
HttpRequest：主要包含對Request Line和Header的組合
FullHttpRequest： 主要包含對HttpRequest和httpContent的組合
從生命周期上來講，HttpRequest -> HttpContent ...... -> LastHttpContent，一個(gè)完整的流程。
公司組件的代碼中，是將每個(gè)HttpContent類型的msg都放入CompositeByteBuf，當(dāng)?shù)阶詈笠粋€(gè)LastHttpContent到達(dá)時(shí)，組裝CompositeByteBuf中已經(jīng)寫入的所有HttpContent，然后清理CompositeByteBuf中所有的ByteBuf引用，并進(jìn)行清理（這里的清理也并不是立即執(zhí)行，而是會(huì)等到AbstractReferenceCountedByteBuf中的refCnt下一次變?yōu)?時(shí)觸發(fā)deallocate()），再調(diào)用業(yè)務(wù)方法，直到ChannelHandler結(jié)束被回收，完成整個(gè)生命周期。
那么，如果LastHttpContent沒有到來會(huì)怎么樣呢？
其實(shí)這也是timeout=1的那一輪測試所對應(yīng)的問題了，消息體發(fā)送不完整，這里就會(huì)存在LastHttpContent邏輯塊無法觸達(dá)的情況，也就是CompositeByteBuf所緩存的ByteBuf引用一直被持有，并且未被執(zhí)行手動(dòng)釋放操作，那么一直到ChannelHandler生命周期結(jié)束，堆外所開辟的空間都將一直被占用，內(nèi)存泄漏。
到此，我們似乎找到了一個(gè)可疑的內(nèi)存泄漏點(diǎn)，那么如何證明就是它引起的呢？做法也很簡單。
@Override
public void channelInactive(ChannelHandlerContext ctx) throws Exception {
logger.info("*** channelInactive");
super.channelInactive(ctx);
compositeByteBuf.clear();
compositeByteBuf.removeComponents(0, compositeByteBuf.numComponents());
}
在Inative階段，我們再去手動(dòng)釋放一次CompositeByteBuf，下面來測試一下。
堆外內(nèi)存泄漏問題順利解決。
到此，其實(shí)我們已經(jīng)將問題順利定位，并提交公共組件負(fù)責(zé)團(tuán)隊(duì)進(jìn)行確認(rèn)，并著手修復(fù)了。
那我們再回想下，這個(gè)場景時(shí)線下可以復(fù)現(xiàn)的情況下，我們嘗試通過測試手段進(jìn)行場景模擬，然后定位的，那么如果生產(chǎn)環(huán)境下，我們會(huì)怎么去定位這個(gè)問題呢，下面再聊聊當(dāng)時(shí)生產(chǎn)環(huán)境戰(zhàn)斗的過程，也是異常兇險(xiǎn)啊~~
開始下半場正文
由于是Netty堆外溢出，重新部署服務(wù)時(shí)，筆者保留了一臺線上故障節(jié)點(diǎn)，可供回溯，就從這臺節(jié)點(diǎn)入手。
首先期望可以定位到既然堆外內(nèi)存溢出，那么當(dāng)時(shí)堆外內(nèi)存泄漏的部分到底是什么內(nèi)容呢？
這里我們查看了服務(wù)進(jìn)行的內(nèi)存映射：
jps -m
pmap -pid
163: java -Duser.timezone=GMT+08 -server -Xms8192m -Xmx10240m -XX:NewSize=3072m -XX:MaxNewSize=3072m -XX:MaxDirectMemorySize=1024m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m-XX:+UseContainerSupport -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/xxx/xxx_heapDump.hprof -XX:+UseParNewGC -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1024M -XX:+ExplicitGCInv
0000000000400000 4K r-x-- java
0000000000600000 4K r---- java
0000000000601000 4K rw--- java
00000000016c0000 132K rw--- [ anon ]
0000000560800000 8388608K rw--- [ anon ]
0000000760800000 2097152K ----- [ anon ]
00000007e0800000 6528K rw--- [ anon ]
00000007e0e60000 1042048K ----- [ anon ]
00007f91b8000000 892K rw--- [ anon ]
00007f91b80df000 64644K ----- [ anon ]
00007f91bc000000 132K rw--- [ anon ]
00007f91bc021000 65404K ----- [ anon ]
00007f91c0000000 800K rw--- [ anon ]
00007f91c00c8000 64736K ----- [ anon ]
00007f91c4000000 980K rw--- [ anon ]
00007f91c40f5000 64556K ----- [ anon ]
00007f91c8000000 916K rw--- [ anon ]
00007f91c80e5000 64620K ----- [ anon ]
00007f91cc000000 608K rw--- [ anon ]
00007f91cc098000 64928K ----- [ anon ]
00007f91d0000000 932K rw--- [ anon ]
00007f91d00e9000 64604K ----- [ anon ]
00007f91d4000000 584K rw--- [ anon ]
00007f91d4092000 64952K ----- [ anon ]
00007f91d8000000 756K rw--- [ anon ]
00007f91d80bd000 64780K ----- [ anon ]
00007f91dc000000 1452K rw--- [ anon ]
00007f91dc16b000 64084K ----- [ anon ]
00007f91e0000000 612K rw--- [ anon ]
00007f91e0099000 64924K ----- [ anon ]
能看到不少anon的64M左右的連續(xù)空間，每一組例如892K + 64644K = 65536K 正好是64M，筆者線下也對比了堆外內(nèi)存泄漏前后相關(guān)內(nèi)存塊的變化：
發(fā)現(xiàn)所分配的rw內(nèi)存會(huì)持續(xù)增長，那么這里就準(zhǔn)備查看下這一部分變化的內(nèi)存中到底是哪些內(nèi)容。
這里會(huì)用到gdb調(diào)試工具，如果有c或c++相關(guān)基礎(chǔ)的同學(xué)可以跳過這一部分：
這里附帶一份安裝指令集：
wget http://mirrors.ustc.edu.cn/gnu/gdb/gdb-7.9.1.tar.xz
tar -xf gdb-7.9.1.tar.xz
cd gdb-7.9.1
yum install texinfo
./configure
// 這里可能會(huì)拋異常no termcap library found
// 下載termcap -> https://ftp.gnu.org/gnu/termcap/
mkdir ../termcap
cd ../termcap
wget https://ftp.gnu.org/gnu/termcap/termcap-1.3.1.tar.gz
tar -zxvf termcap-1.3.1.tar.gz
cd termcap-1.3.1
./configure
make
make install
cd ../gdb-7.9.1
make install
gdb -v // 確認(rèn)安裝成功
// 這里如果遇到configure: error: no acceptable C compiler found in $PATH
// 則需要安裝gcc
yum install gcc
N minutes later......
我們終于可以開始使用gdb了，let's do it。
// 我們就上面分析的那一塊連續(xù)的64M內(nèi)存進(jìn)行dump快照，查看具體的內(nèi)容
gdb -p 160
(gdb)dump memory 0x7f91b8000000_0x7f91b80df000.bin 0x7f91b8000000 0x7f91b80df000
(gdb)dump memory 0x7f91b80df000_0x7f91bc000000.bin 0x7f91b80df000 0x7f91bc000000
(gdb)quit
strings 0x7f91b8000000_0x7f91b80df000.bin > 0x7f91b8000000_0x7f91b80df000.log
strings 0x7f91b80df000_0x7f91bc000000.bin > 0x7f91b80df000_0x7f91bc000000.log
less 0x7f91b8000000_0x7f91b80df000.log
終于我們尋根之地，看到了最終的光明圣地，
這不正是我們的請求入?yún)⒄拿?，那我們?G到最后一行看看，
果然，非正常中斷，再看第二個(gè)內(nèi)存塊strings后的文件，發(fā)現(xiàn)內(nèi)容為空，文件大小為0，筆者也在線下模擬內(nèi)存泄漏后進(jìn)行對比，發(fā)現(xiàn)持續(xù)的內(nèi)容也是非正常中斷，對應(yīng)了我們驗(yàn)證的LastHttpContent未到達(dá)，且堆外內(nèi)存未進(jìn)行回收的結(jié)論。
至此，整個(gè)Netty堆外內(nèi)存泄漏的排查定位過程結(jié)束。
總結(jié)
其實(shí)這個(gè)問題存在了很長時(shí)間，至于到近期爆發(fā)，其實(shí)也是源于公司雙中心機(jī)房升級引起的，部分下游服務(wù)異地部署，異地服務(wù)需要走專線，造成異地服務(wù)訪問耗時(shí)加長，堆外內(nèi)存泄漏的問題才會(huì)被放大。
總的來說，這次故障定位的過程很艱辛，當(dāng)然，最終的結(jié)果也是很棒的。
筆者在此也算沉淀出一些方法論，面對像OOM這樣的問題時(shí)，首先要先明確，是哪一種OOM，有堆內(nèi)、堆外、方法區(qū)等等，也有啟動(dòng)時(shí)階段或者運(yùn)行時(shí)階段，首先要明確當(dāng)下自己的場景，因?yàn)椴粫?huì)有人比你更了解你的代碼，當(dāng)你堅(jiān)定問題方向后，也要義無反顧的堅(jiān)持下去，總會(huì)有自己不在行的領(lǐng)域，只要肯多付出時(shí)間、精力，總會(huì)有提高和回報(bào)。
參考文獻(xiàn)
生活不易、各自努力
前路漫漫，互勉同行
