記一次JVM堆外內(nèi)存泄露Bug的查找

前言

JVM的堆外內(nèi)存泄露的定位一直是個比較棘手的問題安拟。此次的Bug查找從堆內(nèi)內(nèi)存的泄露反推出堆外內(nèi)存癞志，同時對物理內(nèi)存的使用做了定量的分析锣笨，從而實錘了Bug的源頭驻啤。筆者將此Bug分析的過程寫成博客菲驴，以饗讀者。
由于物理內(nèi)存定量分析部分用到了linux kernel虛擬內(nèi)存管理的知識骑冗，讀者如果有興趣了解請看ulk3(《深入理解linux內(nèi)核第三版》)

內(nèi)存泄露Bug現(xiàn)場

一個線上穩(wěn)定運行了三年的系統(tǒng)赊瞬，從物理機遷移到docker環(huán)境后，運行了一段時間贼涩，突然被監(jiān)控系統(tǒng)發(fā)出了某些實例不可用的報警巧涧。所幸有負(fù)載均衡，可以自動下掉節(jié)點遥倦，如下圖所示:

登錄到對應(yīng)機器上后谤绳，發(fā)現(xiàn)由于內(nèi)存占用太大，觸發(fā)OOM，然后被linux系統(tǒng)本身給kill了缩筛。

應(yīng)急措施

緊急在出問題的實例上再次啟動應(yī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)存占用情況如下圖所示:

上圖藍色的線表示總的內(nèi)存使用量胎撤，發(fā)現(xiàn)一直漲到了4G后，超出了系統(tǒng)限制豪硅。
很明顯哩照，有堆外內(nèi)存泄露了。

查找線索

gc日志

一般出現(xiàn)內(nèi)存泄露懒浮，筆者立馬想到的就是查看當(dāng)時的gc日志飘弧。
本身應(yīng)用所采用框架會定時打印出對應(yīng)的gc日志，遂查看砚著，發(fā)現(xiàn)gc日志一切正常次伶。對應(yīng)日志如下:

查看了當(dāng)天的所有g(shù)c日志，發(fā)現(xiàn)內(nèi)存始終會回落到170M左右稽穆，并無明顯的增加冠王。要知道JVM進程本身占用的內(nèi)存可是接近4G(加上其它進程,例如日志進程就已經(jīng)到4G了)，進一步確認(rèn)是堆外內(nèi)存導(dǎo)致舌镶。

排查代碼

打開線上服務(wù)對應(yīng)對應(yīng)代碼柱彻，查了一圈，發(fā)現(xiàn)沒有任何地方顯式利用堆外內(nèi)存餐胀，其沒有依賴任何額外的native方法哟楷。關(guān)于網(wǎng)絡(luò)IO的代碼也是托管給Tomcat，很明顯否灾，作為一個全世界廣泛流行的Web服務(wù)器卖擅，Tomcat不大可能有堆外內(nèi)存泄露。

進一步查找

由于在代碼層面沒有發(fā)現(xiàn)堆外內(nèi)存的痕跡墨技，那就繼續(xù)找些其它的信息惩阶，希望能發(fā)現(xiàn)蛛絲馬跡。

Dump出JVM的Heap堆

由于線上出問題的Server已經(jīng)被kill扣汪，還好有其它幾臺断楷，登上去發(fā)現(xiàn)它們也 占用了很大的堆外內(nèi)存，只是還沒有到觸發(fā)OOM的臨界點而已崭别。于是就趕緊用jmap dump了兩臺機器中應(yīng)用JVM的堆情況冬筒，這兩臺留做現(xiàn)場保留不動统刮，然后將其它機器迅速重啟，以防同時被OOM導(dǎo)致服務(wù)不可用账千。
使用如下命令dump:

jmap -dump:format=b侥蒙，file=heap.bin [pid]

使用MAT分析Heap文件

挑了一個heap文件進行分析，堆的使用情況如下圖所示:

一共用了200多M匀奏，和之前gc文件打印出來的170M相差不大鞭衩，遠遠沒有到4G的程度。
不得不說MAT是個非常好用的工具娃善，它可以提示你可能內(nèi)存泄露的點:

這個cachedBnsClient類有12452個實例论衍，占用了整個堆的61.92%。
查看了另一個heap文件坯台，發(fā)現(xiàn)也是同樣的情況。這個地方肯定有內(nèi)存泄露瘫寝，但是也占用了130多M蜒蕾，和4G相差甚遠。

查看對應(yīng)的代碼

