記一次JVM堆外內存泄露Bug的查找

前言

JVM的堆外內存泄露的定位一直是個比較棘手的問題。這次的Bug查找從堆內內存的泄露反推出堆外內存，同時對物理內存的使用作了定量的分析，從而實錘了Bug的源頭。筆者將此Bug分析的過程寫成博客，以饗讀者。

因爲物理內存定量分析部分用到了linux kernel虛擬內存管理的知識，讀者若是有興趣瞭解請看ulk3(《深刻理解linux內核第三版》)

內存泄露Bug現場

一個線上穩定運行了三年的系統，從物理機遷移到docker環境後，運行了一段時間，忽然被監控系統發出了某些實例不可用的報警。所幸有負載均衡，能夠自動下掉節點，以下圖所示:

登陸到對應機器上後，發現因爲內存佔用太大，觸發OOM，而後被linux系統自己給kill了。

應急措施

緊急在出問題的實例上再次啓動應用，啓動後，內存佔用正常，一切Okay。

奇怪現象

當前設置的最大堆內存是1792M，以下所示:

-Xmx1792m -Xms1792m -Xmn900m -XX:PermSi
ze=256m -XX:MaxPermSize=256m -server -Xss512k

查看操做系統層面的監控，發現內存佔用狀況以下圖所示:

上圖藍色的線表示總的內存使用量，發現一直漲到了4G後，超出了系統限制。

很明顯，有堆外內存泄露了。

查找線索

gc日誌

通常出現內存泄露，筆者立馬想到的就是查看當時的gc日誌。

自己應用所採用框架會定時打印出對應的gc日誌，遂查看，發現gc日誌一切正常。對應日誌以下:

查看了當天的全部gc日誌，發現內存始終會回落到170M左右，並沒有明顯的增長。要知道JVM進程自己佔用的內存但是接近4G(加上其它進程,例如日誌進程就已經到4G了)，進一步確認是堆外內存致使。

排查代碼

打開線上服務對應對應代碼，查了一圈，發現沒有任何地方顯式利用堆外內存，其沒有依賴任何額外的native方法。關於網絡IO的代碼也是託管給Tomcat，很明顯，做爲一個全世界普遍流行的Web服務器，Tomcat不大可能有堆外內存泄露。

進一步查找
因爲在代碼層面沒有發現堆外內存的痕跡，那就繼續找些其它的信息，但願能發現蛛絲馬跡。

Dump出JVM的Heap堆

因爲線上出問題的Server已經被kill，還好有其它幾臺，登上去發現它們也 佔用了很大的堆外內存，只是尚未到觸發OOM的臨界點而已。因而就趕忙用jmap dump了兩臺機器中應用JVM的堆狀況，這兩臺留作現場保留不動，而後將其它機器迅速重啓，以防同時被OOM致使服務不可用。

使用以下命令dump:

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

使用MAT分析Heap文件

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

一共用了200多M，和以前gc文件打印出來的170M相差不大，遠遠沒有到4G的程度。

不得不說MAT是個很是好用的工具，它能夠提示你可能內存泄露的點:

這個cachedBnsClient類有12452個實例，佔用了整個堆的61.92%。

查看了另外一個heap文件，發現也是一樣的狀況。這個地方確定有內存泄露，可是也佔用了130多M，和4G相差甚遠。

查看對應的代碼

系統中大部分對於CachedBnsClient的調用，都是經過註解Autowired的，這部分實例數不多。

惟一頻繁產生此類實例的代碼以下所示:

此CachedBnsClient僅僅在方法體內使用，並無逃逸到外面，再看此類自己

沒有任何static變量，同時也沒有往任何全局變量註冊自身。換言之，在類的成員(Member)中，是不可能出現內存泄露的。

當時只粗略的過了一過成員變量，回過頭來細想，仍是漏了很多地方的。

更多信息

因爲代碼排查下來，感受這塊不該該出現內存泄露(可是事實確是如此的打臉)。這個類也沒有顯式用到堆外內存，並且只佔了130M，和4G比起來微不足道，仍是先去追查主要矛盾再說。

使用jstack dump線程信息

現場信息越多，越能找出蛛絲馬跡。先用jstack把線程信息dump下來看下。 這一看，立馬發現了不一樣，除了正常的IO線程以及框架自己的一些守護線程外，居然還多出來了12563多個線程。

並且這些正好是運行再CachedBnsClient的run方法上面！這些特定線程的數量正好是12452個，和cachedBnsClient數量一致!

再次check對應代碼

原來剛纔看CachedBnsClient代碼的時候遺漏掉了一個關鍵的點!

