Spring Boot “內(nèi)存泄漏”？看看美團(tuán)大牛是如何排查的

來自：美團(tuán)技術(shù)團(tuán)隊
鏈接：8rr.co/38Kh

為了更好地實現(xiàn)對項目的管理杖小，我們將組內(nèi)一個項目遷移到MDP框架（基于Spring Boot）肆汹，隨后我們就發(fā)現(xiàn)系統(tǒng)會頻繁報出Swap區(qū)域使用量過高的異常。筆者被叫去幫忙查看原因予权，發(fā)現(xiàn)配置了4G堆內(nèi)內(nèi)存昂勉，但是實際使用的物理內(nèi)存竟然高達(dá)7G，確實不正常扫腺。JVM參數(shù)配置是“-XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+AlwaysPreTouch -XX:ReservedCodeCacheSize=128m -XX:InitialCodeCacheSize=128m, -Xss512k -Xmx4g -Xms4g,-XX:+UseG1GC -XX:G1HeapRegionSize=4M”岗照，實際使用的物理內(nèi)存如下圖所示：

image

top命令顯示的內(nèi)存情況

排查過程

1. 使用Java層面的工具定位內(nèi)存區(qū)域（堆內(nèi)內(nèi)存、Code區(qū)域或者使用unsafe.allocateMemory和DirectByteBuffer申請的堆外內(nèi)存）

筆者在項目中添加-XX:NativeMemoryTracking=detailJVM參數(shù)重啟項目笆环，使用命令jcmd pid VM.native_memory detail查看到的內(nèi)存分布如下：

image

jcmd顯示的內(nèi)存情況

發(fā)現(xiàn)命令顯示的committed的內(nèi)存小于物理內(nèi)存攒至，因為jcmd命令顯示的內(nèi)存包含堆內(nèi)內(nèi)存、Code區(qū)域躁劣、通過unsafe.allocateMemory和DirectByteBuffer申請的內(nèi)存迫吐，但是不包含其他Native Code（C代碼）申請的堆外內(nèi)存。所以猜測是使用Native Code申請內(nèi)存所導(dǎo)致的問題习绢。

為了防止誤判渠抹，筆者使用了pmap查看內(nèi)存分布蝙昙，發(fā)現(xiàn)大量的64M的地址；而這些地址空間不在jcmd命令所給出的地址空間里面梧却，基本上就斷定就是這些64M的內(nèi)存所導(dǎo)致奇颠。

image

pmap顯示的內(nèi)存情況

使用系統(tǒng)層面的工具定位堆外內(nèi)存

因為筆者已經(jīng)基本上確定是Native Code所引起，而Java層面的工具不便于排查此類問題放航，只能使用系統(tǒng)層面的工具去定位問題烈拒。

首先，使用了gperftools去定位問題

gperftools的使用方法可以參考gperftools广鳍，gperftools的監(jiān)控如下：

image

gperftools監(jiān)控

從上圖可以看出：使用malloc申請的的內(nèi)存最高到3G之后就釋放了荆几，之后始終維持在700M-800M。筆者第一反應(yīng)是：難道Native Code中沒有使用malloc申請赊时，直接使用mmap/brk申請的吨铸？（gperftools原理就使用動態(tài)鏈接的方式替換了操作系統(tǒng)默認(rèn)的內(nèi)存分配器（glibc）。）

然后祖秒，使用strace去追蹤系統(tǒng)調(diào)用

因為使用gperftools沒有追蹤到這些內(nèi)存诞吱，于是直接使用命令“strace -f -e”brk,mmap,munmap” -p pid”追蹤向OS申請內(nèi)存請求，但是并沒有發(fā)現(xiàn)有可疑內(nèi)存申請竭缝。strace監(jiān)控如下圖所示:

image

strace監(jiān)控

接著房维，使用GDB去dump可疑內(nèi)存