系統(tǒng)中大部分對于CachedBnsClient的調(diào)用焕阿，都是通過注解Autowired的咪啡，這部分實例數(shù)很少。
唯一頻繁產(chǎn)生此類實例的代碼如下所示:

@Override
    public void fun() {
            BnsClient bnsClient = new CachedBnsClient();
          // do something
            return  ;
    }

此CachedBnsClient僅僅在方法體內(nè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>>();
    ......
}

沒有任何static變量，同時也沒有往任何全局變量注冊自身汁蝶。換言之渐扮，在類的成員(Member)中论悴，是不可能出現(xiàn)內(nèi)存泄露的掖棉。
當(dāng)時只粗略的過了一過成員變量，回過頭來細(xì)想膀估，還是漏了不少地方的幔亥。

更多信息

由于代碼排查下來，感覺這塊不應(yīng)該出現(xiàn)內(nèi)存泄露(但是事實確是如此的打臉)察纯。這個類也沒有顯式用到堆外內(nèi)存帕棉，而且只占了130M针肥，和4G比起來微不足道，還是先去追查主要矛盾再說香伴。

使用jstack dump線程信息

現(xiàn)場信息越多慰枕，越能找出蛛絲馬跡。先用jstack把線程信息dump下來看下即纲。
這一看具帮，立馬發(fā)現(xiàn)了不同，除了正常的IO線程以及框架本身的一些守護線程外低斋，竟然還多出來了12563多個線程蜂厅。

"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)

而且這些正好是運行再CachedBnsClient的run方法上面！這些特定線程的數(shù)量正好是12452個膊畴，和cachedBnsClient數(shù)量一致!

再次check對應(yīng)代碼

原來剛才看CachedBnsClient代碼的時候遺漏掉了一個關(guā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("出錯"掘猿， e);
                    }
                }
            }
            ......
        }.start();
    }

這段代碼是CachedBnsClient的構(gòu)造函數(shù)，其在里面創(chuàng)建了一個無限循環(huán)的線程唇跨，每隔60s啟動一次刷新一下里面的緩存!

找到關(guān)鍵點

在看到12452個等待在CachedBnsClient.run的業(yè)務(wù)的一瞬間筆者就意識到稠通，肯定是這邊的線程導(dǎo)致對外內(nèi)存泄露了。下面就是根據(jù)線程大小計算其泄露內(nèi)存量是不是確實能夠引起OOM了买猖。

發(fā)現(xiàn)內(nèi)存計算對不上

由于我們這邊設(shè)置的Xss是512K采记，即一個線程棧大小是512K，而由于線程共享其它MM單元(線程本地內(nèi)存是是現(xiàn)在線程棧上的)政勃，所以實際線程堆外內(nèi)存占用數(shù)量也是512K唧龄。進行如下計算:

12563 * 512K = 6331M = 6.3G

整個環(huán)境一共4G，加上JVM堆內(nèi)存1.8G(1792M)奸远，已經(jīng)明顯的超過了4G既棺。

(6.3G + 1.8G)=8.1G > 4G

如果按照此計算，應(yīng)用應(yīng)用早就被OOM了懒叛。

怎么回事呢丸冕？

為了解決這個問題，筆者又思考了好久薛窥。如下所示:

Java線程底層實現(xiàn)

JVM的線程在linux上底層是調(diào)用NPTL(Native Posix Thread Library)來創(chuàng)建的胖烛，一個JVM線程就對應(yīng)linux的lwp(輕量級進程，也是進程诅迷，只不過共享了mm_struct佩番，用來實現(xiàn)線程)，一個thread.start就相當(dāng)于do_fork了一把罢杉。
其中趟畏，我們在JVM啟動時候設(shè)置了-Xss=512K(即線程棧大小)，這512K中然后有8K是必須使用的滩租，這8K是由進程的內(nèi)核棧和thread_info公用的赋秀，放在兩塊連續(xù)的物理頁框上利朵。如下圖所示:

眾所周知，一個進程(包括lwp)包括內(nèi)核棧和用戶棧猎莲，內(nèi)核棧+thread_info用了8K绍弟，那么用戶態(tài)的棧可用內(nèi)存就是:

512K-8K=504K

如下圖所示:

Linux實際物理內(nèi)存映射

事實上linux對物理內(nèi)存的使用非常的摳門著洼，一開始只是分配了虛擬內(nèi)存的線性區(qū)晌柬，并沒有分配實際的物理內(nèi)存，只有推到最后使用的時候才分配具體的物理內(nèi)存郭脂，即所謂的請求調(diào)頁年碘。如下圖所示:

查看smaps進程內(nèi)存使用信息

使用如下命令，查看

cat /proc/[pid]/smaps > smaps.txt

