JAVA堆外內存排查小結

時間 2019-12-04

標籤 java 內存排查小結欄目 Java 简体版

原文原文鏈接

簡介

JVM堆外內存難排查但常常會出現問題，這多是目前最全的JVM堆外內存排查思路。java

經過本文，你應該瞭解：android

pmap 命令
gdb 命令
perf 命令
內存 RSS、VSZ的區別
java NMT

原由

這幾天遇到一個比較奇怪的問題，以爲有必要和你們分享一下。咱們的一個服務，運行在docker上，在某個版本以後，佔用的內存開始增加，直到docker分配的內存上限，可是並不會OOM。版本的更改以下：docker

升級了基礎軟件的版本
將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的設定。bash

[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一塊的內存段，還有巨量小的物理內存塊映射到不一樣的虛擬內存段上。但到如今爲止，咱們不知道里面的內容是什麼，是經過什麼產生的。ui

[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)google

文章指出形成應用程序大量申請64M大內存塊的緣由是由Glibc的一個版本升級引發的，經過export MALLOC_ARENA_MAX=4能夠解決VSZ佔用太高的問題。雖然這也是一個問題，但卻不是咱們想要的，由於咱們增加的是物理內存，而不是虛擬內存。spa

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();
    }

複製代碼

經觀察，問題解決。