十三、jdk命令之Java内存之本地内存分析神器:NMT 和 pmap
目录
一、jdk工具之jps(JVM Process Status Tools)命令使用
二、jdk命令之javah命令(C Header and Stub File Generator)
三、jdk工具之jstack(Java Stack Trace)
四、jdk工具之jstat命令(Java Virtual Machine Statistics Monitoring Tool)
四、jdk工具之jstat命令2(Java Virtual Machine Statistics Monitoring Tool)详解
五、jdk工具之jmap(java memory map)、 mat之四--结合mat对内存泄露的分析
六、jdk工具之jinfo命令(Java Configuration Info)
七、jdk工具之jconsole命令(Java Monitoring and Management Console)
八、jdk工具之JvisualVM、JvisualVM之二--Java程序性能分析工具Java VisualVM
九、jdk工具之jhat命令(Java Heap Analyse Tool)
十、jdk工具之Jdb命令(The Java Debugger)
十一、jdk命令之Jstatd命令(Java Statistics Monitoring Daemon)
十一、jdk命令之Jstatd命令(Java Statistics Monitoring Daemon)
十二、jdk工具之jcmd介绍(堆转储、堆分析、获取系统信息、查看堆外内存)
十三、jdk命令之Java内存之本地内存分析神器:NMT 和 pmap一、概述
NMT是Native Memory Tracking的缩写,是Java7U40引入的HotSpot新特性。 pmap,众所周知,就是Linux上用来看进程地址空间的。
二、NMT
Java7U40之后JDK提供了Native Memory Tracking工具,跟踪JVM内部的内存使用,并可以通过jcmd命令来访问。不过要注意的是NMT是通过在JVM代码中添加跟踪点的方式实现内存跟踪的,因此NMT不能跟踪第三方Native库的内存使用。
2.1、如何开启NMT
NMT功能默认关闭,可以通过以下方式开启:
-XX:NativeMemoryTracking=[off | summary | detail]
配置项 | 说明 |
---|---|
off | 默认配置 |
summary | 只收集汇总信息 |
detail | 收集每次调用的信息 |
注意,根据Java官方文档,开启NMT会有5%-10%的性能损耗;
如果想JVM退出时打印退出时的内存使用情况,可以通过如下配置项:
-XX:+UnlockDiagnosticVMOptions -XX:+PrintNMTStatistics
2.2、访问NMT数据
JDK提供了jcmd命令来访问NMT数据:
jcmd <pid> VM.native_memory [summary | detail | baseline | summary.diff | detail.diff | shutdown] [scale= KB | MB | GB]
配置项 | 说明 |
---|---|
summary | 只打印打印按分类汇总的内存用法 |
detail | 打印按分类汇总的内存用法、virtual memory map和每次内存分配调用 |
baseline | 创建内存快照,以比较不同时间的内存差异 |
summary.diff | 打印自上次baseline到现在的内存差异,显示汇总信息 |
detail.diff | 打印自上次baseline到现在的内存差异, 显示详细信息 |
shutdown | 关闭NMT功能 |
scale | 指定内存单位,默认为KB |
2.3、示例
启动时,加上如下的jvm参数:
-XX:MaxDirectMemorySize=10m -XX:NativeMemoryTracking=detail -XX:+UnlockDiagnosticVMOptions -XX:+PrintNMTStatistics
分析
服务通过-Xmx=6G指定最大堆分配为6G,但实际RSS已达到11G,开始怀疑堆外内存是否有内存泄露。为了有更好详细的数据,就在本地重现这个问题,并且打开了NMT持续监控。
NMT的Report如下,重点关注每个分类下的commit大小,这个是实际使用的内存大小。
命令:[root@ip-172-29-206-104 applogs]# jcmd 6739 VM.native_memory summary scale=MB
6739: #进程ID Native Memory Tracking: Total: reserved=8491110KB, committed=7220750KB - Java Heap (reserved=6293504KB, committed=6291456KB) (mmap: reserved=6293504KB, committed=6291456KB) - Class (reserved=1107429KB, committed=66189KB) (classes #11979) (malloc=1509KB #18708) (mmap: reserved=1105920KB, committed=64680KB) - Thread (reserved=159383KB, committed=159383KB) (thread #156) (stack: reserved=158720KB, committed=158720KB) (malloc=482KB #788) (arena=182KB #310) - Code (reserved=255862KB, committed=41078KB) (malloc=6262KB #9319) (mmap: reserved=249600KB, committed=34816KB) - GC (reserved=449225KB, committed=449225KB) (malloc=166601KB #1714646) (mmap: reserved=282624KB, committed=282624KB) - Compiler (reserved=395KB, committed=395KB) (malloc=265KB #856) (arena=131KB #3) - Internal (reserved=146041KB, committed=146041KB) (malloc=132185KB #276370) (mmap: reserved=13856KB, committed=13856KB) - Symbol (reserved=31487KB, committed=31487KB) (malloc=29209KB #91080) (arena=2278KB #1) - Native Memory Tracking (reserved=33212KB, committed=33212KB) (malloc=168KB #2575) (tracking overhead=33044KB) - Arena Chunk (reserved=2284KB, committed=2284KB) (malloc=2284KB) - Unknown (reserved=12288KB, committed=0KB) (mmap: reserved=12288KB, committed=0KB) Virtual memory map: ......
并且在服务器上通过cron job来定期抓取NMT的report保存下来做分析,而且同时也把其对应的RSS和PMAP都抓取了一份。
COLLECTOR_PID=`ps -ef|grep "ProcessName" | grep -v grep | awk '{print $2}'` OUTDIR=/opt/chkmem HOSTNAME=`hostname` prstat -s rss 1 1 > ${OUTDIR}/${HOSTNAME}_coll_${COLLECTOR_PID}_prstat_`date '+%Y%m%d_%H%M%S'`.txt /opt/jdk1.8.0_40/bin/jcmd ${COLLECTOR_PID} VM.native_memory detail > ${OUTDIR}/${HOSTNAME}_coll_${COLLECTOR_PID}_nmd_`date '+%Y%m%d_%H%M%S'`.txt pmap -x ${COLLECTOR_PID} > ${OUTDIR}/${HOSTNAME}_coll_${COLLECTOR_PID}_pmap_`date '+%Y%m%d_%H%M%S'`.txt
分析发现NMT中的Symbol域持续增大,从最开始的几十兆已经增加到了2G左右,而且整个jvm的内存使用量也在持续增加。见下图:
验证后发现问题和JDK8的一个bug https://bugs.java.com/view_bug.do?bug_id=8180048 非常类似,测试后也证实确实如此,最后通过升级JDK解决了这个问题。具体是那个组件命中了JDK的这个bug,会在下一篇文章中详细描述。
jcmd 14179 VM.native_memory detail
首先,你要在Java启动项中,加入启动项: -XX:NativeMemoryTracking=detail 然后,重新启动Java程序。执行如下命令: jcmd 14179 VM.native_memory detail 你会在标准输出得到类似下面的内容(本文去掉了许多与本文无关或者重复的信息):
14179: Native Memory Tracking: Total: reserved=653853KB, committed=439409KB - Java Heap (reserved=262144KB, committed=262144KB) (mmap: reserved=262144KB, committed=262144KB) - Class (reserved=82517KB, committed=81725KB) (classes #17828) (malloc=1317KB #26910) (mmap: reserved=81200KB, committed=80408KB) - Thread (reserved=20559KB, committed=20559KB) (thread #58) (stack: reserved=20388KB, committed=20388KB) (malloc=102KB #292) (arena=69KB #114) - Code (reserved=255309KB, committed=41657KB) (malloc=5709KB #11730) (mmap: reserved=249600KB, committed=35948KB) - GC (reserved=1658KB, committed=1658KB) (malloc=798KB #676) (mmap: reserved=860KB, committed=860KB) - Compiler (reserved=130KB, committed=130KB) (malloc=31KB #357) (arena=99KB #3) - Internal (reserved=5039KB, committed=5039KB) (malloc=5007KB #20850) (mmap: reserved=32KB, committed=32KB) - Symbol (reserved=18402KB, committed=18402KB) (malloc=14972KB #221052) (arena=3430KB #1) - Native Memory Tracking (reserved=2269KB, committed=2269KB) (malloc=53KB #1597) (tracking overhead=2216KB) - Arena Chunk (reserved=187KB, committed=187KB) (malloc=187KB) - Unknown (reserved=5640KB, committed=5640KB) (mmap: reserved=5640KB, committed=5640KB) . . . Virtual memory map: [0xceb00000 - 0xcec00000] reserved 1024KB for Class from [0xced00000 - 0xcee00000] reserved 1024KB for Class from . . . [0xcf85e000 - 0xcf8af000] reserved and committed 324KB for Thread Stack from [0xd4eaf000 - 0xd4f00000] reserved and committed 324KB for Thread Stack from [0xf687866e] Thread::record_stack_base_and_size()+0x1be [0xf68818bf] JavaThread::run()+0x2f [0xf67541f9] java_start(Thread*)+0x119 [0xf7606395] start_thread+0xd5 [0xd5a00000 - 0xe5a00000] reserved 262144KB for Java Heap from . . . [0xe5e00000 - 0xf4e00000] reserved 245760KB for Code from [0xf737f000 - 0xf7400000] reserved 516KB for GC from [0xf745d000 - 0xf747d000] reserved 128KB for Unknown from [0xf7700000 - 0xf7751000] reserved and committed 324KB for Thread Stack from [0xf7762000 - 0xf776a000] reserved and committed 32KB for Internal from
上面的输出也就两大部分:Total和Virtual Memory Map. Total部分就是Java进程所使用的本地内存大小的一个分布: Heap用了多少,所有的Class用了多少。其中,最重要的一个就是Heap大小,此处它的Reserved值为262144KB, 其实也就是256MB, 因为该Java启动参数最大堆设为了256M:-Xmx256M。 Virtual Memory Map部分就是细节了,也就是Java进程的地址空间的每一段是用来干什么的,大小是多少。这些进程空间段按照用途分可以分为以下几种:
Reserved for Class (总共有76段)
例如:[0xceb00000 - 0xcec00000] reserved 1024KB for Class from
[0xced00000 - 0xcee00000] reserved 1024KB for Class from
大部分的为Class分配的进程空间都是1024KB的。
Reserved for Heap ( 总共只有1段)
例如:[0xd5a00000 - 0xe5a00000] reserved 262144KB for Java Heap from
简单演算一下:0xe5a00000-0xd5a00000=0x10000000=pow(2, 28)。很明显2的28方个比特就是256MB.
Reserved for Internal (总共只有1段)
例如:[0xf7762000 - 0xf776a000] reserved and committed 32KB for Internal from
Reserved for Thread Stack(总共有57段)
例如:[0xcf85e000 - 0xcf8af000] reserved and committed 324KB for Thread Stack from
从输出看,大部分的 Stack的地址空间都是324KB的,还有不少部分是516KB的。
Reserved for Code( 总共有2段 )
例如:[0xe5e00000 - 0xf4e00000] reserved 245760KB for Code from
这个地方用了好大的进程空间。后面,我们会在pmap的输出中找到它。它用了很大的Virtual Address Space, 但是RSS却相对比较小。
Reserved for Unknown( 总共有4 段)
例如: [0xf745d000 - 0xf747d000] reserved 128KB for Unknown from
Reserved for GC (总共有2段)
例如: [0xf737f000 - 0xf7400000] reserved 516KB for GC from
pmap的输出
使用命令行: pmap -p PID, 我们就可以得到对应进程的VSS&RSS信息。
pmap输出的中,我们把其中我们比较关心的部分列在下面:
START SIZE RSS PSS DIRTY SWAP PERM MAPPING
0000000008048000 4K 4K 4K 0K 0K r-xp /usr/java/jre1.8.0_65/bin/java
0000000008049000 4K 4K 4K 4K 0K rw-p /usr/java/jre1.8.0_65/bin/java
000000000804a000 74348K 71052K 71052K 71052K 0K rw-p [heap]
…
00000000ced00000 1024K 976K 976K 976K 0K rw-p [anon]
…
00000000d4eaf000 12K 0K 0K 0K 0K ---p [anon]
00000000d4eb2000 312K 28K 28K 28K 0K rwxp [stack:21151]
00000000d4f00000 1024K 1024K 1024K 1024K 0K rw-p [anon]
00000000d5000000 32K 32K 32K 0K 0K r-xp /usr/java/jre1.8.0_65/jre/lib/i386/libmanagement.so
00000000d5008000 4K 4K 4K 4K 0K rw-p /usr/java/jre1.8.0_65/jre/lib/i386/libmanagement.so
00000000d500d000 324K 24K 24K 24K 0K rwxp [stack:18608]
00000000d505e000 4376K 4376K 4376K 4376K 0K rw-p [anon]
00000000d54a4000 24K 0K 0K 0K 0K ---p [anon]
00000000d54aa000 92824K 92824K 92824K 92824K 0K rw-p [anon]
00000000daf50000 174784K 174784K 174784K 174784K 0K rw-p [anon]
00000000e5a40000 544K 544K 544K 544K 0K rw-p [anon]
00000000e5ac8000 3296K 0K 0K 0K 0K ---p [anon]
00000000e5e00000 34656K 34300K 34300K 34300K 0K rwxp [anon]
00000000e7fd8000 211104K 0K 0K 0K 0K ---p [anon]
00000000f4e00000 100K 60K 60K 0K 0K r-xp /usr/java/jre1.8.0_65/jre/lib/i386/libzip.so
00000000f4e19000 4K 4K 4K 4K 0K rw-p /usr/java/jre1.8.0_65/jre/lib/i386/libzip.so
00000000f4e5e000 648K 68K 68K 68K 0K rwxp [stack:18331]
00000000f4f00000 1024K 1024K 1024K 1024K 0K rw-p [anon]
…
Total: 735324K 482832K 479435K 462244K 0K
我们对几个重要部分的pmap输出一一作出分析,
- 000000000804a000: 该部分是Java进程的Heap区,此处的Heap指的不是Java那种特殊的Heap, 还是一个任何C/C++内存区域中Heap区。VSS和RSS差不多,都在70M上下。
- 00000000ced00000: 该区域就是用来存放class的。在NMT输出中可以找到对应项。Mapping那一栏是[anon], 因为pmap并不知道这部分区域是干什么用的,而直有JVM自己知道,所以, NMT的输出可以看出该内存区域的用处。
- 00000000d4eaf000 00000000d4eb2000: 这两部分合起来就是一个324K大小的Java Thread Stack。NTM输出中可以找到对应项。
- 00000000d54aa000, 00000000daf50000: 这两部分就非常重要的。它对应就是我们Java意义上的堆的那一部分。简单地讲,- 00000000daf50000那一块就是老年代(Java内存分布分析要以垃圾收集算法为前提)。00000000d54aa000这一部分包含了新生代。结合jstat –gc的输出可以得出这个结论。