因為使用strace沒有追蹤到可疑內(nèi)存申請；于是想著看看內(nèi)存中的情況抬纸。就是直接使用命令gdp -pid pid進(jìn)入GDB之后咙俩，然后使用命令dump memory mem.bin startAddress endAddressdump內(nèi)存，其中startAddress和endAddress可以從/proc/pid/smaps中查找湿故。然后使用strings mem.bin查看dump的內(nèi)容阿趁，如下：

image

gperftools監(jiān)控

從內(nèi)容上來看，像是解壓后的JAR包信息晓锻。讀取JAR包信息應(yīng)該是在項目啟動的時候歌焦，那么在項目啟動之后使用strace作用就不是很大了飞几。所以應(yīng)該在項目啟動的時候使用strace砚哆，而不是啟動完成之后。

再次屑墨，項目啟動時使用strace去追蹤系統(tǒng)調(diào)用

項目啟動使用strace追蹤系統(tǒng)調(diào)用躁锁，發(fā)現(xiàn)確實申請了很多64M的內(nèi)存空間，截圖如下：

image

strace監(jiān)控

使用該mmap申請的地址空間在pmap對應(yīng)如下：

image

strace申請內(nèi)容對應(yīng)的pmap地址空間

最后卵史，使用jstack去查看對應(yīng)的線程

因為strace命令中已經(jīng)顯示申請內(nèi)存的線程ID战转。直接使用命令jstack pid去查看線程棧，找到對應(yīng)的線程棧（注意10進(jìn)制和16進(jìn)制轉(zhuǎn)換）如下：

image

strace申請空間的線程棧

這里基本上就可以看出問題來了：MCC（美團(tuán)統(tǒng)一配置中心）使用了Reflections進(jìn)行掃包以躯，底層使用了Spring Boot去加載JAR槐秧。因為解壓JAR使用Inflater類啄踊，需要用到堆外內(nèi)存，然后使用Btrace去追蹤這個類刁标，棧如下：

image

btrace追蹤棧

然后查看使用MCC的地方颠通，發(fā)現(xiàn)沒有配置掃包路徑，默認(rèn)是掃描所有的包膀懈。于是修改代碼顿锰，配置掃包路徑，發(fā)布上線后內(nèi)存問題解決启搂。

為什么堆外內(nèi)存沒有釋放掉呢硼控？

雖然問題已經(jīng)解決了，但是有幾個疑問：

  • 為什么使用舊的框架沒有問題胳赌？

  • 為什么堆外內(nèi)存沒有釋放牢撼？

  • 為什么內(nèi)存大小都是64M，JAR大小不可能這么大疑苫，而且都是一樣大浪默？

  • 為什么gperftools最終顯示使用的的內(nèi)存大小是700M左右，解壓包真的沒有使用malloc申請內(nèi)存嗎缀匕？

帶著疑問纳决，筆者直接看了一下Spring Boot Loader那一塊的源碼。發(fā)現(xiàn)Spring Boot對Java JDK的InflaterInputStream進(jìn)行了包裝并且使用了Inflater乡小，而Inflater本身用于解壓JAR包的需要用到堆外內(nèi)存阔加。而包裝之后的類ZipInflaterInputStream沒有釋放Inflater持有的堆外內(nèi)存。于是筆者以為找到了原因满钟，立馬向Spring Boot社區(qū)反饋了這個bug胜榔。但是反饋之后，筆者就發(fā)現(xiàn)Inflater這個對象本身實現(xiàn)了finalize方法湃番，在這個方法中有調(diào)用釋放堆外內(nèi)存的邏輯夭织。也就是說Spring Boot依賴于GC釋放堆外內(nèi)存。

筆者使用jmap查看堆內(nèi)對象時吠撮，發(fā)現(xiàn)已經(jīng)基本上沒有Inflater這個對象了尊惰。于是就懷疑GC的時候，沒有調(diào)用finalize泥兰。帶著這樣的懷疑弄屡，筆者把Inflater進(jìn)行包裝在Spring Boot Loader里面替換成自己包裝的Inflater，在finalize進(jìn)行打點監(jiān)控鞋诗，結(jié)果finalize方法確實被調(diào)用了膀捷。于是筆者又去看了Inflater對應(yīng)的C代碼，發(fā)現(xiàn)初始化的使用了malloc申請內(nèi)存削彬，end的時候也調(diào)用了free去釋放內(nèi)存全庸。

