簡(jiǎn)介
JVM堆外內(nèi)存難排查但經(jīng)常會(huì)出現(xiàn)問題妹田，這可能是目前最全的JVM堆外內(nèi)存排查思路黔帕。之前的文章排版太亂，現(xiàn)在整理重發(fā)一下怀伦，內(nèi)容是一樣的壁涎。
通過本文凡恍，你應(yīng)該了解：
pmap 命令
gdb 命令
perf 命令
內(nèi)存 RSS、VSZ的區(qū)別
java NMT
起因
這幾天遇到一個(gè)比較奇怪的問題怔球，覺得有必要和大家分享一下嚼酝。我們的一個(gè)服務(wù)，運(yùn)行在docker上竟坛，在某個(gè)版本之后闽巩，占用的內(nèi)存開始增長(zhǎng)，直到docker分配的內(nèi)存上限担汤，但是并不會(huì)OOM涎跨。版本的更改如下：
升級(jí)了基礎(chǔ)軟件的版本
將docker的內(nèi)存上限由4GB擴(kuò)展到8GB
上上個(gè)版本的一項(xiàng)變動(dòng)是使用了EhCache的Heap緩存
沒有讀文件，也沒有mmap操作
使用jps 查看啟動(dòng)參數(shù)崭歧，發(fā)現(xiàn)分配了大約3GB的堆內(nèi)存
[root]$ jps -v
75 Bootstrap -Xmx3000m -Xms3000m -verbose:gc -Xloggc:/home/logs/gc.log -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSCompactAtFullCollection -XX:MaxTenuringThreshold=10 -XX:MaxPermSize=128M -XX:SurvivorRatio=3 -XX:NewRatio=2 -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+UseParNewGC -XX:+UseConcMarkSweepGC
使用ps查看進(jìn)程使用的內(nèi)存和虛擬內(nèi)存 ( Linux內(nèi)存管理 )隅很。除了虛擬內(nèi)存比較高達(dá)到17GB以外，實(shí)際使用的內(nèi)存RSS也夸張的達(dá)到了7GB率碾，遠(yuǎn)遠(yuǎn)超過了-Xmx的設(shè)定叔营。
[root]$ ps -p 75 -o rss,vsz
RSS VSZ 7152568 17485844
排查過程
明顯的屋彪，是有堆外內(nèi)存的使用，不太可能是由于EhCache引起的（因?yàn)槲覀兪褂昧薶eap方式）绒尊。了解到基礎(chǔ)軟件的升級(jí)涉及到netty版本升級(jí)畜挥，netty會(huì)用到一些DirectByteBuffer，第一輪排查我們采用如下方式：
jmap -dump:format=b,file=75.dump 75通過分析堆內(nèi)存找到DirectByteBuffer的引用和大小部署一個(gè)升級(jí)基礎(chǔ)軟件之前的版本垒酬，持續(xù)觀察
部署另一個(gè)版本砰嘁，更改EhCache限制其大小到1024M
考慮到可能由Docker的內(nèi)存分配機(jī)制引起，部署一實(shí)例到實(shí)體機(jī)
結(jié)果4個(gè)環(huán)境中的服務(wù)勘究，無一例外的都出現(xiàn)了內(nèi)存超用的問題矮湘。問題很奇怪，寶寶睡不著覺口糕。
pmap
為了進(jìn)一步分析問題缅阳，我們使用pmap查看進(jìn)程的內(nèi)存分配，通過RSS升序序排列景描。結(jié)果發(fā)現(xiàn)除了地址000000073c800000上分配的3GB堆以外十办，還有數(shù)量非常多的64M一塊的內(nèi)存段，還有巨量小的物理內(nèi)存塊映射到不同的虛擬內(nèi)存段上超棺。但到現(xiàn)在為止向族，我們不知道里面的內(nèi)容是什么，是通過什么產(chǎn)生的棠绘。
[root]$ pmap -x 75 | sort -n -k3
.....省略N行
0000000040626000 55488 55484 55484 rwx-- [ anon ]
00007fa07c000000 65536 55820 55820 rwx-- [ anon ]
00007fa044000000 65536 55896 55896 rwx-- [ anon ]
00007fa0c0000000 65536 56304 56304 rwx-- [ anon ]
00007f9db8000000 65536 56360 56360 rwx-- [ anon ]
00007fa0b8000000 65536 56836 56836 rwx-- [ anon ]
00007fa084000000 65536 57916 57916 rwx-- [ anon ]
00007f9ec4000000 65532 59752 59752 rwx-- [ anon ]
00007fa008000000 65536 60012 60012 rwx-- [ anon ]
00007f9e58000000 65536 61608 61608 rwx-- [ anon ]
00007f9f18000000 65532 61732 61732 rwx-- [ anon ]
00007fa018000000 65532 61928 61928 rwx-- [ anon ]
00007fa088000000 65536 62336 62336 rwx-- [ anon ]
00007fa020000000 65536 62428 62428 rwx-- [ anon ]
00007f9e44000000 65536 64352 64352 rwx-- [ anon ]
00007f9ec0000000 65528 64928 64928 rwx-- [ anon ]
00007fa050000000 65532 65424 65424 rwx-- [ anon ]
00007f9e08000000 65512 65472 65472 rwx-- [ anon ]
00007f9de0000000 65524 65512 65512 rwx-- [ anon ]
00007f9dec000000 65532 65532 65532 rwx-- [ anon ]
00007f9dac000000 65536 65536 65536 rwx-- [ anon ]
00007f9dc8000000 65536 65536 65536 rwx-- [ anon ]
00007f9e30000000 65536 65536 65536 rwx-- [ anon ]
00007f9eb4000000 65536 65536 65536 rwx-- [ anon ]
00007fa030000000 65536 65536 65536 rwx-- [ anon ]
00007fa0b0000000 65536 65536 65536 rwx-- [ anon ]
000000073c800000 3119140 2488596 2487228 rwx-- [ anon ]
total kB 17629516 7384476 7377520
通過google件相，找到以下資料 Linux glibc >= 2.10 (RHEL 6) malloc may show excessive virtual memory usage)
文章指出造成應(yīng)用程序大量申請(qǐng)64M大內(nèi)存塊的原因是由Glibc的一個(gè)版本升級(jí)引起的，通過export MALLOC_ARENA_MAX=4可以解決VSZ占用過高的問題氧苍。雖然這也是一個(gè)問題夜矗，但卻不是我們想要的，因?yàn)槲覀冊(cè)鲩L(zhǎng)的是物理內(nèi)存让虐，而不是虛擬內(nèi)存紊撕。
NMT
幸運(yùn)的是 JDK1.8有Native Memory Tracker可以幫助定位。通過在啟動(dòng)參數(shù)上加入-XX:NativeMemoryTracking=detail就可以啟用赡突。在命令行執(zhí)行jcmd可查看內(nèi)存分配对扶。
#jcmd 75 VM.native_memory summary
Native Memory Tracking: Total: reserved=5074027KB, committed=3798707KB - Java Heap (reserved=3072000KB, committed=3072000KB) (mmap: reserved=3072000KB, committed=3072000KB) - Class (reserved=1075949KB, committed=28973KB) (classes #4819) (malloc=749KB #13158) (mmap: reserved=1075200KB, committed=28224KB) - Thread (reserved=484222KB, committed=484222KB) (thread #470) (stack: reserved=482132KB, committed=482132KB) (malloc=1541KB #2371) (arena=550KB #938) - Code (reserved=253414KB, committed=25070KB) (malloc=3814KB #5593) (mmap: reserved=249600KB, committed=21256KB) - GC (reserved=64102KB, committed=64102KB) (malloc=54094KB #255) (mmap: reserved=10008KB, committed=10008KB) - Compiler (reserved=542KB, committed=542KB) (malloc=411KB #543) (arena=131KB #3) - Internal (reserved=50582KB, committed=50582KB) (malloc=50550KB #13713) (mmap: reserved=32KB, committed=32KB) - Symbol (reserved=6384KB, committed=6384KB) (malloc=4266KB #31727) (arena=2118KB #1) - Native Memory Tracking (reserved=1325KB, committed=1325KB) (malloc=208KB #3083) (tracking overhead=1117KB) - Arena Chunk (reserved=231KB, committed=231KB) (malloc=231KB) - Unknown (reserved=65276KB, committed=65276KB) (mmap: reserved=65276KB, committed=65276KB)
雖然pmap得到的內(nèi)存地址和NMT大體能對(duì)的上，但仍然有不少內(nèi)存去向成謎麸俘。雖然是個(gè)好工具但問題并不能解決辩稽。
gdb
非常好奇64M或者其他小內(nèi)存塊中是什么內(nèi)容，接下來通過gdb dump出來从媚。讀取/proc目錄下的maps文件逞泄，能精準(zhǔn)的知曉目前進(jìn)程的內(nèi)存分布。
以下腳本通過傳入進(jìn)程id，能夠?qū)⑺P(guān)聯(lián)的內(nèi)存全部dump到文件中（會(huì)影響服務(wù)喷众，慎用）各谚。
grep rw-p /proc/$1/maps | sed -n 's/^\([0-9a-f]*\)-\([0-9a-f]*\) .*$/\1 \2/p' | while read start stop; do gdb --batch --pid $1 -ex "dump memory $1-$start-$stop.dump 0x$start 0x$stop"; done
更多時(shí)候，推薦之dump一部分內(nèi)存到千。(再次提醒操作會(huì)影響服務(wù)昌渤，注意dump的內(nèi)存塊大小，慎用)憔四。
gdb --batch --pid 75 -ex "dump memory a.dump 0x7f2bceda1000 0x7f2bcef2b000
[root]$ du -h *
dump 4.0K
55-00600000-00601000.dump 400K
55-00eb7000-00f1b000.dump 0
55-704800000-7c0352000.dump 47M
55-7f2840000000-7f2842eb8000.dump 53M
55-7f2848000000-7f284b467000.dump 64M
55-7f284c000000-7f284fffa000.dump 64M
55-7f2854000000-7f2857fff000.dump 64M
55-7f285c000000-7f2860000000.dump 64M
55-7f2864000000-7f2867ffd000.dump 1016K
55-7f286a024000-7f286a122000.dump 1016K
55-7f286a62a000-7f286a728000.dump 1016K
55-7f286d559000-7f286d657000.dump
是時(shí)候查看里面的內(nèi)容了
[root]$ view 55-7f284c000000-7f284fffa000.dump
^@^@X+^?^@^@^@^@^@d(^?^@^@^@ ?^C^@^@^@^@^@ ?^C^@^@^@^@^@^@^@^@^@^@^@^@±<97>p^C^@^@^@^@ 8^^Z+^?^@^@ ^@^@d(^?^@^@ 8^^Z+^?^@^@ ^@^@d(^?^@^@
achine":524993642,"timeSecond":1460272569,"inc":2145712868,"new":false},"device":{"client":"android","uid":"xxxxx","version":881},"
device_android":{"BootSerialno":"xxxxx","CpuInfo":"0-7","MacInfo":"2c:5b:b8:b0:d5:10","RAMSize":"4027212","SdcardInfo":"xxxx","Serialno":"xxxx",
"android_id":"488aedba19097476","buildnumber":"KTU84P/1416486236","device_ip":"0.0.0.0","mac":"2c:5b:b8:b0:d5:10","market_source":"12","model":"OPPO ...more
納尼膀息？這些內(nèi)容不應(yīng)該在堆里面么？為何還會(huì)使用額外的內(nèi)存進(jìn)行分配了赵？上面已經(jīng)排查netty申請(qǐng)directbuffer的原因了潜支，那么還有什么地方在分配堆外內(nèi)存呢？
perf
傳統(tǒng)工具失靈柿汛，快到了黔驢技窮的時(shí)候了冗酿，是時(shí)候祭出神器perf了。
使用 perf record -g -p 55 開啟監(jiān)控棧函數(shù)調(diào)用络断。運(yùn)行一段時(shí)間后Ctrl+C結(jié)束裁替，會(huì)生成一個(gè)文件perf.data。
執(zhí)行perf report -i perf.data查看報(bào)告貌笨。
如圖弱判，進(jìn)程大量執(zhí)行bzip相關(guān)函數(shù)。搜索zip锥惋，結(jié)果如下：-.-!
進(jìn)程調(diào)用了
Java_java_util_zip_Inflater_inflatBytes()
申請(qǐng)了內(nèi)存裕循，僅有一小部分調(diào)用Deflater釋放內(nèi)存。與pmap內(nèi)存地址相比對(duì)净刮，確實(shí)是bzip在搞鬼。
解決
java項(xiàng)目搜索zip定位到代碼硅则，發(fā)現(xiàn)確實(shí)有相關(guān)bzip壓縮解壓操作淹父，而且GZIPInputStream有個(gè)地方?jīng)]有close。
GZIPInputStream使用Inflater申請(qǐng)堆外內(nèi)存怎虫，Deflater釋放內(nèi)存暑认，調(diào)用close()方法來主動(dòng)釋放。如果忘記關(guān)閉大审，Inflater對(duì)象的生命會(huì)延續(xù)到下一次GC蘸际。在此過程中，堆外內(nèi)存會(huì)一直增長(zhǎng)徒扶。
原代碼：
public byte[] decompress ( byte[] input) throws IOException {
ByteArrayOutputStream out = new ByteArrayOutputStream();
IOUtils.copy(new GZIPInputStream(new ByteArrayInputStream(input)), out); return out.toByteArray();
}
修改后：
public byte[] decompress(byte[] input) throws IOException {
ByteArrayOutputStream out = new ByteArrayOutputStream();
GZIPInputStream gzip = new GZIPInputStream(new ByteArrayInputStream(input));
IOUtils.copy(gzip, out);
gzip.close(); return out.toByteArray();
}
經(jīng)觀察粮彤，問題解決。
