JVM的堆外內存泄露的定位一直是個比較棘手的問題。此次的Bug查找從堆內內存的泄露反推出堆外內存,同時對物理內存的使用做了定量的分析,從而實錘了Bug的源頭。筆者將此Bug分析的過程寫成博客,以饗讀者。
由于物理內存定量分析部分用到了linux kernel虛擬內存管理的知識,讀者如果有興趣了解請看ulk3(《深入理解linux內核第三版》)
一個線上穩(wěn)定運行了三年的系統(tǒng),從物理機遷移到docker環(huán)境后,運行了一段時間,突然被監(jiān)控系統(tǒng)發(fā)出了某些實例不可用的報警。所幸有負載均衡,可以自動下掉節(jié)點,如下圖所示:
登錄到對應機器上后,發(fā)現(xiàn)由于內存占用太大,觸發(fā)OOM,然后被linux系統(tǒng)本身給kill了。
緊急在出問題的實例上再次啟動應用,啟動后,內存占用正常,一切Okay。
當前設置的最大堆內存是1792M,如下所示:
-Xmx1792m -Xms1792m -Xmn900m -XX:PermSi ze=256m -XX:MaxPermSize=256m -server -Xss512k
查看操作系統(tǒng)層面的監(jiān)控,發(fā)現(xiàn)內存占用情況如下圖所示:
上圖藍色的線表示總的內存使用量,發(fā)現(xiàn)一直漲到了4G后,超出了系統(tǒng)限制。
很明顯,有堆外內存泄露了。
一般出現(xiàn)內存泄露,筆者立馬想到的就是查看當時的gc日志。
本身應用所采用框架會定時打印出對應的gc日志,遂查看,發(fā)現(xiàn)gc日志一切正常。對應日志如下:
查看了當天的所有gc日志,發(fā)現(xiàn)內存始終會回落到170M左右,并無明顯的增加。要知道JVM進程本身占用的內存可是接近4G(加上其它進程,例如日志進程就已經到4G了),進一步確認是堆外內存導致。
打開線上服務對應對應代碼,查了一圈,發(fā)現(xiàn)沒有任何地方顯式利用堆外內存,其沒有依賴任何額外的native方法。關于網絡IO的代碼也是托管給Tomcat,很明顯,作為一個全世界廣泛流行的Web服務器,Tomcat不大可能有堆外內存泄露。
由于在代碼層面沒有發(fā)現(xiàn)堆外內存的痕跡,那就繼續(xù)找些其它的信息,希望能發(fā)現(xiàn)蛛絲馬跡。
由于線上出問題的Server已經被kill,還好有其它幾臺,登上去發(fā)現(xiàn)它們也
占用了很大的堆外內存,只是還沒有到觸發(fā)OOM的臨界點而已。于是就趕緊用jmap
dump了兩臺機器中應用JVM的堆情況,這兩臺留做現(xiàn)場保留不動,然后將其它機器迅速重啟,以防同時被OOM導致服務不可用。
使用如下命令dump:
jmap -dump:format=b,file=heap.bin [pid]
挑了一個heap文件進行分析,堆的使用情況如下圖所示:
一共用了200多M,和之前gc文件打印出來的170M相差不大,遠遠沒有到4G的程度。
不得不說MAT是個非常好用的工具,它可以提示你可能內存泄露的點:
這個cachedBnsClient類有12452個實例,占用了整個堆的61.92%。
查看了另一個heap文件,發(fā)現(xiàn)也是同樣的情況。這個地方肯定有內存泄露,但是也占用了130多M,和4G相差甚遠。
系統(tǒng)中大部分對于CachedBnsClient的調用,都是通過注解Autowired的,這部分實例數很少。
唯一頻繁產生此類實例的代碼如下所示:
@Override public void fun() { BnsClient bnsClient = new CachedBnsClient(); // do something return ; }
此CachedBnsClient僅僅在方法體內使用,并沒有逃逸到外面,再看此類本身
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)內存泄露的。
當時只粗略的過了一過成員變量,回過頭來細想,還是漏了不少地方的。
由于代碼排查下來,感覺這塊不應該出現(xiàn)內存泄露(但是事實確是如此的打臉)。這個類也沒有顯式用到堆外內存,而且只占了130M,和4G比起來微不足道,還是先去追查主要矛盾再說。
現(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方法上面!這些特定線程的數量正好是12452個,和cachedBnsClient數量一致!
原來剛才看CachedBnsClient代碼的時候遺漏掉了一個關鍵的點!
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); } } } }
這段代碼是CachedBnsClient的構造函數,其在里面創(chuàng)建了一個無限循環(huán)的線程,每隔60s啟動一次刷新一下里面的緩存!
在看到12452個等待在CachedBnsClient.run的業(yè)務的一瞬間筆者就意識到,肯定是這邊的線程導致對外內存泄露了。下面就是根據線程大小計算其泄露內存量是不是確實能夠引起OOM了。
由于我們這邊設置的Xss是512K,即一個線程棧大小是512K,而由于線程共享其它MM單元(線程本地內存是是現(xiàn)在線程棧上的),所以實際線程堆外內存占用數量也是512K。進行如下計算:
12563 * 512K = 6331M = 6.3G
整個環(huán)境一共4G,加上JVM堆內存1.8G(1792M),已經明顯的超過了4G。
(6.3G + 1.8G)=8.1G > 4G
如果按照此計算,應用應用早就被OOM了。
為了解決這個問題,筆者又思考了好久。如下所示:
JVM的線程在linux上底層是調用NPTL(Native Posix Thread Library)來創(chuàng)建的,一個JVM線程就對應linux的lwp(輕量級進程,也是進程,只不過共享了mm_struct,用來實現(xiàn)線程),一個thread.start就相當于do_fork了一把。
其中,我們在JVM啟動時候設置了-Xss=512K(即線程棧大小),這512K中然后有8K是必須使用的,這8K是由進程的內核棧和thread_info公用的,放在兩塊連續(xù)的物理頁框上。如下圖所示:
眾所周知,一個進程(包括lwp)包括內核棧和用戶棧,內核棧+thread_info用了8K,那么用戶態(tài)的??捎脙却婢褪?
512K-8K=504K
如下圖所示:
事實上linux對物理內存的使用非常的摳門,一開始只是分配了虛擬內存的線性區(qū),并沒有分配實際的物理內存,只有推到最后使用的時候才分配具體的物理內存,即所謂的請求調頁。如下圖所示:
使用如下命令,查看
cat /proc/[pid]/smaps > smaps.txt
實際物理內存使用信息,如下所示:
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表示實際物理內存(含共享庫)92KB,Pss表示實際物理內存(按比例共享庫)92KB(由于沒有共享庫,所以Rss==Pss),以第一個7fa69a6d1000-7fa69a74f000線性區(qū)來看,其映射了92KB的空間,第二個映射了152KB的空間。如下圖所示:
挑出符合條件(即size是504K)的幾十組看了下,基本都在92K-152K之間,再加上內核棧8K
(92+152)/2+8K=130K,由于是估算,取整為128K,即反映此應用平均線程棧大小。
注意,實際內存有波動的原因是由于環(huán)境不同,從而走了不同的分支,導致棧上的增長不同。
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,這樣內存就對應上了!(注:用于定量內存計算的環(huán)境是一臺內存用量將近4G,但還沒OOM的機器)
筆者登錄了原來物理機,應用還在跑,發(fā)現(xiàn)其同樣有堆外內存泄露的現(xiàn)象,其物理內存使用已經達到了5個多G!幸好物理機內存很大,而且此應用發(fā)布還比較頻繁,所以沒有被OOM。
Dump了物理機上應用的線程,
一共有28737個線程,其中28626個線程等待在CachedBnsClient上。
同樣用smaps查看進程實際內存信息,其平均大小依舊為
128K,因為是同一應用的原因
繼續(xù)進行物理內存計算
1.8+(28737 * 128k)/1024K =(3.6+1.8)=5.4G
進一步驗證了我們的推理。
因為基本所有的線程都睡眠在
Thread.sleep(60 * 1000);//一次睡眠60s
上。所以僅僅占用了內存,實際占用的CPU時間很少。
查找Bug的時候,現(xiàn)場信息越多越好,同時定位Bug必須要有實質性的證據。例如內存泄露就要用你推測出的模型進行定量分析。在定量和實際對不上的時候,深挖下去,你會發(fā)現(xiàn)不一樣的風景!