此刻秀仲，筆者只能懷疑free的時候沒有真正釋放內(nèi)存，便把Spring Boot包裝的InflaterInputStream替換成Java JDK自帶的壶笼，發(fā)現(xiàn)替換之后啄育，內(nèi)存問題也得以解決了。

這時拌消，再返過來看gperftools的內(nèi)存分布情況挑豌，發(fā)現(xiàn)使用Spring Boot時，內(nèi)存使用一直在增加墩崩，突然某個點內(nèi)存使用下降了好多（使用量直接由3G降為700M左右）氓英。這個點應(yīng)該就是GC引起的，內(nèi)存應(yīng)該釋放了鹦筹，但是在操作系統(tǒng)層面并沒有看到內(nèi)存變化铝阐，那是不是沒有釋放到操作系統(tǒng)，被內(nèi)存分配器持有了呢铐拐？

繼續(xù)探究徘键，發(fā)現(xiàn)系統(tǒng)默認(rèn)的內(nèi)存分配器（glibc 2.12版本）和使用gperftools內(nèi)存地址分布差別很明顯，2.5G地址使用smaps發(fā)現(xiàn)它是屬于Native Stack。內(nèi)存地址分布如下：

image

gperftools顯示的內(nèi)存地址分布

到此，基本上可以確定是內(nèi)存分配器在搗鬼升熊；搜索了一下glibc 64M，發(fā)現(xiàn)glibc從2.11開始對每個線程引入內(nèi)存池（64位機(jī)器大小就是64M內(nèi)存）它呀，原文如下：

image

glib內(nèi)存池說明

按照文中所說去修改MALLOC_ARENA_MAX環(huán)境變量，發(fā)現(xiàn)沒什么效果棒厘。查看tcmalloc（gperftools使用的內(nèi)存分配器）也使用了內(nèi)存池方式纵穿。

為了驗證是內(nèi)存池搞的鬼，筆者就簡單寫個不帶內(nèi)存池的內(nèi)存分配器奢人。使用命令gcc zjbmalloc.c -fPIC -shared -o zjbmalloc.so生成動態(tài)庫谓媒，然后使用export LD_PRELOAD=zjbmalloc.so替換掉glibc的內(nèi)存分配器。其中代碼Demo如下：

#include<sys/mman.h>
#include<stdlib.h>
#include<string.h>
#include<stdio.h>
//作者使用的64位機(jī)器何乎，sizeof(size_t)也就是sizeof(long)
void* malloc ( size_t size )
{
   long* ptr = mmap( 0, size + sizeof(long), PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS, 0, 0 );
   if (ptr == MAP_FAILED) {
  return NULL;
   }
   *ptr = size;                     // First 8 bytes contain length.
   return (void*)(&ptr[1]);        // Memory that is after length variable
}

void *calloc(size_t n, size_t size) {
 void* ptr = malloc(n * size);
 if (ptr == NULL) {
return NULL;
 }
 memset(ptr, 0, n * size);
 return ptr;
}
void *realloc(void *ptr, size_t size)
{
 if (size == 0) {
free(ptr);
return NULL;
 }
 if (ptr == NULL) {
return malloc(size);
 }
 long *plen = (long*)ptr;
 plen--;                          // Reach top of memory
 long len = *plen;
 if (size <= len) {
return ptr;
 }
 void* rptr = malloc(size);
 if (rptr == NULL) {
free(ptr);
return NULL;
 }
 rptr = memcpy(rptr, ptr, len);
 free(ptr);
 return rptr;
}

void free (void* ptr )
{
   if (ptr == NULL) {
 return;
   }
   long *plen = (long*)ptr;
   plen--;                          // Reach top of memory
   long len = *plen;               // Read length
   munmap((void*)plen, len + sizeof(long));
}

