前言
JVM的堆外內(nèi)存泄露的定位一直是個(gè)比較棘手的問(wèn)題。此次的Bug查找從堆內(nèi)內(nèi)存的泄露反推出堆外內(nèi)存，同時(shí)對(duì)物理內(nèi)存的使用做了定量的分析，從而實(shí)錘了Bug的源頭。筆者將此Bug分析的過(guò)程寫(xiě)成博客，以饗讀者。
由于物理內(nèi)存定量分析部分用到了linux kernel虛擬內(nèi)存管理的知識(shí)，讀者如果有興趣了解請(qǐng)看ulk3(《深入理解linux內(nèi)核第三版》)
內(nèi)存泄露Bug現(xiàn)場(chǎng)
一個(gè)線上穩(wěn)定運(yùn)行了三年的系統(tǒng)，從物理機(jī)遷移到docker環(huán)境后，運(yùn)行了一段時(shí)間，突然被監(jiān)控系統(tǒng)發(fā)出了某些實(shí)例不可用的報(bào)警。所幸有負(fù)載均衡，可以自動(dòng)下掉節(jié)點(diǎn)，如下圖所示:
登錄到對(duì)應(yīng)機(jī)器上后，發(fā)現(xiàn)由于內(nèi)存占用太大，觸發(fā)OOM，然后被linux系統(tǒng)本身給kill了。
應(yīng)急措施
緊急在出問(wèn)題的實(shí)例上再次啟動(dòng)應(yīng)用，啟動(dòng)后，內(nèi)存占用正常，一切Okay。
奇怪現(xiàn)象
當(dāng)前設(shè)置的最大堆內(nèi)存是1792M，如下所示:
-Xmx1792m -Xms1792m -Xmn900m -XX:PermSi
ze=256m -XX:MaxPermSize=256m -server -Xss512k
查看操作系統(tǒng)層面的監(jiān)控，發(fā)現(xiàn)內(nèi)存占用情況如下圖所示:
上圖藍(lán)色的線表示總的內(nèi)存使用量，發(fā)現(xiàn)一直漲到了4G后，超出了系統(tǒng)限制。
很明顯，有堆外內(nèi)存泄露了。
查找線索
gc日志
一般出現(xiàn)內(nèi)存泄露，筆者立馬想到的就是查看當(dāng)時(shí)的gc日志。
本身應(yīng)用所采用框架會(huì)定時(shí)打印出對(duì)應(yīng)的gc日志，遂查看，發(fā)現(xiàn)gc日志一切正常。對(duì)應(yīng)日志如下:
查看了當(dāng)天的所有g(shù)c日志，發(fā)現(xiàn)內(nèi)存始終會(huì)回落到170M左右，并無(wú)明顯的增加。要知道JVM進(jìn)程本身占用的內(nèi)存可是接近4G(加上其它進(jìn)程,例如日志進(jìn)程就已經(jīng)到4G了)，進(jìn)一步確認(rèn)是堆外內(nèi)存導(dǎo)致。
排查代碼
打開(kāi)線上服務(wù)對(duì)應(yīng)對(duì)應(yīng)代碼，查了一圈，發(fā)現(xiàn)沒(méi)有任何地方顯式利用堆外內(nèi)存，其沒(méi)有依賴任何額外的native方法。關(guān)于網(wǎng)絡(luò)IO的代碼也是托管給Tomcat，很明顯，作為一個(gè)全世界廣泛流行的Web服務(wù)器，Tomcat不大可能有堆外內(nèi)存泄露。
進(jìn)一步查找
由于在代碼層面沒(méi)有發(fā)現(xiàn)堆外內(nèi)存的痕跡，那就繼續(xù)找些其它的信息，希望能發(fā)現(xiàn)蛛絲馬跡。
Dump出JVM的Heap堆
由于線上出問(wèn)題的Server已經(jīng)被kill，還好有其它幾臺(tái)，登上去發(fā)現(xiàn)它們也 占用了很大的堆外內(nèi)存，只是還沒(méi)有到觸發(fā)OOM的臨界點(diǎn)而已。于是就趕緊用jmap dump了兩臺(tái)機(jī)器中應(yīng)用JVM的堆情況，這兩臺(tái)留做現(xiàn)場(chǎng)保留不動(dòng)，然后將其它機(jī)器迅速重啟，以防同時(shí)被OOM導(dǎo)致服務(wù)不可用。
使用如下命令dump:
jmap -dump:format=b，file=heap.bin [pid]
使用MAT分析Heap文件
挑了一個(gè)heap文件進(jìn)行分析，堆的使用情況如下圖所示:
一共用了200多M，和之前gc文件打印出來(lái)的170M相差不大，遠(yuǎn)遠(yuǎn)沒(méi)有到4G的程度。
不得不說(shuō)MAT是個(gè)非常好用的工具，它可以提示你可能內(nèi)存泄露的點(diǎn):
這個(gè)cachedBnsClient類(lèi)有12452個(gè)實(shí)例，占用了整個(gè)堆的61.92%。
查看了另一個(gè)heap文件，發(fā)現(xiàn)也是同樣的情況。這個(gè)地方肯定有內(nèi)存泄露，但是也占用了130多M，和4G相差甚遠(yuǎn)。
查看對(duì)應(yīng)的代碼
系統(tǒng)中大部分對(duì)于CachedBnsClient的調(diào)用，都是通過(guò)注解Autowired的，這部分實(shí)例數(shù)很少。
唯一頻繁產(chǎn)生此類(lèi)實(shí)例的代碼如下所示:
@Override
public void fun() {
BnsClient bnsClient = new CachedBnsClient();
// do something
return ;
}
此CachedBnsClient僅僅在方法體內(nèi)使用，并沒(méi)有逃逸到外面，再看此類(lèi)本身
public class CachedBnsClient {
private ConcurrentHashMap<String， List<String>> authCache = new ConcurrentHashMap<String， List<String>>();
private ConcurrentHashMap<String， List<URI>> validUriCache = new ConcurrentHashMap<String， List<URI>>();
private ConcurrentHashMap<String， List<URI>> uriCache = new ConcurrentHashMap<String， List<URI>>();
......
}
沒(méi)有任何static變量，同時(shí)也沒(méi)有往任何全局變量注冊(cè)自身。換言之，在類(lèi)的成員(Member)中，是不可能出現(xiàn)內(nèi)存泄露的。
當(dāng)時(shí)只粗略的過(guò)了一過(guò)成員變量，回過(guò)頭來(lái)細(xì)想，還是漏了不少地方的。
更多信息
由于代碼排查下來(lái)，感覺(jué)這塊不應(yīng)該出現(xiàn)內(nèi)存泄露(但是事實(shí)確是如此的打臉)。這個(gè)類(lèi)也沒(méi)有顯式用到堆外內(nèi)存，而且只占了130M，和4G比起來(lái)微不足道，還是先去追查主要矛盾再說(shuō)。
使用jstack dump線程信息
現(xiàn)場(chǎng)信息越多，越能找出蛛絲馬跡。先用jstack把線程信息dump下來(lái)看下。
這一看，立馬發(fā)現(xiàn)了不同，除了正常的IO線程以及框架本身的一些守護(hù)線程外，竟然還多出來(lái)了12563多個(gè)線程。
"Thread-5" daemon prio=10 tid=0x00007fb79426e000 nid=0x7346 waiting on condition [0x00007fb7b5678000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.xxxxx.CachedBnsClient$1.run(CachedBnsClient.java:62)
而且這些正好是運(yùn)行再CachedBnsClient的run方法上面！這些特定線程的數(shù)量正好是12452個(gè)，和cachedBnsClient數(shù)量一致!
再次check對(duì)應(yīng)代碼
原來(lái)剛才看CachedBnsClient代碼的時(shí)候遺漏掉了一個(gè)關(guān)鍵的點(diǎn)!
public CachedBnsClient(BnsClient client) {
super();
this.backendClient = client;
new Thread() {
@Override
public void run() {
for (; ; ) {
refreshCache();
try {
Thread.sleep(60 * 1000);
} catch (InterruptedException e) {
logger.error("出錯(cuò)"， e);
}
}
}
......
}.start();
}
這段代碼是CachedBnsClient的構(gòu)造函數(shù)，其在里面創(chuàng)建了一個(gè)無(wú)限循環(huán)的線程，每隔60s啟動(dòng)一次刷新一下里面的緩存!
找到關(guān)鍵點(diǎn)
在看到12452個(gè)等待在CachedBnsClient.run的業(yè)務(wù)的一瞬間筆者就意識(shí)到，肯定是這邊的線程導(dǎo)致對(duì)外內(nèi)存泄露了。下面就是根據(jù)線程大小計(jì)算其泄露內(nèi)存量是不是確實(shí)能夠引起OOM了。
發(fā)現(xiàn)內(nèi)存計(jì)算對(duì)不上
由于我們這邊設(shè)置的Xss是512K，即一個(gè)線程棧大小是512K，而由于線程共享其它MM單元(線程本地內(nèi)存是是現(xiàn)在線程棧上的)，所以實(shí)際線程堆外內(nèi)存占用數(shù)量也是512K。進(jìn)行如下計(jì)算:
12563 * 512K = 6331M = 6.3G
整個(gè)環(huán)境一共4G，加上JVM堆內(nèi)存1.8G(1792M)，已經(jīng)明顯的超過(guò)了4G。
(6.3G + 1.8G)=8.1G > 4G
如果按照此計(jì)算，應(yīng)用應(yīng)用早就被OOM了。
怎么回事呢？
為了解決這個(gè)問(wèn)題，筆者又思考了好久。如下所示:
Java線程底層實(shí)現(xiàn)
JVM的線程在linux上底層是調(diào)用NPTL(Native Posix Thread Library)來(lái)創(chuàng)建的，一個(gè)JVM線程就對(duì)應(yīng)linux的lwp(輕量級(jí)進(jìn)程，也是進(jìn)程，只不過(guò)共享了mm_struct，用來(lái)實(shí)現(xiàn)線程)，一個(gè)thread.start就相當(dāng)于do_fork了一把。
其中，我們?cè)贘VM啟動(dòng)時(shí)候設(shè)置了-Xss=512K(即線程棧大小)，這512K中然后有8K是必須使用的，這8K是由進(jìn)程的內(nèi)核棧和thread_info公用的，放在兩塊連續(xù)的物理頁(yè)框上。如下圖所示:
眾所周知，一個(gè)進(jìn)程(包括lwp)包括內(nèi)核棧和用戶棧，內(nèi)核棧+thread_info用了8K，那么用戶態(tài)的?？捎脙?nèi)存就是:
512K-8K=504K
如下圖所示:
Linux實(shí)際物理內(nèi)存映射
事實(shí)上linux對(duì)物理內(nèi)存的使用非常的摳門(mén)，一開(kāi)始只是分配了虛擬內(nèi)存的線性區(qū)，并沒(méi)有分配實(shí)際的物理內(nèi)存，只有推到最后使用的時(shí)候才分配具體的物理內(nèi)存，即所謂的請(qǐng)求調(diào)頁(yè)。如下圖所示:
查看smaps進(jìn)程內(nèi)存使用信息
使用如下命令，查看
cat /proc/[pid]/smaps > smaps.txt
實(shí)際物理內(nèi)存使用信息，如下所示:
7fa69a6d1000-7fa69a74f000 rwxp 00000000 00:00 0
Size: 504 kB
Rss: 92 kB
Pss: 92 kB
Shared_Clean: 0 kB
Shared_Dirty: 0 kB
Private_Clean: 0 kB
Private_Dirty: 92 kB
Referenced: 92 kB
Anonymous: 92 kB
AnonHugePages: 0 kB
Swap: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
7fa69a7d3000-7fa69a851000 rwxp 00000000 00:00 0
Size: 504 kB
Rss: 152 kB
Pss: 152 kB
Shared_Clean: 0 kB
Shared_Dirty: 0 kB
Private_Clean: 0 kB
Private_Dirty: 152 kB
Referenced: 152 kB
Anonymous: 152 kB
AnonHugePages: 0 kB
Swap: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
搜索下504KB，正好是12563個(gè)，對(duì)了12563個(gè)線程，其中Rss表示實(shí)際物理內(nèi)存(含共享庫(kù))92KB，Pss表示實(shí)際物理內(nèi)存(按比例共享庫(kù))92KB(由于沒(méi)有共享庫(kù)，所以Rss==Pss)，以第一個(gè)7fa69a6d1000-7fa69a74f000線性區(qū)來(lái)看，其映射了92KB的空間，第二個(gè)映射了152KB的空間。如下圖所示:
挑出符合條件（即size是504K）的幾十組看了下，基本都在92K-152K之間，再加上內(nèi)核棧8K
(92+152)/2+8K=130K，由于是估算，取整為128K，即反映此應(yīng)用平均線程棧大小。
注意，實(shí)際內(nèi)存有波動(dòng)的原因是由于環(huán)境不同，從而走了不同的分支，導(dǎo)致棧上的增長(zhǎng)不同。
重新進(jìn)行內(nèi)存計(jì)算
JVM一開(kāi)始申請(qǐng)了
-Xmx1792m -Xms1792m
即1.8G的堆內(nèi)內(nèi)存，這里是即時(shí)分配，一開(kāi)始就用物理頁(yè)框填充。
12563個(gè)線程，每個(gè)線程棧平均大小128K，即:
128K * 12563=1570M=1.5G的對(duì)外內(nèi)存
取個(gè)整數(shù)128K，就能反映出平均水平。再拿這個(gè)128K * 12563 =1570M = 1.5G，加上JVM的1.8G，就已經(jīng)達(dá)到了3.3G，再加上kernel和日志傳輸進(jìn)程等使用的內(nèi)存數(shù)量，確實(shí)已經(jīng)接近了4G，這樣內(nèi)存就對(duì)應(yīng)上了！(注:用于定量?jī)?nèi)存計(jì)算的環(huán)境是一臺(tái)內(nèi)存用量將近4G，但還沒(méi)OOM的機(jī)器)
為什么在物理機(jī)上沒(méi)有應(yīng)用Down機(jī)
筆者登錄了原來(lái)物理機(jī)，應(yīng)用還在跑，發(fā)現(xiàn)其同樣有堆外內(nèi)存泄露的現(xiàn)象，其物理內(nèi)存使用已經(jīng)達(dá)到了5個(gè)多G!幸好物理機(jī)內(nèi)存很大，而且此應(yīng)用發(fā)布還比較頻繁，所以沒(méi)有被OOM。
Dump了物理機(jī)上應(yīng)用的線程，
一共有28737個(gè)線程，其中28626個(gè)線程等待在CachedBnsClient上。
同樣用smaps查看進(jìn)程實(shí)際內(nèi)存信息，其平均大小依舊為
128K，因?yàn)槭峭粦?yīng)用的原因
繼續(xù)進(jìn)行物理內(nèi)存計(jì)算
1.8+(28737 * 128k)/1024K =(3.6+1.8)=5.4G
進(jìn)一步驗(yàn)證了我們的推理。
這么多線程應(yīng)用為什么沒(méi)有卡頓
因?yàn)榛舅械木€程都睡眠在
Thread.sleep(60 * 1000);//一次睡眠60s
上。所以僅僅占用了內(nèi)存，實(shí)際占用的CPU時(shí)間很少。
總結(jié)
查找Bug的時(shí)候，現(xiàn)場(chǎng)信息越多越好，同時(shí)定位Bug必須要有實(shí)質(zhì)性的證據(jù)。例如內(nèi)存泄露就要用你推測(cè)出的模型進(jìn)行定量分析。在定量和實(shí)際對(duì)不上的時(shí)候，深挖下去，你會(huì)發(fā)現(xiàn)不一樣的風(fēng)景!
看完三件事??
如果你覺(jué)得這篇內(nèi)容對(duì)你還蠻有幫助，我想邀請(qǐng)你幫我三個(gè)小忙：
點(diǎn)贊，轉(zhuǎn)發(fā)，有你們的 『點(diǎn)贊和評(píng)論』，才是我創(chuàng)造的動(dòng)力。
關(guān)注公眾號(hào) 『 java爛豬皮 』，不定期分享原創(chuàng)知識(shí)。
同時(shí)可以期待后續(xù)文章ing??