這段代碼是CachedBnsClient的構造函數，其在裏面建立了一個無限循環的線程，每隔60s啓動一次刷新一下里面的緩存!

找到關鍵點

在看到12452個等待在CachedBnsClient.run的業務的一瞬間筆者就意識到，確定是這邊的線程致使對外內存泄露了。下面就是根據線程大小計算其泄露內存量是否是確實可以引發OOM了。

發現內存計算對不上

因爲咱們這邊設置的Xss是512K，即一個線程棧大小是512K，而因爲線程共享其它MM單元(線程本地內存是是如今線程棧上的)，因此實際線程堆外內存佔用數量也是512K。進行以下計算:

12563 * 512K = 6331M = 6.3G

整個環境一共4G，加上JVM堆內存1.8G(1792M)，已經明顯的超過了4G。

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

若是按照此計算，應用應用早就被OOM了。

怎麼回事呢？

爲了解決這個問題，筆者又思考了很久。以下所示:

Java線程底層實現

JVM的線程在linux上底層是調用NPTL(Native Posix Thread Library)來建立的，一個JVM線程就對應linux的lwp(輕量級進程，也是進程，只不過共享了mm_struct，用來實現線程)，一個thread.start就至關於do_fork了一把。

其中，咱們在JVM啓動時候設置了-Xss=512K(即線程棧大小)，這512K中而後有8K是必須使用的，這8K是由進程的內核棧和thread_info公用的，放在兩塊連續的物理頁框上。以下圖所示:

衆所周知，一個進程(包括lwp)包括內核棧和用戶棧，內核棧+thread_info用了8K，那麼用戶態的棧可用內存就是:

512K-8K=504K

以下圖所示:

Linux實際物理內存映射

事實上linux對物理內存的使用很是的摳門，一開始只是分配了虛擬內存的線性區，並無分配實際的物理內存，只有推到最後使用的時候才分配具體的物理內存，即所謂的請求調頁。以下圖所示:

查看smaps進程內存使用信息

使用以下命令，查看

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

實際物理內存使用信息，以下所示:

搜索下504KB，正好是12563個，對了12563個線程，其中Rss表示實際物理內存(含共享庫)92KB，Pss表示實際物理內存(按比例共享庫)92KB(因爲沒有共享庫，因此Rss==Pss)，以第一個7fa69a6d1000-7fa69a74f000線性區來看，其映射了92KB的空間，第二個映射了152KB的空間。以下圖所示:

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

(92+152)/2+8K=130K，因爲是估算，取整爲128K，即反映此應用平均線程棧大小。

注意，實際內存有波動的緣由是因爲環境不一樣，從而走了不一樣的分支，致使棧上的增加不一樣。

從新進行內存計算

JVM一開始申請了

-Xmx1792m -Xms1792m

即1.8G的堆內內存，這裏是即時分配，一開始就用物理頁框填充。

12563個線程，每一個線程棧平均大小128K，即:

128K * 12563=1570M=1.5G的對外內存

取個整數128K，就能反映出平均水平。再拿這個128K * 12563 =1570M = 1.5G，加上JVM的1.8G，就已經達到了3.3G，再加上kernel和日誌傳輸進程等使用的內存數量，確實已經接近了4G，這樣內存就對應上了！(注:用於定量內存計算的環境是一臺內存用量將近4G，但還沒OOM的機器)

爲何在物理機上沒有應用Down機

筆者登陸了原來物理機，應用還在跑，發現其一樣有堆外內存泄露的現象，其物理內存使用已經達到了5個多G!幸虧物理機內存很大，並且此應用發佈還比較頻繁，因此沒有被OOM。

Dump了物理機上應用的線程，

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

一樣用smaps查看進程實際內存信息，其平均大小依舊爲

128K，由於是同一應用的緣由

繼續進行物理內存計算

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

進一步驗證了咱們的推理。

這麼多線程應用爲何沒有卡頓

由於基本全部的線程都睡眠在

Thread.sleep(60 1000);//一次睡眠60s*上。因此僅僅佔用了內存，實際佔用的CPU時間不多。

此我向你們推薦一個架構學習交流羣。交流學習羣號：575745314 裏面會分享一些資深架構師錄製的視頻錄像：有Spring，MyBatis，Netty源碼分析，高併發、高性能、分佈式、微服務架構的原理，JVM性能優化、分佈式架構等這些成爲架構師必備的知識體系。還能領取免費的學習資源，目前受益良多

總結

查找Bug的時候，現場信息越多越好，同時定位Bug必需要有實質性的證據。例如內存泄露就要用你推測出的模型進行定量分析。在定量和實際對不上的時候，深挖下去，你會發現不同的風景!