通過在自定義分配器當(dāng)中埋點可以發(fā)現(xiàn)其實程序啟動之后應(yīng)用實際申請的堆外內(nèi)存始終在700M-800M之間句惯，gperftools監(jiān)控顯示內(nèi)存使用量也是在700M-800M左右。但是從操作系統(tǒng)角度來看進(jìn)程占用的內(nèi)存差別很大（這里只是監(jiān)控堆外內(nèi)存）宪赶。

筆者做了一下測試宗弯，使用不同分配器進(jìn)行不同程度的掃包脯燃，占用的內(nèi)存如下：

image

內(nèi)存測試對比

為什么自定義的malloc申請800M搂妻，最終占用的物理內(nèi)存在1.7G呢？

因為自定義內(nèi)存分配器采用的是mmap分配內(nèi)存辕棚，mmap分配內(nèi)存按需向上取整到整數(shù)個頁欲主，所以存在著巨大的空間浪費(fèi)邓厕。通過監(jiān)控發(fā)現(xiàn)最終申請的頁面數(shù)目在536k個左右，那實際上向系統(tǒng)申請的內(nèi)存等于512k * 4k（pagesize） = 2G扁瓢。為什么這個數(shù)據(jù)大于1.7G呢详恼？

因為操作系統(tǒng)采取的是延遲分配的方式，通過mmap向系統(tǒng)申請內(nèi)存的時候引几，系統(tǒng)僅僅返回內(nèi)存地址并沒有分配真實的物理內(nèi)存昧互。只有在真正使用的時候，系統(tǒng)產(chǎn)生一個缺頁中斷伟桅，然后再分配實際的物理Page敞掘。

總結(jié)

image

流程圖