實際物理內(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個，對了12563個線程莹弊，其中Rss表示實際物理內(nèi)存(含共享庫)92KB涤久，Pss表示實際物理內(nèi)存(按比例共享庫)92KB(由于沒有共享庫，所以Rss==Pss)忍弛，以第一個7fa69a6d1000-7fa69a74f000線性區(qū)來看响迂，其映射了92KB的空間，第二個映射了152KB的空間细疚。如下圖所示:

挑出符合條件（即size是504K）的幾十組看了下蔗彤，基本都在92K-152K之間，再加上內(nèi)核棧8K

(92+152)/2+8K=130K疯兼，由于是估算然遏，取整為128K，即反映此應(yīng)用平均線程棧大小吧彪。

注意待侵，實際內(nèi)存有波動的原因是由于環(huán)境不同，從而走了不同的分支姨裸，導(dǎo)致棧上的增長不同秧倾。

重新進行內(nèi)存計算

JVM一開始申請了

-Xmx1792m -Xms1792m

即1.8G的堆內(nèi)內(nèi)存，這里是即時分配傀缩，一開始就用物理頁框填充那先。
12563個線程，每個線程棧平均大小128K扑毡，即:

128K * 12563=1570M=1.5G的對外內(nèi)存

取個整數(shù)128K胃榕，就能反映出平均水平盛险。再拿這個128K * 12563 =1570M = 1.5G瞄摊，加上JVM的1.8G勋又，就已經(jīng)達到了3.3G，再加上kernel和日志傳輸進程等使用的內(nèi)存數(shù)量换帜，確實已經(jīng)接近了4G楔壤，這樣內(nèi)存就對應(yīng)上了！(注:用于定量內(nèi)存計算的環(huán)境是一臺內(nèi)存用量將近4G惯驼，但還沒OOM的機器)

為什么在物理機上沒有應(yīng)用Down機

筆者登錄了原來物理機蹲嚣，應(yīng)用還在跑，發(fā)現(xiàn)其同樣有堆外內(nèi)存泄露的現(xiàn)象祟牲，其物理內(nèi)存使用已經(jīng)達到了5個多G!幸好物理機內(nèi)存很大隙畜，而且此應(yīng)用發(fā)布還比較頻繁，所以沒有被OOM说贝。
Dump了物理機上應(yīng)用的線程议惰，

一共有28737個線程，其中28626個線程等待在CachedBnsClient上乡恕。

同樣用smaps查看進程實際內(nèi)存信息言询，其平均大小依舊為

128K，因為是同一應(yīng)用的原因

繼續(xù)進行物理內(nèi)存計算

1.8+(28737 * 128k)/1024K =(3.6+1.8)=5.4G

進一步驗證了我們的推理傲宜。

這么多線程應(yīng)用為什么沒有卡頓

因為基本所有的線程都睡眠在

 Thread.sleep(60 * 1000);//一次睡眠60s

上运杭。所以僅僅占用了內(nèi)存，實際占用的CPU時間很少函卒。

總結(jié)

查找Bug的時候辆憔，現(xiàn)場信息越多越好，同時定位Bug必須要有實質(zhì)性的證據(jù)报嵌。例如內(nèi)存泄露就要用你推測出的模型進行定量分析躁愿。在定量和實際對不上的時候，深挖下去沪蓬，你會發(fā)現(xiàn)不一樣的風(fēng)景!

看完三件事??

如果你覺得這篇內(nèi)容對你還蠻有幫助彤钟，我想邀請你幫我三個小忙：

點贊，轉(zhuǎn)發(fā)跷叉，有你們的 『點贊和評論』逸雹，才是我創(chuàng)造的動力。

關(guān)注公眾號 『 java爛豬皮 』云挟，不定期分享原創(chuàng)知識梆砸。

同時可以期待后續(xù)文章ing??

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
  • 人面猴
    序言：七十年代末，一起剝皮案震驚了整個濱河市园欣，隨后出現(xiàn)的幾起案子帖世，更是在濱河造成了極大的恐慌，老刑警劉巖沸枯，帶你破解...
    沈念sama閱讀 218,546評論 6贊 507
  • 死咒
    序言：濱河連續(xù)發(fā)生了三起死亡事件日矫，死亡現(xiàn)場離奇詭異赂弓，居然都是意外死亡，警方通過查閱死者的電腦和手機哪轿，發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 93,224評論 3贊 395
  • 救了他兩次的神仙讓他今天三更去死
    文/潘曉璐 我一進店門盈魁，熙熙樓的掌柜王于貴愁眉苦臉地迎上來，“玉大人窃诉，你說我怎么就攤上這事杨耙。” “怎么了飘痛？”我有些...
    開封第一講書人閱讀 164,911評論 0贊 354
  • 道士緝兇錄：失蹤的賣姜人
    文/不壞的土叔 我叫張陵珊膜，是天一觀的道長。 經(jīng)常有香客問我宣脉，道長辅搬，這世上最難降的妖魔是什么？ 我笑而不...
    開封第一講書人閱讀 58,737評論 1贊 294
  • ?港島之戀（遺憾婚禮）
    正文 為了忘掉前任脖旱，我火速辦了婚禮堪遂，結(jié)果婚禮上，老公的妹妹穿的比我還像新娘萌庆。我一直安慰自己溶褪，他們只是感情好，可當(dāng)我...
    茶點故事閱讀 67,753評論 6贊 392
  • 惡毒庶女頂嫁案：這布局不是一般人想出來的
    文/花漫 我一把揭開白布践险。 她就那樣靜靜地躺著猿妈，像睡著了一般。 火紅的嫁衣襯著肌膚如雪巍虫。 梳的紋絲不亂的頭發(fā)上彭则，一...
    開封第一講書人閱讀 51,598評論 1贊 305
  • 城市分裂傳說
    那天，我揣著相機與錄音占遥，去河邊找鬼俯抖。 笑死，一個胖子當(dāng)著我的面吹牛瓦胎，可吹牛的內(nèi)容都是我干的芬萍。 我是一名探鬼主播，決...
    沈念sama閱讀 40,338評論 3贊 418
  • 雙鴛鴦連環(huán)套：你想象不到人心有多黑
    文/蒼蘭香墨 我猛地睜開眼搔啊，長吁一口氣：“原來是場噩夢啊……” “哼柬祠！你這毒婦竟也來了？” 一聲冷哼從身側(cè)響起负芋，我...
    開封第一講書人閱讀 39,249評論 0贊 276
  • 萬榮殺人案實錄
    序言：老撾萬榮一對情侶失蹤漫蛔，失蹤者是張志新（化名）和其女友劉穎，沒想到半個月后，有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體莽龟，經(jīng)...
    沈念sama閱讀 45,696評論 1贊 314
  • ?護林員之死
    正文 獨居荒郊野嶺守林人離奇死亡蠕嫁，尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點故事閱讀 37,888評論 3贊 336
  • ?白月光啟示錄
    正文 我和宋清朗相戀三年，在試婚紗的時候發(fā)現(xiàn)自己被綠了轧房。 大學(xué)時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片拌阴。...
    茶點故事閱讀 40,013評論 1贊 348
  • 活死人
    序言：一個原本活蹦亂跳的男人離奇死亡绍绘，死狀恐怖奶镶，靈堂內(nèi)的尸體忽然破棺而出，到底是詐尸還是另有隱情陪拘，我是刑警寧澤厂镇，帶...
    沈念sama閱讀 35,731評論 5贊 346
  • ?日本核電站爆炸內(nèi)幕
    正文 年R本政府宣布，位于F島的核電站左刽，受9級特大地震影響捺信，放射性物質(zhì)發(fā)生泄漏。R本人自食惡果不足惜欠痴，卻給世界環(huán)境...
    茶點故事閱讀 41,348評論 3贊 330
  • 男人毒藥：我在死后第九天來索命
    文/蒙蒙 一迄靠、第九天 我趴在偏房一處隱蔽的房頂上張望。 院中可真熱鬧喇辽，春花似錦掌挚、人聲如沸。這莊子的主人今日做“春日...
    開封第一講書人閱讀 31,929評論 0贊 22
  • 一樁弒父案吠式，背后竟有這般陰謀
    文/蒼蘭香墨 我抬頭看了看天上的太陽。三九已至抽米，卻和暖如春特占，著一層夾襖步出監(jiān)牢的瞬間，已是汗流浹背云茸。 一陣腳步聲響...
    開封第一講書人閱讀 33,048評論 1贊 270
  • 情欲美人皮
    我被黑心中介騙來泰國打工是目， 沒想到剛下飛機就差點兒被人妖公主榨干…… 1. 我叫王不留，地道東北人胖笛。 一個月前我還...
    沈念sama閱讀 48,203評論 3贊 370
  • 代替公主和親
    正文 我出身青樓长踊，卻偏偏與公主長得像萍倡，于是被迫代替她去往敵國和親。 傳聞我的和親對象是個殘疾皇子阱佛，可洞房花燭夜當(dāng)晚...
    茶點故事閱讀 44,960評論 2贊 355