簡介
JVM
堆外記憶體難排查但經常會出現問題,這可能是目前最全的JVM堆外記憶體排查思路。
通過本文,你應該瞭解:
- pmap 命令
- gdb 命令
- perf 命令
- 記憶體 RSS、VSZ的區別
- java NMT
起因
這幾天遇到一個比較奇怪的問題,覺得有必要和大家分享一下。我們的一個服務,執行在docker
上,在某個版本之後,佔用的記憶體開始增長,直到docker
分配的記憶體上限,但是並不會OOM
。版本的更改如下:
- 升級了基礎軟體的版本
- 將docker的記憶體上限由4GB擴充套件到8GB
- 上上個版本的一項變動是使用了EhCache的Heap快取
- 沒有讀檔案,也沒有mmap操作
使用jps
檢視啟動引數,發現分配了大約3GB的堆記憶體
[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檢視程式使用的記憶體和虛擬記憶體 ( Linux記憶體管理 )。除了虛擬記憶體比較高達到17GB
以外,實際使用的記憶體RSS也誇張的達到了7GB,遠遠超過了-Xmx
的設定。
[root]$ ps -p 75 -o rss,vsz
RSS VSZ 7152568 17485844
複製程式碼
排查過程
明顯的,是有堆外記憶體的使用,不太可能是由於EhCache
引起的(因為我們使用了heap方式)。瞭解到基礎軟體的升級涉及到netty版本升級,netty會用到一些DirectByteBuffer
,第一輪排查我們採用如下方式:
jmap -dump:format=b,file=75.dump 75
通過分析堆記憶體找到DirectByteBuffer
的引用和大小- 部署一個升級基礎軟體之前的版本,持續觀察
- 部署另一個版本,更改EhCache限制其大小到1024M
- 考慮到可能由Docker的記憶體分配機制引起,部署一例項到實體機
結果4個環境中的服務,無一例外的都出現了記憶體超用的問題。問題很奇怪,寶寶睡不著覺。
pmap
為了進一步分析問題,我們使用pmap檢視程式的記憶體分配,通過RSS升序序排列。結果發現除了地址000000073c800000
上分配的3GB堆以外,還有數量非常多的64M一塊的記憶體段,還有巨量小的實體記憶體塊對映到不同的虛擬記憶體段上。但到現在為止,我們不知道里面的內容是什麼,是通過什麼產生的。
[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)
文章指出造成應用程式大量申請64M大記憶體塊的原因是由Glibc的一個版本升級引起的,通過export MALLOC_ARENA_MAX=4
可以解決VSZ佔用過高的問題。雖然這也是一個問題,但卻不是我們想要的,因為我們增長的是實體記憶體,而不是虛擬記憶體。
NMT
幸運的是 JDK1.8有Native Memory Tracker
可以幫助定位。通過在啟動引數上加入-XX:NativeMemoryTracking=detail
就可以啟用。在命令列執行jcmd可檢視記憶體分配。
#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得到的記憶體地址和NMT
大體能對的上,但仍然有不少記憶體去向成謎。雖然是個好工具但問題並不能解決。
gdb
非常好奇64M或者其他小記憶體塊中是什麼內容,接下來通過gdb
dump出來。讀取/proc
目錄下的maps檔案,能精準的知曉目前程式的記憶體分佈。
以下指令碼通過傳入程式id,能夠將所關聯的記憶體全部dump到檔案中(會影響服務,慎用)。
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
複製程式碼
更多時候,推薦之dump一部分記憶體。(再次提醒操作會影響服務,注意dump的記憶體塊大小,慎用)。
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
複製程式碼
是時候檢視裡面的內容了
[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
複製程式碼
納尼?這些內容不應該在堆裡面麼?為何還會使用額外的記憶體進行分配?上面已經排查netty申請directbuffer的原因了,那麼還有什麼地方在分配堆外記憶體呢?
perf
傳統工具失靈,快到了黔驢技窮的時候了,是時候祭出神器perf了。
使用 perf record -g -p 55
開啟監控棧函式呼叫。執行一段時間後Ctrl+C結束,會生成一個檔案perf.data。
執行perf report -i perf.data
檢視報告。
如圖,程式大量執行bzip相關函式。搜尋zip,結果如下:
-.-!
程式呼叫了Java_java_util_zip_Inflater_inflatBytes() 申請了記憶體,僅有一小部分呼叫Deflater釋放記憶體。與pmap記憶體地址相比對,確實是bzip在搞鬼。
解決
java專案搜尋zip定位到程式碼,發現確實有相關bzip壓縮解壓操作,而且GZIPInputStream
有個地方沒有close。
GZIPInputStream使用Inflater申請堆外記憶體,Deflater釋放記憶體,呼叫close()方法來主動釋放。如果忘記關閉,Inflater物件的生命會延續到下一次GC。在此過程中,堆外記憶體會一直增長。
原始碼:
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();
}
複製程式碼
經觀察,問題解決。