整個內(nèi)存分配的流程如上圖所示。MCC掃包的默認(rèn)配置是掃描所有的JAR包楣铁。在掃描包的時候玖雁，Spring Boot不會主動去釋放堆外內(nèi)存，導(dǎo)致在掃描階段盖腕，堆外內(nèi)存占用量一直持續(xù)飆升赫冬。當(dāng)發(fā)生GC的時候，Spring Boot依賴于finalize機(jī)制去釋放了堆外內(nèi)存溃列；但是glibc為了性能考慮劲厌，并沒有真正把內(nèi)存歸返到操作系統(tǒng)，而是留下來放入內(nèi)存池了听隐，導(dǎo)致應(yīng)用層以為發(fā)生了“內(nèi)存泄漏”脊僚。所以修改MCC的配置路徑為特定的JAR包，問題解決遵绰。筆者在發(fā)表這篇文章時辽幌，發(fā)現(xiàn)Spring Boot的最新版本（2.0.5.RELEASE）已經(jīng)做了修改，在ZipInflaterInputStream主動釋放了堆外內(nèi)存不再依賴GC椿访；所以Spring Boot升級到最新版本乌企，這個問題也可以得到解決。

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
  • 人面猴
    序言：七十年代末成玫，一起剝皮案震驚了整個濱河市加酵，隨后出現(xiàn)的幾起案子，更是在濱河造成了極大的恐慌哭当，老刑警劉巖猪腕，帶你破解...
    沈念sama閱讀 216,843評論 6贊 502
  • 死咒
    序言：濱河連續(xù)發(fā)生了三起死亡事件，死亡現(xiàn)場離奇詭異钦勘，居然都是意外死亡陋葡，警方通過查閱死者的電腦和手機(jī)，發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 92,538評論 3贊 392
  • 救了他兩次的神仙讓他今天三更去死
    文/潘曉璐 我一進(jìn)店門彻采，熙熙樓的掌柜王于貴愁眉苦臉地迎上來腐缤，“玉大人捌归，你說我怎么就攤上這事×朐粒” “怎么了惜索？”我有些...
    開封第一講書人閱讀 163,187評論 0贊 353
  • 道士緝兇錄：失蹤的賣姜人
    文/不壞的土叔 我叫張陵，是天一觀的道長剃浇。 經(jīng)常有香客問我巾兆，道長，這世上最難降的妖魔是什么虎囚？ 我笑而不...
    開封第一講書人閱讀 58,264評論 1贊 292
  • ?港島之戀（遺憾婚禮）
    正文 為了忘掉前任臼寄，我火速辦了婚禮，結(jié)果婚禮上溜宽，老公的妹妹穿的比我還像新娘吉拳。我一直安慰自己，他們只是感情好适揉，可當(dāng)我...
    茶點故事閱讀 67,289評論 6贊 390
  • 惡毒庶女頂嫁案：這布局不是一般人想出來的
    文/花漫 我一把揭開白布留攒。 她就那樣靜靜地躺著，像睡著了一般嫉嘀。 火紅的嫁衣襯著肌膚如雪炼邀。 梳的紋絲不亂的頭發(fā)上，一...
    開封第一講書人閱讀 51,231評論 1贊 299
  • 城市分裂傳說
    那天剪侮，我揣著相機(jī)與錄音拭宁，去河邊找鬼。 笑死瓣俯，一個胖子當(dāng)著我的面吹牛杰标，可吹牛的內(nèi)容都是我干的。 我是一名探鬼主播彩匕，決...
    沈念sama閱讀 40,116評論 3贊 418
  • 雙鴛鴦連環(huán)套：你想象不到人心有多黑
    文/蒼蘭香墨 我猛地睜開眼腔剂，長吁一口氣：“原來是場噩夢啊……” “哼！你這毒婦竟也來了驼仪？” 一聲冷哼從身側(cè)響起掸犬，我...
    開封第一講書人閱讀 38,945評論 0贊 275
  • 萬榮殺人案實錄
    序言：老撾萬榮一對情侶失蹤，失蹤者是張志新（化名）和其女友劉穎绪爸，沒想到半個月后湾碎，有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體，經(jīng)...
    沈念sama閱讀 45,367評論 1贊 313
  • ?護(hù)林員之死
    正文 獨居荒郊野嶺守林人離奇死亡奠货，尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點故事閱讀 37,581評論 2贊 333
  • ?白月光啟示錄
    正文 我和宋清朗相戀三年介褥，在試婚紗的時候發(fā)現(xiàn)自己被綠了。 大學(xué)時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片。...
    茶點故事閱讀 39,754評論 1贊 348
  • 活死人
    序言：一個原本活蹦亂跳的男人離奇死亡呻顽，死狀恐怖雹顺，靈堂內(nèi)的尸體忽然破棺而出丹墨，到底是詐尸還是另有隱情廊遍，我是刑警寧澤，帶...
    沈念sama閱讀 35,458評論 5贊 344
  • ?日本核電站爆炸內(nèi)幕
    正文 年R本政府宣布贩挣，位于F島的核電站喉前，受9級特大地震影響，放射性物質(zhì)發(fā)生泄漏王财。R本人自食惡果不足惜卵迂，卻給世界環(huán)境...
    茶點故事閱讀 41,068評論 3贊 327
  • 男人毒藥：我在死后第九天來索命
    文/蒙蒙 一、第九天 我趴在偏房一處隱蔽的房頂上張望绒净。 院中可真熱鬧见咒，春花似錦、人聲如沸挂疆。這莊子的主人今日做“春日...
    開封第一講書人閱讀 31,692評論 0贊 22
  • 一樁弒父案，背后竟有這般陰謀
    文/蒼蘭香墨 我抬頭看了看天上的太陽缤言。三九已至宝当，卻和暖如春，著一層夾襖步出監(jiān)牢的瞬間胆萧，已是汗流浹背庆揩。 一陣腳步聲響...
    開封第一講書人閱讀 32,842評論 1贊 269
  • 情欲美人皮
    我被黑心中介騙來泰國打工， 沒想到剛下飛機(jī)就差點兒被人妖公主榨干…… 1. 我叫王不留跌穗，地道東北人订晌。 一個月前我還...
    沈念sama閱讀 47,797評論 2贊 369
  • 代替公主和親
    正文 我出身青樓，卻偏偏與公主長得像蚌吸，于是被迫代替她去往敵國和親腾仅。 傳聞我的和親對象是個殘疾皇子，可洞房花燭夜當(dāng)晚...
    茶點故事閱讀 44,654評論 2贊 354