记一次 JVM Young GC 排查经历

| 分类 java之内存管理  深入学习之编译原理  | 标签 Java  JVM  jps  jstat  jinfo  jmap  jstack  JConsole  jdb  堆外内存  GC  YGC  垃圾回收  pmap  pref  JVisualVM  jdb  jboss  堆内存  arthas  虚拟内存  物理内存  HotSpot  JVM参数  线程  调用栈  top  DirectByteBuffer  Dump  MAT 

测试环境上APP4 应用出现报警。APP4 是JBoss 的应用

监控:99.16.171.191 Ava memory percent:6 Lack of available memory on server 99.16.171.191 
内存剩余量小于阈值20%,且swap剩余量小于阈值80%,请联系开发确认是否为程序异常,请不要调整CPU内存等系统配置。。

收集基本信息

首先查看java 的版本信息

$ java -version

java version "1.8.0_191"
Java(TM) SE Runtime Environment (build 1.8.0_191-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.191-b12, mixed mode)

然后查看JVM 进程的信息,包括进程号、启动参数等。进程号是9706

$ ps -elf | grep jboss

0 S qappsom    9706   9571  1  80   0 - 1755183 futex_ Aug07 ?      04:00:59 /usr/java/jdk1.8.0_191-amd64/bin/java -D[Standalone] -XX:+UseCompressedOops -verbose:gc -Xloggc:/opt/jbshome/appserver/Server1/log/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=3M -XX:-TraceClassUnloading -server -Xms4096m -Xmx4096m -XX:NewSize=1024m -XX:MaxNewSize=1200m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/jbshome/jboss_dump/Server1-OOM-pid.hprof -Dorg.jboss.boot.log.file=/opt/jbshome/appserver/Server1/log/server.log -Dlogging.configuration=file:/opt/jbshome/appserver/Server1/configuration/logging.properties -jar /opt/jbshome/jboss-eap-6.4/jboss-modules.jar -mp /opt/jbshome/jboss-eap-6.4/modules -jaxpmodule javax.xml.jaxp-provider org.jboss.as.standalone -Djboss.home.dir=/opt/jbshome/jboss-eap-6.4 -Djboss.server.base.dir=/opt/jbshome/appserver/Server1 -Djboss.server.base.dir=/opt/jbshome/appserver/Server1/ --server-config=standalone.xml -Djboss.bind.address.management=99.16.171.191 -Djboss.bind.address=99.16.171.191 -Djboss.socket.binding.port-offset=0 -Djboss.node.name=Server1
0 S readuser 118879 116971  0  80   0 - 28178 pipe_w 16:25 pts/0    00:00:00 grep --color=auto jboss

查看这个进程的内存、CPU 信息。top 命令下,按e 可以切换内存的显示单位,byte、kb、mb、gb。VIRT: 虚拟内存占用6.695g;RES: 物理内存占用2.738g;CPU 占用才1%,而且确实没有什么请求进来,为什么会有这么多的内存占用呢?

$ top -p 9706

top - 16:27:24 up 166 days, 22:48,  2 users,  load average: 1.03, 0.64, 0.45
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  1.7 us,  2.2 sy,  0.0 ni, 96.0 id,  0.0 wa,  0.0 hi,  0.2 si,  0.0 st
KiB Mem :  3861520 total,    56216 free,  3279900 used,   525404 buff/cache
KiB Swap:  8388604 total,  6666748 free,  1721856 used.   208904 avail Mem
 
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  9706 qappsom   20   0  6.695g 2.738g 0.006g S   1.0 74.3 241:00.15 java

APP4 是分布式应用,看一下测试环境其他几个机器上应用的内存占用,也都是很高的。VIRT:6.695g,RES:2.653g

各种进程的内存对比分析

和其他的应用对比一下。APP1 也是jboss 应用,看一下APP1 的某个测试环境应用的内存占用

top - 17:00:12 up 64 days, 20:03,  1 user,  load average: 1.34, 0.61, 0.38
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  1.3 us,  3.2 sy,  0.0 ni, 95.4 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  3861512 total,    67976 free,  2413160 used,  1380376 buff/cache
KiB Swap:  8388604 total,  8224252 free,   164352 used.  1090488 avail Mem
 
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 82447 qappsom   20   0  4.480g 1.440g 0.021g S   0.7 39.1  22:03.83 java

再看一下非jboss 的JVM 应用,APP2。APP1、APP4 是运行在jboss 上JVM HTTP 应用,APP2 是独立运行的JVM TCP 应用,对外提供类似的服务,且都有对接Kafka 集群异步处理等模块,jboss 与非jboss 在一起也还是有对比性的!

top - 10:32:28 up 68 days, 13:36,  1 user,  load average: 0.29, 0.36, 0.40
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  2.5 us,  3.5 sy,  0.0 ni, 93.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  3861512 total,  1271056 free,  1672288 used,   918168 buff/cache
KiB Swap:  8388604 total,  8086168 free,   302436 used.  1808868 avail Mem
 
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 28744 qappsom   20   0  4.521g 0.728g 0.016g S   2.0 19.8   0:36.04 java

APP1、APP2、APP4 的启动参数分析

对比一下APP4 和APP1、APP2 的启动命令,使用ps -elf 可以查看

APP1

java -D[Standalone] -XX:+UseCompressedOops -verbose:gc -Xloggc:/opt/jbshome/appserver/zwsServer1/log/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=3M -XX:-TraceClassUnloading -server -Xms1932m -Xmx1932m -XX:NewSize=1024m -XX:MaxNewSize=1200m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/jbshome/jboss_dump/zwsServer1-OOM-20200818202853.hprof -Dorg.jboss.boot.log.file=/opt/jbshome/appserver/zwsServer1/log/server.log -Dlogging.configuration=file:/opt/jbshome/appserver/zwsServer1/configuration/logging.properties -jar /opt/jbshome/jboss-eap-6.4/jboss-modules.jar -mp /opt/jbshome/jboss-eap-6.4/modules -jaxpmodule javax.xml.jaxp-provider org.jboss.as.standalone -Djboss.home.dir=/opt/jbshome/jboss-eap-6.4 -Djboss.server.base.dir=/opt/jbshome/appserver/zwsServer1 -Djboss.server.base.dir=/opt/jbshome/appserver/zwsServer1/ --server-config=standalone.xml -Djboss.bind.address.management=99.16.18.103 -Djboss.bind.address=99.16.18.103 -Djboss.socket.binding.port-offset=0 -Djboss.node.name=zwsServer1

APP2

java -server -Xms1885m -Xmx1885m -cp XXXZ/xxxcld.jar com.tst.xxx.api.xxxcld.XXXCLD_APPStart com.tst.xxx.api.xxxolt.XXXOLT_APPStart APP2

APP4

java -D[Standalone] -XX:+UseCompressedOops -verbose:gc -Xloggc:/opt/jbshome/appserver/Server1/log/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=3M -XX:-TraceClassUnloading -server -Xms4096m -Xmx4096m -XX:NewSize=1024m -XX:MaxNewSize=1200m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/jbshome/jboss_dump/Server1-OOM-pid.hprof -Dorg.jboss.boot.log.file=/opt/jbshome/appserver/Server1/log/server.log -Dlogging.configuration=file:/opt/jbshome/appserver/Server1/configuration/logging.properties -jar /opt/jbshome/jboss-eap-6.4/jboss-modules.jar -mp /opt/jbshome/jboss-eap-6.4/modules -jaxpmodule javax.xml.jaxp-provider org.jboss.as.standalone -Djboss.home.dir=/opt/jbshome/jboss-eap-6.4 -Djboss.server.base.dir=/opt/jbshome/appserver/Server1 -Djboss.server.base.dir=/opt/jbshome/appserver/Server1/ --server-config=standalone.xml -Djboss.bind.address.management=99.16.171.191 -Djboss.bind.address=99.16.171.191 -Djboss.socket.binding.port-offset=0 -Djboss.node.name=Server1

其中APP1、APP2、APP4 的-Xms、-Xmx 参数明显不同,是否与此有关?

  • APP1: -Xms1932m -Xmx1932m
  • APP2: -Xms1885m -Xmx1885m
  • APP4: -Xms4096m -Xmx4096m

各项参数分析

  • -XX:+UseCompressedOops
  • -verbose:gc
  • -Xloggc:/opt/jbshome/appserver/Server1/log/gc.log GC日志文件的输出路径
  • -XX:+PrintGCDetails 输出GC的详细日志
  • -XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800)
  • -XX:+UseGCLogFileRotation 滚动记录GC日志
  • -XX:NumberOfGCLogFiles=5 GC日志文件个数
  • -XX:GCLogFileSize=3M GC日志文件大小
  • -XX:-TraceClassUnloading
  • -server
  • -Xms4096m 表示java虚拟机堆区内存初始内存分配的大小
  • -Xmx4096m 表示java虚拟机堆区内存可被分配的最大上限
  • -XX:NewSize=1024m 表示新生代初始内存的大小,应该小于-Xms的值
  • -XX:MaxNewSize=1200m 表示新生代可被分配的内存的最大上限;当然这个值应该小于-Xmx的值
  • -XX:MetaspaceSize=256m 元数据区的大小是256M
  • -XX:MaxMetaspaceSize=512m 元数据区的最大大小事512M
  • -XX:+HeapDumpOnOutOfMemoryError 当发生OOM错误时生成Dump文件
  • -XX:HeapDumpPath=/opt/jbshome/jboss_dump/zwsServer1-OOM-20200818202853.hprof 指定Dump文件的生成地址
  • -Djava.awt.headless=true
  • -Djboss.modules.system.pkgs=org.jboss.byteman
  • -Djboss.home.dir=/opt/jbshome/jboss-eap-6.4
  • -Djboss.server.base.dir=/opt/jbshome/appserver/Server1
  • -Djboss.server.base.dir=/opt/jbshome/appserver/Server1/
  • --server-config=standalone.xml 设置jboss启动使用的配置文件
  • -Djboss.bind.address.management=99.16.171.191
  • -Djboss.bind.address=99.16.171.191
  • -Djboss.socket.binding.port-offset=0
  • -Djboss.node.name=Server1

典型JVM 服务器配置有以下几种

情况一

-Xmx3800m -Xms3800m -Xmn2g -Xss128k -XX:+UseParallelGC -XX:ParallelGCThreads=20 
-XX:+UseParallelGC: 选择垃圾收集器为并行收集器。此配置仅对年轻代有效。即上述配置下,年轻代使用并发收集,而年老代仍旧使用串行收集
-XX:ParallelGCThreads=20: 配置并行收集器的线程数,即:同时多少个线程一起进行垃圾回收。此值最好配置与处理器数目相同 

情况二

-Xmx3550m -Xms3550m -Xmn2g -Xss128k -XX:+UseParallelGC -XX:ParallelGCThreads=20 -XX:+UseParallelOldGC 
-XX:+UseParallelOldGC: 配置年老代垃圾收集方式为并行收集。JDK6.0支持对年老代并行收集。 

情况三

-Xmx3550m -Xms3550m -Xmn2g -Xss128k -XX:+UseConcMarkSweepGC -XX:CMSFullGCsBeforeCompaction=5 -XX:+UseCMSCompactAtFullCollection 
-XX:CMSFullGCsBeforeCompaction: 由于并发收集器不对内存空间进行压缩、整理,所以运行一段时间以后会产生“碎片”,使得运行效率降低。此值设置运行多少次GC以后对内存空间进行压缩、整理
-XX:+UseCMSCompactAtFullCollection: 打开对年老代的压缩。可能会影响性能,但是可以消除碎片

使用JVisualVM 分析Dump 文件

在Linux 服务器上使用jmap 命令生成Dump 堆转储文件

$ jmap -dump:format=b,file=/tmp/dump.dat 9706

在测试环境生成Dump 转储文件后,导入到Windows 环境,使用用JVisualVM 分析,类名占用从大到小分别是

  • char[] 实例数2313351,12%;大小2.286G,59.4%
    • 在实例数Tab页,查看每个char[]数组的大小都是524302Byte = 0.5M,这是一个规律点
    • char[] 数组的大小是262143,在Java中每个字符是2Byte
    • 524302 - 262143 * 2 = 16,16Byte应该是存储数组的长度、类型等信息
  • byte[] 实例数1596454,8.3%;大小536.96M,13.6%
  • String 实例数1389782,7.2%;大小37M,0.9%
  • int[] 实例数1229689,6.4%;大小255.77M,6.5%
  • Object[] 实例数909068,4.7%;大小63.73M,1.6%
  • java.util.LinkedHashMap$Entry 实例数641537,3.3%;大小36.7M,0.9%
  • java.util.ArrayList 实例数628203,3.3%;大小19M,0.5%
  • java.util.HashMap$Node 实例数502367,2.6%;大小21M,0.5%
  • java.util.HashMap 实例数397476,2.1%;大小24M,0.6%
  • java.util.HashMap$Node 实例数394203,2.0%;大小58M,1.5%
  • oracle.jdbc.driver.T4CharAccessor 实例数168678,0.9%;大小48.9M,1.2%

其中char[] 多的离谱,在JVisualVM 的【类】页面,双击char[] 一行,进入【实例数】页面,因为数量太多,会加载的比较慢,稍等一下

看不出来是什么问题,在OQL 控制界面可以执行查询,可以查看具体的对象的内容,被谁引用等信息

select s from java.lang.String s
 
select c from char[] c

Dump 文件实在是太大了,JVisualVM 直接就卡死了…

GC 日志分析

回想到上面看到APP4 启动的时候有设置参数输出GC 日志的,去 /opt/jbshome/appserver/Server1/log/gc.log 查看GC 日志内容

...
2020-08-23T18:41:51.228+0800: 1387803.160: [GC (Allocation Failure) [PSYoungGen: 1212272K->5056K(1217024K)] 1916341K->713968K(4182528K), 0.1016167 secs] [Times: user=0.05 sys=0.00, real=0.10 secs]
2020-08-23T19:12:21.461+0800: 1389633.392: [GC (Allocation Failure) [PSYoungGen: 1210816K->6880K(1218048K)] 1919728K->718897K(4183552K), 0.0778163 secs] [Times: user=0.06 sys=0.00, real=0.07 secs]
2020-08-23T19:43:21.961+0800: 1391493.893: [GC (Allocation Failure) [PSYoungGen: 1213664K->5712K(1217536K)] 1925681K->722894K(4183040K), 0.1091475 secs] [Times: user=0.04 sys=0.01, real=0.11 secs]
2020-08-23T20:13:53.725+0800: 1393325.657: [GC (Allocation Failure) [PSYoungGen: 1212496K->8176K(1218048K)] 1929678K->729030K(4183552K), 0.0720464 secs] [Times: user=0.04 sys=0.01, real=0.07 secs]
2020-08-23T20:44:42.775+0800: 1395174.707: [GC (Allocation Failure) [PSYoungGen: 1215472K->3488K(1218048K)] 1936326K->730813K(4183552K), 0.1406177 secs] [Times: user=0.05 sys=0.00, real=0.14 secs]
2020-08-23T21:15:25.858+0800: 1397017.790: [GC (Allocation Failure) [PSYoungGen: 1210784K->7984K(1217024K)] 1938109K->736989K(4182528K), 0.0465405 secs] [Times: user=0.04 sys=0.00, real=0.05 secs]
2020-08-23T21:46:09.882+0800: 1398861.814: [GC (Allocation Failure) [PSYoungGen: 1214256K->5888K(1217536K)] 1943261K->741194K(4183040K), 0.1272709 secs] [Times: user=0.05 sys=0.02, real=0.12 secs]
2020-08-23T22:16:42.399+0800: 1400694.331: [GC (Allocation Failure) [PSYoungGen: 1212160K->6320K(1218560K)] 1947466K->745520K(4184064K), 0.0866131 secs] [Times: user=0.04 sys=0.01, real=0.09 secs]
2020-08-23T22:47:25.565+0800: 1402537.497: [GC (Allocation Failure) [PSYoungGen: 1214128K->6176K(1218048K)] 1953328K->749982K(4183552K), 0.1042474 secs] [Times: user=0.04 sys=0.00, real=0.10 secs]
2020-08-23T23:18:04.415+0800: 1404376.347: [GC (Allocation Failure) [PSYoungGen: 1213984K->7296K(1218560K)] 1957790K->755294K(4184064K), 0.1378852 secs] [Times: user=0.07 sys=0.00, real=0.14 secs]
2020-08-23T23:48:41.894+0800: 1406213.826: [GC (Allocation Failure) [PSYoungGen: 1215616K->5792K(1218560K)] 1963614K->759409K(4184064K), 0.1012862 secs] [Times: user=0.04 sys=0.01, real=0.10 secs]
2020-08-24T00:19:08.816+0800: 1408040.748: [GC (Allocation Failure) [PSYoungGen: 1214112K->7130K(1219072K)] 1967729K->764547K(4184576K), 0.0734753 secs] [Times: user=0.04 sys=0.00, real=0.07 secs]
2020-08-24T00:49:51.505+0800: 1409883.437: [GC (Allocation Failure) [PSYoungGen: 1216474K->5744K(1219072K)] 1973891K->768612K(4184576K), 0.1213085 secs] [Times: user=0.06 sys=0.01, real=0.12 secs]
2020-08-24T01:20:34.394+0800: 1411726.326: [GC (Allocation Failure) [PSYoungGen: 1215088K->8656K(1218048K)] 1977956K->775269K(4183552K), 0.1044698 secs] [Times: user=0.06 sys=0.01, real=0.10 secs]
2020-08-24T01:51:33.365+0800: 1413585.297: [GC (Allocation Failure) [PSYoungGen: 1216976K->4992K(1218560K)] 1983589K->778579K(4184064K), 0.1502979 secs] [Times: user=0.04 sys=0.01, real=0.15 secs]
2020-08-24T02:22:23.987+0800: 1415435.919: [GC (Allocation Failure) [PSYoungGen: 1213312K->7856K(1218560K)] 1986899K->784484K(4184064K), 0.0690054 secs] [Times: user=0.05 sys=0.01, real=0.07 secs]
2020-08-24T02:53:16.409+0800: 1417288.341: [GC (Allocation Failure) [PSYoungGen: 1216176K->5216K(1218560K)] 1992804K->788009K(4184064K), 0.2007110 secs] [Times: user=0.06 sys=0.02, real=0.20 secs]
2020-08-24T03:23:56.652+0800: 1419128.583: [GC (Allocation Failure) [PSYoungGen: 1213536K->7088K(1218560K)] 1996329K->793169K(4184064K), 0.0699469 secs] [Times: user=0.04 sys=0.00, real=0.07 secs]
2020-08-24T03:54:06.774+0800: 1420938.706: [GC (Allocation Failure) [PSYoungGen: 1215408K->5760K(1218560K)] 2001489K->797228K(4184064K), 0.1057941 secs] [Times: user=0.04 sys=0.01, real=0.10 secs]
2020-08-24T04:24:45.699+0800: 1422777.631: [GC (Allocation Failure) [PSYoungGen: 1214080K->8096K(1218048K)] 2005548K->803364K(4183552K), 0.0929450 secs] [Times: user=0.07 sys=0.01, real=0.10 secs]
2020-08-24T04:55:14.407+0800: 1424606.339: [GC (Allocation Failure) [PSYoungGen: 1216416K->5904K(1218560K)] 2011684K->807585K(4184064K), 0.1614329 secs] [Times: user=0.06 sys=0.02, real=0.16 secs]
2020-08-24T05:26:03.832+0800: 1426455.763: [GC (Allocation Failure) [PSYoungGen: 1214224K->8624K(1218048K)] 2015905K->814169K(4183552K), 0.2242565 secs] [Times: user=0.14 sys=0.01, real=0.22 secs]
2020-08-24T05:56:54.237+0800: 1428306.169: [GC (Allocation Failure) [PSYoungGen: 1216944K->3104K(1211904K)] 2022489K->815560K(4177408K), 0.1386225 secs] [Times: user=0.05 sys=0.01, real=0.14 secs]
2020-08-24T06:27:31.190+0800: 1430143.122: [GC (Allocation Failure) [PSYoungGen: 1211424K->8256K(1218048K)] 2023880K->822072K(4183552K), 0.0531420 secs] [Times: user=0.06 sys=0.01, real=0.06 secs]
2020-08-24T06:58:39.529+0800: 1432011.461: [GC (Allocation Failure) [PSYoungGen: 1215552K->4896K(1218048K)] 2029368K->825267K(4183552K), 0.1409707 secs] [Times: user=0.04 sys=0.01, real=0.14 secs]
2020-08-24T07:29:14.652+0800: 1433846.584: [GC (Allocation Failure) [PSYoungGen: 1212192K->8640K(1217024K)] 2032563K->831979K(4182528K), 0.0748562 secs] [Times: user=0.05 sys=0.00, real=0.07 secs]
2020-08-24T07:59:56.211+0800: 1435688.143: [GC (Allocation Failure) [PSYoungGen: 1214912K->4512K(1217536K)] 2038251K->834764K(4183040K), 0.1720133 secs] [Times: user=0.06 sys=0.02, real=0.17 secs]
2020-08-24T08:30:13.670+0800: 1437505.602: [GC (Allocation Failure) [PSYoungGen: 1210784K->8320K(1217536K)] 2041036K->841228K(4183040K), 0.0624815 secs] [Times: user=0.05 sys=0.00, real=0.07 secs]
2020-08-24T09:01:03.894+0800: 1439355.826: [GC (Allocation Failure) [PSYoungGen: 1214592K->4832K(1217536K)] 2047500K->844405K(4183040K), 0.1898080 secs] [Times: user=0.05 sys=0.02, real=0.19 secs]
2020-08-24T09:31:51.869+0800: 1441203.801: [GC (Allocation Failure) [PSYoungGen: 1211104K->9152K(1216512K)] 2050677K->851629K(4182016K), 0.0598782 secs] [Times: user=0.05 sys=0.01, real=0.06 secs]

可以看出来,GC 的时间还是很频繁的,且每次变动的幅度基本一致。基本是半小时一次,比如最后一条

2020-08-24T09:31:51.869+0800: 1441203.801: [GC (Allocation Failure) [PSYoungGen: 1211104K->9152K(1216512K)] 2050677K->851629K(4182016K), 0.0598782 secs] [Times: user=0.05 sys=0.01, real=0.06 secs]

[GC (Allocation Failure) [PSYoungGen: 1211104K->9152K(1216512K)]

  1. GC表示一次YGC(Young GC),另外一个FGC 表示Full GC
  2. Allocation Failure 表示是失败的类型
  3. 1211104K->9152K 表示年轻代从1211104K 降为9152K。从1G 降低为9M,这个变化明显很剧烈。这里明显是一个问题点!
  4. 1216512K 表示年轻代的大小。1188M
  5. 2050677K->851629K 表示整个堆占用从2050677K 降为851629K。从1.96G 降低为831M
  6. 4182016K 表示整个堆的大小。4084M,和参数-Xms4096m、-Xmx4096m 基本一致
  7. 0.0598782 secs 表示这次GC总计所用的时间
  8. [Times: user=0.05 sys=0.01, real=0.06 secs] 分别表示,用户态占用时长,内核用时,真实用时

参数-Xms4096m、-Xmx4096m 设置堆大小 为4096M,刚好和GC 日志中打印的堆大小4182016K = 4084M 基本吻合,剩下的部分是不是元数据区存储空间?

另外,在没有参数明确指定的情况下,堆中Old 和 Young 的比例是 3: 1,刚好GC 日志中年轻代是1216512K = 1188M,基本就是对大小的1/4

另外,默认Young 区中,Eden:S0:S1 = 8:1:1,所以Eden 区应该是950M,S0和S1都是118.8M

其他还有一些具体的问题

  • 以上是对堆内存转储文件的处理,栈内存转储文件呢?
  • APP4 进程的Eden、S0、S1、Old、堆外内存没有进行分别分析
  • APP4 使用的什么垃圾回收器?年轻代、老年代分别是什么?
  • 堆外内存怎么分析?
  • char[]、byte[]到底位于哪块内存?
  • char[]、byte[]到底存储了什么内容?
  • char[]、byte[]到底是被谁申请、被谁引用的?
  • top 显示APP4这个进程的虚拟内存是6928M,但是GC 日志中显示堆内存是4084M,差出来的内存是哪里的内存?堆外内存?
  • GC 日志中每次回收1G多的垃圾,这些垃圾都是哪些对象?知道这个信息将很有助于排查问题
  • 需要实时监控APP4进程,查看内存的变化曲线,GC日志中显示30分钟GC一次,那这30分钟的内存变化曲线是什么样的?
  • 怎么查看哪些类被垃圾回收了?
  • 需要试着调整APP4启动的各个参数,看各个参数对JVM进程内存的影响!
  • APP4 是JBoss 的应用,是不是和JBoss 有关?
  • 上面的分析思路还是分析不出来,怎么办?
  • 尝试在一个高权限环境部署APP4,然后在线对APP4 进行分析
  • 在高权限环境,可以直接用arthas 进行分析

相关文章

查看APP4 使用的垃圾收集器

根据APP4 的启动参数,可以看到是没有指定使用了什么垃圾回收器的,所以就是默认的垃圾回收器

$ java -XX:+PrintCommandLineFlags -version
-XX:InitialHeapSize=61784320 -XX:MaxHeapSize=988549120 -XX:+PrintCommandLineFlags -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
java version "1.8.0_191"
Java(TM) SE Runtime Environment (build 1.8.0_191-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.191-b12, mixed mode)
 
 
// -heap 打印heap的概要信息,GC使用的算法,heap的配置及wise heap的使用情况
$ jmap -heap pid
...
using thread-local object allocation.
Parallel GC with 2 thread(s)
...

这里列一下不同参数对应的垃圾回收器组合

  • -XX:+UseParallelGC 虚拟机运行在server模式下的默认值,打开此开关后,使用Parallel Scavenge + Serial Old(PS MarkSweep)
  • -XX:+UserSerialGC 虚拟机运行在client模式下的默认值,打开此开关后,使用Serial + Serial Old
  • -XX:+UseParNewGC 使用ParNew + Serial Old
  • -XX:+UseConcMarkSweepGC 使用ParNew + CMS + Serial Old 组合,Serial Old 作为CMS 出现Concurrent Mode Failure 失败后的备用回收器使用
  • -XX:+UseParallelOldGC 使用Parallel Scavenge + Parallel Old

对于我现在正在分析的这个进程,使用的是Parallel Scavenge + Serial Old(PS MarkSweep)

在高权限环境复现问题

测试环境没有权限,将APP4 部署到高权限机器上

tail -f /opt/jbshome/appserver/Server1/log/APP4-gc.log.0.current 实时监控GC日志

另外,和测试环境的APP4分别进行对比,首先查看top 监控

测试环境

$ top -p 9706
top - 16:23:48 up 170 days, 22:44,  1 user,  load average: 0.28, 0.40, 0.42
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  1.2 us,  1.6 sy,  0.0 ni, 97.2 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  3861520 total,    56460 free,  3272616 used,   532444 buff/cache
KiB Swap:  8388604 total,  6277512 free,  2111092 used.   207576 avail Mem
 
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  9706 qappsom   20   0  6.766g 2.699g 0.004g S   0.8 73.3 308:13.08 java


对比环境
# top -p 39086
top - 16:24:13 up 172 days,  6:53,  3 users,  load average: 0.09, 0.22, 0.26
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.5 us,  1.2 sy,  0.0 ni, 98.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  3861512 total,   141900 free,  1749056 used,  1970556 buff/cache
KiB Swap:  8388604 total,  8369304 free,    19300 used.  1744816 avail Mem
 
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 39086 root      20   0  6.610g 0.350g 0.019g S   0.0  9.5   0:10.37 java

再去比较一下对象实例情况,之前统计的测试环境

  • char[] 实例数2313351,12%;大小2.286G,59.4% * 在实例数Tab页,查看每个char[]数组的大小都是524302Byte = 0.5M,这是一个规律点 * 这些char[] 数组的大小是262143,在Java中每个字符是2Byte * 524302 - 262143 * 2 = 16,16Byte应该是存储数组的长度、类型等信息
  • byte[] 实例数1596454,8.3%;大小536.96M,13.6% * 在实例数Tab页,查看每个byte[]数组的大小都是65560Byte = 64K,这是一个规律点 * 这些byte[] 数组的大小是65536,在Java中每个字符是1Byte * 65560 - 65536 = 24,24Byte应该是存储数组的长度、类型等信息?
  • String 实例数1389782,7.2%;大小37M,0.9%
  • int[] 实例数1229689,6.4%;大小255.77M,6.5%
  • Object[] 实例数909068,4.7%;大小63.73M,1.6%
  • java.util.LinkedHashMap$Entry 实例数641537,3.3%;大小36.7M,0.9%
  • java.util.ArrayList 实例数628203,3.3%;大小19M,0.5%
  • java.util.HashMap$Node 实例数502367,2.6%;大小21M,0.5%
  • java.util.HashMap 实例数397476,2.1%;大小24M,0.6%
  • java.util.HashMap$Node 实例数394203,2.0%;大小58M,1.5%
  • oracle.jdbc.driver.T4CharAccessor 实例数168678,0.9%;大小48.9M,1.2%

现在复现问题进行排查的高权限开发环境,实例数存在明显的差别!使用jmap 命令可以查看

# jmap -F -histo 39086
 
 num     #instances         #bytes  class name
----------------------------------------------
   1:         87045      553341424  [I       527M
   2:         64934       42325248  [B       40M
   3:        245479       31976744  [C       30M
   4:        172053        4129272  java.lang.String
   5:         85882        3435280  java.util.LinkedHashMap$Entry
   6:        102516        3280512  java.util.HashMap$Node
   7:         27706        3123432  [Ljava.util.HashMap$Node;
   8:         35042        2242688  java.util.regex.Matcher
   9:         22359        2146464  java.util.jar.JarFile$JarFileEntry
  10:         39208        1878240  [Ljava.lang.Object;
  11:         22277        1782160  java.util.zip.ZipEntry
  12:         33078        1058496  org.jboss.as.controller.PathElement
  13:          8072         920744  java.lang.Class
  14:         16858         809184  java.util.HashMap
  15:         32090         770160  java.util.ArrayList
  16:         31406         753744  org.jboss.dmr.ModelNode
  17:         13347         747432  java.util.LinkedHashMap
  18:          7615         670120  java.lang.reflect.Method
  19:         20491         655712  java.util.ArrayList$Itr
  20:         19146         612672  org.jboss.as.controller.registry.AbstractModelResource$1
  21:         13042         521680  java.lang.ref.Finalizer
  22:         17495         419880  java.util.Collections$UnmodifiableCollection$1
  23:         12414         397248  java.util.ArrayList$ListItr
  24:         14877         357048  java.lang.StringBuilder
  25:          8767         350680  java.util.HashMap$KeyIterator
  26:          5710         319760  java.util.zip.ZipFile$ZipFileInputStream
  27:          5709         319704  java.util.zip.ZipFile$ZipFileInflaterInputStream
  28:          8322         266304  java.util.LinkedHashMap$LinkedKeyIterator
  29:          7644         244608  java.util.RegularEnumSet
  30:          3371         242712  java.util.regex.Pattern
  31:         10599         236592  [Ljava.lang.Class;
  32:          4546         229144  [Ljava.lang.String;

完善问题列表

  • 以上是对堆内存转储文件的处理,栈内存转储文件呢?
  • APP4 进程的Eden、S0、S1、Old、堆外内存没有进行分别分析
  • APP4 使用的什么垃圾回收器?年轻代、老年代分别是什么?
  • 堆外内存怎么分析?
  • char[]、byte[] 到底位于哪块内存?
  • char[]、byte[] 到底存储了什么内容?
  • char[]、byte[] 到底是被谁申请、被谁引用的?
  • top 显示APP4 这个进程的虚拟内存是6928M,但是GC 日志中显示堆内存是4084M,差出来的内存是哪里的内存?堆外内存?
  • GC 日志中每次回收1G 多的垃圾,这些垃圾都是哪些对象?知道这个信息将很有助于排查问题
  • 需要实时监控APP4 进程,查看内存的变化曲线,GC 日志中显示30分钟GC 一次,那这30分钟的内存变化曲线是什么样的?
  • 怎么查看哪些类被垃圾回收了?
  • 需要试着调整APP4 启动的各个参数,看各个参数对JVM 进程内存的影响!
  • APP4 是JBoss 的应用,是不是和JBoss 有关?
  • 上面的分析思路还是分析不出来,怎么办?
  • 尝试在一个高权限环境部署APP4,然后在线对APP4进行分析
  • 在高权限环境,可以直接用arthas 进行分析
  • 发现ST环境的APP4内存持续在1.3左右,而搭建的对比环境没有这个问题,这个估计也是一个突破口

线程分析

ps -T -p 9706。查看线程信息,但是对于Java 进程,这个命令输出的线程信息很少,明确的线程名都没有

top 命令查看9706 进程内部所有线程的情况,发现CPU占用高的线程是这几个

# top -H -p 9706
   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
  9717 qappsom   20   0 7094748 2.665g   4848 S  0.3 72.4  29:56.92 java
  9884 qappsom   20   0 7094748 2.665g   4848 S  0.3 72.4  85:29.55 java
  9887 qappsom   20   0 7094748 2.665g   4848 S  0.3 72.4   1:44.94 java
  9886 qappsom   20   0 7094748 2.628g   5712 S  0.3 71.4  60:40.16 java
  9752 qappsom   20   0 7094748 2.628g   5712 S  0.0 71.4   4:59.58 java
...

接下来需要看一下这几个线程是什么线程

$ jstack 9706

// 定时任务
Thread 9887: (state = BLOCKED)
 - java.lang.Thread.sleep(long) @bci=0 (Compiled frame; information may be imprecise)
 - com.tst.xxx.api.xxxscd.XXXTSK_IntervlTask.delay(int) @bci=27, line=201 (Compiled frame)
 - com.tst.xxx.api.xxxscd.XXXTSK_IntervlTask.run() @bci=167, line=96 (Compiled frame)
 
 
// Kafka消费者
Thread 9884: (state = IN_NATIVE)
 - sun.nio.ch.EPollArrayWrapper.epollWait(long, int, long, int) @bci=0 (Compiled frame; information may be imprecise)
 - sun.nio.ch.EPollArrayWrapper.poll(long) @bci=18, line=269 (Compiled frame)
 - sun.nio.ch.EPollSelectorImpl.doSelect(long) @bci=28, line=93 (Compiled frame)
 - sun.nio.ch.SelectorImpl.lockAndDoSelect(long) @bci=37, line=86 (Compiled frame)
 - sun.nio.ch.SelectorImpl.select(long) @bci=30, line=97 (Compiled frame)
 - org.apache.kafka.common.network.Selector.select(long) @bci=35, line=689 (Compiled frame)
 - org.apache.kafka.common.network.Selector.poll(long) @bci=191, line=409 (Compiled frame)
 - org.apache.kafka.clients.NetworkClient.poll(long, long) @bci=72, line=510 (Compiled frame)
 - org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient.poll(long, long, org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient$PollCondition, boolean) @bci=89, line=271 (Compiled frame)
 - org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient.poll(long, long, org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient$PollCondition) @bci=6, line=242 (Compiled frame)
 - org.apache.kafka.clients.consumer.KafkaConsumer.pollForFetches(long) @bci=90, line=1247 (Compiled frame)
 - org.apache.kafka.clients.consumer.KafkaConsumer.poll(long, boolean) @bci=158, line=1187 (Compiled frame)
 - org.apache.kafka.clients.consumer.KafkaConsumer.poll(java.time.Duration) @bci=6, line=1154 (Compiled frame)
 - com.tst.kafka.client.consumer.KafkaConsumer.poll(java.time.Duration) @bci=2, line=74 (Compiled frame)
 - com.tst.xxx.api.xxxkfk.XXXKFK_MsgReceiver.receive() @bci=51, line=74 (Compiled frame)
 - com.tst.xxx.api.xxxmnv.xxxMNV_Monitor.execute(com.tst.xxx.api.xxxque.xxxQUE_MsgReceiver, com.tst.xxx.api.xxxque.xxxQUE_MsgSender) @bci=1, line=83 (Compiled frame)
 - com.tst.xxx.api.xxxmnv.xxxMNV_QueMsgHdl.run() @bci=22, line=99 (Compiled frame)
 
 
// Unsafe和堆外内存有关,这个是jboss的线程
Thread 9752: (state = BLOCKED)
 - sun.misc.Unsafe.park(boolean, long) @bci=0 (Compiled frame; information may be imprecise)
 - java.util.concurrent.locks.LockSupport.parkNanos(java.lang.Object, long) @bci=20, line=215 (Compiled frame)
 - java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(long) @bci=78, line=2078 (Compiled frame)
 - java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take() @bci=124, line=1093 (Compiled frame)
 - java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take() @bci=1, line=809 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor.getTask() @bci=149, line=1074 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker) @bci=26, line=1134 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=5, line=624 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=748 (Interpreted frame)
 - org.jboss.threads.JBossThread.run() @bci=10, line=122 (Interpreted frame)
 
 
// Kafka消费者
Thread 9886: (state = IN_NATIVE)
 - sun.nio.ch.EPollArrayWrapper.epollWait(long, int, long, int) @bci=0 (Compiled frame; information may be imprecise)
 - sun.nio.ch.EPollArrayWrapper.poll(long) @bci=18, line=269 (Compiled frame)
 - sun.nio.ch.EPollSelectorImpl.doSelect(long) @bci=28, line=93 (Compiled frame)
 - sun.nio.ch.SelectorImpl.lockAndDoSelect(long) @bci=37, line=86 (Compiled frame)
 - sun.nio.ch.SelectorImpl.select(long) @bci=30, line=97 (Compiled frame)
 - org.apache.kafka.common.network.Selector.select(long) @bci=35, line=689 (Compiled frame)
 - org.apache.kafka.common.network.Selector.poll(long) @bci=191, line=409 (Compiled frame)
 - org.apache.kafka.clients.NetworkClient.poll(long, long) @bci=72, line=510 (Compiled frame)
 - org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient.poll(long, long, org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient$PollCondition, boolean) @bci=89, line=271 (Compiled frame)
 - org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient.poll(long, long, org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient$PollCondition) @bci=6, line=242 (Compiled frame)
 - org.apache.kafka.clients.consumer.KafkaConsumer.pollForFetches(long) @bci=90, line=1247 (Compiled frame)
 - org.apache.kafka.clients.consumer.KafkaConsumer.poll(long, boolean) @bci=158, line=1187 (Compiled frame)
 - org.apache.kafka.clients.consumer.KafkaConsumer.poll(java.time.Duration) @bci=6, line=1154 (Compiled frame)
 - com.tst.kafka.client.consumer.KafkaConsumer.poll(java.time.Duration) @bci=2, line=74 (Compiled frame)
 - com.tst.xxx.api.xxxkfk.XXXKFK_MsgReceiver.receive() @bci=51, line=74 (Compiled frame)
 - com.tst.xxx.api.xxxasy.XXXASY_MsgHandler.run() @bci=37, line=47 (Compiled frame)

研究一下堆外内存

堆外(OffHeapStore)存储:被称为BigMemory,只在企业版本的Ehcache 中提供,原理是利用NIO 的DirectByteBuffers 实现,比存储到磁盘上快,而且完全不受GC 的影响,可以保证响应时间的稳定性;但Direct Buffer 的在分配上的开销要比Heap Buffer 大,而且要求必须以字节数组方式存储,因此对象必须在存储过程中进行序列化,读取则进行反序列化操作,它的速度大约比堆内存储慢一个数量级

Direct Buffer 不受GC 影响,但是Direct Buffer 归属的的Java 对象是在堆上且能够被GC 回收的,一旦它被回收,JVM 将释放Direct Buffer 的堆外空间

堆外内存,其实就是不受JVM 控制的内存。相比于堆内内存有几个优势:

  1. 减少了垃圾回收的工作,因为垃圾回收会暂停其他的工作(可能使用多线程或者时间片的方式,根本感觉不到)
  2. 加快了复制的速度。因为堆内在flush到远程时,会先复制到直接内存(非堆内存),然后在发送;而堆外内存相当于省略掉了这个工作
  3. 可以在进程间共享,减少JVM间的对象复制,使得JVM的分割部署更容易实现
  4. 可以扩展至更大的内存空间。比如超过1TB甚至比主存还大的空间

而福之祸所依,自然也有不好的一面:

  1. 堆外内存难以控制,如果内存泄漏,那么很难排查
  2. 堆外内存相对来说,不适合存储很复杂的对象。一般简单的对象或者扁平化的比较适合

Direct Memory 的回收机制:Direct Memory 是受GC控制的,例如ByteBuffer bb = ByteBuffer.allocateDirect(1024),这段代码的执行会在堆外占用1k的内存,Java 堆内只会占用一个对象的指针引用的大小,堆外的这1k的空间只有当bb对象被回收时,才会被回收,这里会发现一个明显的不对称现象,就是堆外可能占用了很多,而堆内没占用多少,导致还没触发GC,那就很容易出现Direct Memory 造成物理内存耗光。

ByteBuffer 与Unsafe 使用堆外内存在回收时的不同:

Direct ByteBuffer 分配出去的直接内存其实也是由GC 负责回收的,而不像Unsafe 是完全自行管理的,Hotspot 在GC 时会扫描Direct ByteBuffer 对象是否有引用,如没有则同时也会回收其占用的堆外内存

堆外内存回收的几种方法:

Full GC,一般发生在年老代垃圾回收以及调用System.gc的时候,但这样不一顶能满足我们的需求。 调用ByteBuffer的cleaner的clean(),内部还是调用System.gc(),所以一定不要-XX:+DisableExplicitGC

再说说”hello”和new String(“hello”)的区别:

如果是”hello”,JVM会先去共享的字符串池中查找,有没有”hello”这个词,如果有直接返回它的引用;如果没有,就会创建这个对象,再返回。因此,”a”+”b”相当于存在3个对象,分别是”a”、”b”、”ab”。

而new String(“hello”),则省去了查找的过程,直接就创建一个hello的对象,并且返回引用。

jstat 实时分析垃圾回收

# jstat -gc 9706 1000 1000

S0C     S1C      S0U   S1U     EC        EU       OC         OU         MC      MU      CCSC    CCSU      YGC   YGCT     FGC    FGCT    GCT   
13824.0 13824.0  0.0   13457.0 1201152.0 115464.0 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 115464.0 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 116715.5 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 118353.7 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 119433.1 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 119435.4 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 119435.4 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 119435.4 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 119435.4 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 120378.5 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 120538.0 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 120777.0 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 120777.0 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 120777.0 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 121704.1 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 128417.1 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 128417.1 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 128417.1 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13824.0 13824.0  0.0   13457.0 1201152.0 128417.1 2965504.0  1075262.9  81536.0 75816.5 10112.0 8363.9    839   55.434   1      5.591   61.025
13.5M   13.5M    0     13.1M   1.15G     125.4M   2.82G      1.03G      79.6M   74M
  • S0C/S0U survivor0容量和使用
  • S1C/S1U survivor1容量和使用
  • EC/EU Eden
  • MC/MU 方法区
  • CCSC/CCSU jdk8是meta,以前应该是PC/PC
  • YGC/YGCT young gc次数和耗时
  • FGC/FCGT full gc次数和耗时
  • GCT total gc时间

补充一个堆外内存溢出的案例

环境:

基于B\S的点子考试系统,为了发现客户端能实时地从服务端接收考试数据,系统使用了逆向AJAX技术(也称Comet或Server Side Push),选用CometD1.1.1作为服务端推送框架,服务器是Jetty7.1.4,硬件为一台普通PC机,Core i5 CPU,4G内存,运行32位Windows操作系统。

说明:

测试期间发现服务端不定时抛出内存溢出异常,服务器不一定每次都会出现异常,但是假如正式考试时奔溃一次,那估计整场考试都会全乱套,网站管理员尝试过把堆开到最大,32位系统最多到1.6GB基本无法再加大了,而且开大量也基本没效果,抛出

内存溢出异常好像更加繁琐了。加入-XX:+HeapDumpOnOutOfMemoryError,居然也没有任何反应,抛出内存溢出异常时什么文件都没产生。无奈之下只好挂着jstat使劲盯屏幕,发现GC并不频繁,Eden区,Survivor区,老年代及拥挤代内存全部

表示”情绪稳定,压力不大”,但是照样不停的抛出内存溢出异常,管理员鸭梨很大。最后,在内存溢出后从系统日志中找到异常堆栈。

分析:

大家都知道操作系统对每个进程能管理的内存是有限的,这台服务器使用的32位Windows平台的限制是2GB,其中给了Java堆1.6GB,而Direct Memory 并不算在1.6GB的堆之内,因此它只能在剩余的0.4GB空间分出一部分。在此应用中导致内

存溢出的关键是:垃圾收集进行时,虚拟机虽然会对Direct Memory进行回收,但是Direct Memory 却不能像新生代和老年代那样,发现空间不足了就通知收集器进行垃圾回收,他只能等到抛出内存溢出异常时,先catch掉,再在catch块里面“大喊”

“System.gc”.要是虚拟机还是不听(如:打开了-XX:+DisableExplicitGC开关),那就只能眼睁睁地看着堆中还有许多空闲内存,自己却不得不抛出内存异常了。而本案例中使用的Comet1.1.1框架,正好有大量的NIO操作需要用到Direct Memory。

总结:

从实践经验来看,除了java堆和永久代之外,我们注意到下面这些区域也会占用较多的内存,这里所有的内存总和会受到操作系统进程最大内存的限制:

  1. Direct Memory:可以通过-XX:MaxDirectMemorySize 调整大小,内存不足时抛出OutOfMemoryError 或OutOfMemoryError:Direct buffer memory
  2. 线程堆栈:可通过-Xss 调整大小内存不足时抛出StackoverflowError(纵向无法分配,即无法分配新的栈帧)或OutOfMemoryError:unable to create new native thread(横向无法分配,即无法建立新的线程)
  3. Socket 缓存区:每个Socket 连接都Receive 和Send 两个缓存区,分别占大约37KB和25KB的内存,连接多的话这块内存占用也比较可观。如果无法分配,则可能会抛出IOException:Too many open files 异常
  4. JNI 代码:如果代码中使用JNI调用本地库,那么本地库使用内存也不在堆中
  5. 虚拟机和GC:虚拟机和GC的代码执行也要消耗一定的内存

发生GC 时候的JVM 堆上对象

观察GC日志,当出现下面这种说明发生了GC

2020-08-25T11:11:34.533+0800: 1533586.464: [GC (Allocation Failure) [PSYoungGen: 1214608K->5824K(1212928K)] 2289871K->1085956K(4178432K), 0.1200154 secs] [Times: user=0.05 sys=0.01, real=0.12 secs]
 

对应看一下各个时间点的jmap -F -histo 9706 信息

// 11:20
num       #instances    #bytes  Class description
--------------------------------------------------------------------------
1:              789664  879090280=838M  char[]
2:              543249  198258896=189M  byte[]
3:              430143  95220888=90.8M  int[]
4:              319176  13526952=12.9M  java.lang.Object[]
5:              57898   12969152=12.4M  oracle.jdbc.driver.T4CCharAccessor
6:              481587  11558088=11M    java.lang.String
7:              136817  11374704=11M    java.util.HashMap$Node[]

 
// 11:40
num       #instances    #bytes  Class description
--------------------------------------------------------------------------
1:              2209766 1020227384 = 973M       char[]
2:              1603708 318106976 = 303.4M      byte[]
3:              744211  275194600       int[]
4:              1157951 48321896        java.lang.Object[]
5:              515510  42128648        java.util.HashMap$Node[]
6:              831407  33256280        java.util.LinkedHashMap$Entry
7:              1080658 25935792        java.lang.String
8:              498405  23923440        java.util.HashMap
9:              650606  20819392        java.util.HashMap$Node
10:             358012  20048672        java.util.LinkedHashMap

在堆内存层面,基本可以确定是char[]、byte[] 导致的内存问题,为什么byte[]、char[] 会频繁申请和释放呢?

还是要优先看一下这些char[]、byte[] 是在哪里申请的?是哪些类中的引用?

JVM 对象查询语言(OQL)

MAT(Memory Analyzer Tool)内存分析工具

下载独立的Memory Analyzer (MAT) 工具:https://www.eclipse.org/mat/

下载结果是一个zip包,解压之后直接运行即可

注意MAT 的版本要与你机器上的JDK 版本保持一致,比如都得是32 位的。然后使用MAT 打开Dump 堆转储文件

Shallow Heap 表示对象本身占用内存的大小,不包含对其他对象的引用,也就是对象头加成员变量(不是成员变量的值)的总和

Retained Heap 是该对象自己的Shallow Heap,并加上从该对象能直接或间接访问到对象的Shallow Heap之和。换句话说,Retained Heap是该对象GC之后所能回收到内存的总和。

一些疑问

  • 好像MAT的Histogram 显示的类都是GCRoot 可达的对象,好像不包括垃圾信息!?
  • 因为在MAT的Histogram 查看到的char[] 的大小只有14M,远远小于Java Visual VM显示的1G多
  • 按照看到的GC 日志,确实每次Young GC 的时候,大量的char[] 对象都被回收了!
  • 在Histogram 中可以看到对象的内容,可以右键对象去查看对象的树状层次引用关系
  • 在MAT 中能不能看到Dump 中的垃圾?

对比其他应用的GC 情况

再去看APP4 的测试环境的其他实例的GC 日志信息(这些应用都是多实例的分布式应用),也都是类似这种的,基本每30 分钟一次GC

2020-08-25T17:33:20.157+0800: 1118578.476: [GC (Allocation Failure) [PSYoungGen: 1215280K->5920K(1219584K)] 3500777K->2294137K(4185088K), 0.0395195 secs] [Times: user=0.07 sys=0.00, real=0.04 secs]
2020-08-25T18:03:10.408+0800: 1120368.728: [GC (Allocation Failure) [PSYoungGen: 1216800K->4352K(1220096K)] 3505017K->2297042K(4185600K), 0.0366397 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]
2020-08-25T18:32:51.838+0800: 1122150.158: [GC (Allocation Failure) [PSYoungGen: 1215744K->6032K(1220096K)] 3508434K->2301442K(4185600K), 0.0387554 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]

再去看测试环境环境其他APP1 应用的GC 日志,也是类似的

2020-08-25T15:41:59.604+0800: 436270.325: [GC (Allocation Failure) [PSYoungGen: 1224576K->2352K(1225216K)] 1316311K->94847K(1974784K), 0.0130409 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2020-08-25T16:49:49.006+0800: 440339.728: [GC (Allocation Failure) [PSYoungGen: 1223984K->2352K(1225216K)] 1316479K->95431K(1974784K), 0.0151846 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
2020-08-25T17:58:08.362+0800: 444439.083: [GC (Allocation Failure) [PSYoungGen: 1223984K->2384K(1225216K)] 1317063K->96048K(1974784K), 0.0119513 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

再去看APP1 和APP4 的内存占用,top 命令

// APP1
$ top -p 63694
top - 18:50:13 up 446 days,  8:37,  1 user,  load average: 0.04, 0.15, 0.15
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.8 us,  1.3 sy,  0.0 ni, 97.8 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  3865308 total,   140696 free,  2671856 used,  1052756 buff/cache
KiB Swap:  8388604 total,  8018164 free,   370440 used.   818800 avail Mem
 
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 63694 qappsom   20   0  4.475g 1.469g 0.008g S   0.7 39.9  34:19.91 java
 
 
 
// APP4
$ top -p  72439
top - 18:49:54 up 39 days, 22:53,  1 user,  load average: 1.34, 1.04, 0.75
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  1.7 us,  2.7 sy,  0.0 ni, 95.5 id,  0.2 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  3861512 total,    82064 free,  3126368 used,   653080 buff/cache
KiB Swap:  8388604 total,  6397528 free,  1991076 used.   374536 avail Mem
 
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 72439 qappsom   20   0  6.691g 1.950g 0.004g S   1.0 52.9 286:52.49 java

经过分析,APP1、APP4 其实都有基本类似的Young GC 行为。APP1 和APP4 相比内存占用没有这么大,其实就是启动时候的这个设置堆大小的参数导致的

  • APP1 -Xms1932m -Xmx1932m -XX:NewSize=1024m -XX:MaxNewSize=1200m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m
  • APP4 -Xms4096m -Xmx4096m -XX:NewSize=1024m -XX:MaxNewSize=1200m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m

再看一下生产环境的情况

APP1 应用

// 启动参数
/usr/java/jdk1.8.0_191-amd64/bin/java -D[Standalone] -XX:+UseCompressedOops -verbose:gc -Xloggc:/opt/jbshome/appserver/appcloud442shServer1/log/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=3M -XX:-TraceClassUnloading -server -Xms3997m -Xmx3997m -XX:NewSize=1024m -XX:MaxNewSize=1200m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/jbshome/jboss_dump/appcloud442shServer1-OOM-pid%p.hprof -Dorg.jboss.boot.log.file=/opt/jbshome/appserver/appcloud442shServer1/log/server.log -Dlogging.configuration=file:/opt/jbshome/appserver/appcloud442shServer1/configuration/logging.properties -jar /opt/jbshome/jboss-eap-6.4/jboss-modules.jar -mp /opt/jbshome/jboss-eap-6.4/modules -jaxpmodule javax.xml.jaxp-provider org.jboss.as.standalone -Djboss.home.dir=/opt/jbshome/jboss-eap-6.4 -Djboss.server.base.dir=/opt/jbshome/appserver/appcloud442shServer1 -Djboss.server.base.dir=/opt/jbshome/appserver/appcloud442shServer1/ --server-config=standalone.xml -Djboss.bind.address.management=10.4.176.214 -Djboss.bind.address=10.4.176.214 -Djboss.socket.binding.port-offset=0 -Djboss.node.name=za24cloud442shServer1
 

// GC日志
2020-08-25T13:46:20.019+0800: 482939.062: [GC (Allocation Failure) [PSYoungGen: 1223168K->3504K(1224192K)] 1362929K->143881K(4089344K), 0.0119684 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2020-08-25T14:15:49.559+0800: 484708.602: [GC (Allocation Failure) [PSYoungGen: 1223088K->2736K(1224192K)] 1363465K->143945K(4089344K), 0.0115629 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2020-08-25T14:52:05.590+0800: 486884.633: [GC (Allocation Failure) [PSYoungGen: 1222320K->3504K(1224192K)] 1363529K->144730K(4089344K), 0.0111573 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2020-08-25T15:26:35.859+0800: 488954.902: [GC (Allocation Failure) [PSYoungGen: 1223088K->2720K(1224192K)] 1364314K->144770K(4089344K), 0.0114452 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2020-08-25T16:02:05.842+0800: 491084.885: [GC (Allocation Failure) [PSYoungGen: 1222304K->3568K(1224192K)] 1364354K->145658K(4089344K), 0.0112519 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2020-08-25T16:37:46.102+0800: 493225.146: [GC (Allocation Failure) [PSYoungGen: 1223152K->2720K(1224192K)] 1365242K->145602K(4089344K), 0.0118292 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2020-08-25T17:05:07.727+0800: 494866.770: [GC (Allocation Failure) [PSYoungGen: 1222304K->3600K(1224192K)] 1365186K->146498K(4089344K), 0.0111031 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2020-08-25T17:38:45.328+0800: 496884.371: [GC (Allocation Failure) [PSYoungGen: 1223184K->2752K(1224192K)] 1366082K->146482K(4089344K), 0.0113314 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2020-08-25T18:23:27.121+0800: 499566.164: [GC (Allocation Failure) [PSYoungGen: 1222336K->3616K(1224192K)] 1366066K->147363K(4089344K), 0.0114842 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2020-08-25T18:56:43.631+0800: 501562.674: [GC (Allocation Failure) [PSYoungGen: 1223200K->3568K(1224192K)] 1366947K->147899K(4089344K), 0.0115221 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
 

// 内存和CPU情况
$ top - p 95294
top - 19:15:04 up 426 days, 23:36,  1 user,  load average: 0.30, 0.17, 0.15
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  6.2 us, 12.9 sy,  0.0 ni, 80.7 id,  0.0 wa,  0.0 hi,  0.2 si,  0.0 st
KiB Mem : 12184584 total,  3491240 free,  3476284 used,  5217060 buff/cache
KiB Swap:  8388604 total,  8370932 free,    17672 used.  8084416 avail Mem
 
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 95294 qappsom   20   0  6.585g 1.563g 0.022g S   0.7 13.5  51:12.10 java

再去看一下非jboss 的APP2 应用

// 启动参数
$ ps -elf  | grep xxx
0 S qdevsom   16383  16221  0  80   0 - 28177 pipe_w 19:17 pts/0    00:00:00 grep --color=auto xxx
0 S qappsom   69994  69990  1  80   0 - 1767317 futex_ Aug20 ?      02:00:20 /usr/java/jdk1.8.0_191-amd64/bin/java -server -Xms4096m -Xmx4096m -cp XXXZ/xxxcld.jar com.tst.xxx.api.xxxcld.XXXCLD_APPStart com.tst.xxx.api.xxxolt.XXXOLT_APPStart APP2
 

// 内存、CPU信息
$ top -p 69994
top - 19:17:16 up 375 days,  3:03,  1 user,  load average: 0.03, 0.09, 0.15
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  1.0 us,  0.7 sy,  0.0 ni, 98.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 12184592 total,  3593364 free,  3304528 used,  5286700 buff/cache
KiB Swap:  8388604 total,  8388604 free,        0 used.  8294240 avail Mem
 
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 69994 qappsom   20   0  6.742g 1.608g 0.017g S   1.0 13.8 120:20.48 java

再来简单回顾和总结一下

  • APP4 每30分钟会有一次GC;APP1约每1小时一次GC
  • APP1 和APP4 的YGC 销毁的垃圾数量基本一致
  • APP1 和APP4 的内存不同估计是和 -Xms1932m 设置有关
    • 所以top命令显示的两者的内存也刚好差2G左右
    • 生产上的APP1应用其实也是这个规律
  • -XX:MaxNewSize=1200m 所以确实是在Young区内存达到1200M 的时候产生GC
  • APP4 的总内存是6.691g,设置的堆内存是4G,元数据区是0.5G,剩下的还有2G是什么内存?
    • 栈?堆外内存?
    • 进程的内存分布怎么查看?
  • APP4报内存占用过大,是因为设置的 -Xmx4096m 较大导致的,其运行现象其实是和APP1一样的
  • 那接下来就是这几个个问题
    • 除了堆内存、元数据区,剩下的近2G是什么内存?
    • 为什么APP1、APP4这两个jboss应用的Young 区频繁的产生GC,是什么对象导致的GC?
    • APP4的Dump文件中的大量的char[]、byte[],到底是什么?

使用Arthas 进行分析

启动 arthas,然后附加到对应的进程上

$ java -jar arthas-boot.jar

补充堆外内存的知识,虽然后续分析这个问题并不是堆外内存导致的!

Direct Memory 堆外内存

基于GC 回收:堆内的DirectByteBuffer 对象被GC 时,会调用cleaner 回收其引用的堆外内存。问题是YGC 只会将将新生代里的不可达的DirectByteBuffer 对象及其堆外内存回收,如果有大量的DirectByteBuffer 对象移到了old区,但是又一直没有做CMS GC 或者FGC,而只进行YGC,物理内存会被慢慢耗光,触发OutOfMemoryError (水平有限,这句话还没懂) 因此为了避免这种悲剧的发生,通过 -XX:MaxDirectMemorySize 来指定最大的堆外内存大小,当使用达到了阈值的时候将调用System.gc来做一次full gc,以此来回收掉没有被使用的堆外内存

dashboard 显示当前进程的基本信息,线程、内存分布、JVM,下面将内存信息列出来

$ dashboard

Memory                                       used          total        max           usage        GC
heap                    堆内存                623M          4035M        4035M         15.45%       gc.ps_scavenge.count                           11
ps_eden_space           Eden区               576M          1080M        1081M         53.29%       gc.ps_scavenge.time(ms)                        770
ps_survivor_space       S区                  4M            59M          59M           7.02%        gc.ps_marksweep.count                          0
ps_old_gen              老年代                43M           2896M        2896M         1.49%        gc.ps_marksweep.time(ms)                       0
nonheap                                      115M          122M         1256M         9.17%
code_cache                                   32M           32M          240M          13.58%
metaspace               元数据区              74M           79M          512M          14.48%
compressed_class_space                        8M            10M          504M          1.67%
direct                  堆外内存              132K          132K         -             100.00%
mapped                                        0K            0K           -             NaN%

高权限环境APP2 的对象分布情况

在不同时刻,打印APP2 应用的对象分布信息

$ jmap -F -histo 105371

num       #instances    #bytes  Class description
--------------------------------------------------------------------------
1:              1177553 125229120  119M     char[]
2:              1090021 103724536       byte[]
3:              147033  85658312        int[]
4:              836246  35216968        java.lang.Object[]
5:              372637  17886576        java.util.HashMap
6:              237137  16926504        java.util.HashMap$Node[]
7:              658554  15805296        java.util.ArrayList
8:              270471  15146376        java.util.LinkedHashMap
9:              599335  14384040        java.lang.String
10:             415777  13304864        java.util.HashMap$Node
11:             465024  11160576        org.apache.kafka.common.internals.PartitionStates$PartitionState
12:             204041  9793968 java.nio.HeapByteBuffer
13:             9380    7828616 short[]
14:             241800  7737600 java.util.ArrayList$Itr
15:             194921  6237472 java.util.concurrent.locks.AbstractQueuedSynchronizer$Node
16:             137965  5518600 java.util.LinkedHashMap$Entry
17:             205771  4938504 org.apache.kafka.common.protocol.types.Struct
18:             111714  4468560 java.util.HashMap$KeyIterator
19:             66866   4279424 sun.nio.cs.ext.DoubleByte$Encoder
20:             70574   3952144 sun.nio.cs.ext.DoubleByte$Decoder
21:             66845   3743320 sun.nio.cs.UTF_8$Encoder
22:             229584  3673344 java.util.LinkedHashMap$LinkedEntrySet
23:             72538   3481824 java.nio.HeapCharBuffer
 
 |
 |
 v
 等了几分钟 
 
 
um       #instances    #bytes  Class description
--------------------------------------------------------------------------
1:              1278634 133716496  127.5M     char[]
2:              1167601 110480000       byte[]
3:              160434  91468136        int[]
4:              900426  38011440        java.lang.Object[]
5:              401553  19274544        java.util.HashMap
6:              253657  18116496        java.util.HashMap$Node[]
7:              709310  17023440        java.util.ArrayList
8:              290083  16244648        java.util.LinkedHashMap
9:              652701  15664824        java.lang.String
10:             448940  14366080        java.util.HashMap$Node
11:             501243  12029832        org.apache.kafka.common.internals.PartitionStates$PartitionState
12:             218774  10501152        java.nio.HeapByteBuffer
13:             261488  8367616 java.util.ArrayList$Itr
14:             10526   7964480 short[]
15:             208318  6666176 java.util.concurrent.locks.AbstractQueuedSynchronizer$Node
16:             146621  5864840 java.util.LinkedHashMap$Entry
17:             222291  5334984 org.apache.kafka.common.protocol.types.Struct
18:             120416  4816640 java.util.HashMap$KeyIterator
19:             71481   4574784 sun.nio.cs.ext.DoubleByte$Encoder
20:             75490   4227440 sun.nio.cs.ext.DoubleByte$Decoder
21:             71614   4010384 sun.nio.cs.UTF_8$Encoder
 
 
 |
 |
 v
发生了垃圾回收
 
um       #instances    #bytes  Class description
--------------------------------------------------------------------------
1:              83589   21275488  20M      char[]
2:              46625   17740880        byte[]
3:              13515   7415512 int[]
4:              17650   1976800 java.net.SocksSocketImpl
5:              39950   1892544 java.lang.Object[]
6:              68754   1650096 java.lang.String
7:              22363   1393656 java.util.HashMap$Node[]
8:              40076   1282432 java.util.HashMap$Node
9:              77635   1242160 java.lang.Object
10:             30910   1236400 java.util.LinkedHashMap$Entry
11:             19629   1099224 java.util.LinkedHashMap
12:             31196   748704  java.util.ArrayList
13:             20104   643328  java.util.concurrent.ConcurrentHashMap$Node
14:             12006   576288  java.util.HashMap
15:             17647   564704  java.net.Socket
16:             4572    537496  java.lang.Class
17:             7754    372192  org.apache.kafka.common.metrics.stats.SampledStat$Sample
18:             9059    362360  java.lang.ref.Finalizer
19:             6641    318768  java.net.SocketOutputStream
20:             6641    318768  java.net.SocketInputStream
21:             9403    300896  org.apache.kafka.common.MetricName
22:             9400    300800  org.apache.kafka.common.metrics.KafkaMetric
23:             5634    270432  java.nio.HeapByteBuffer
24:             1136    254464  oracle.jdbc.driver.T4CCharAccessor
25:             7504    240128  java.io.FileDescriptor
26:             7458    238656  java.net.InetAddress$InetAddressHolder
27:             14467   231472  java.util.LinkedHashMap$LinkedEntrySet
28:             9582    229968  org.apache.kafka.common.internals.PartitionStates$PartitionState

发现好多都是和Kafka、NIO 相关的内存,垃圾回收掉的看起来都是Kafka 内容!!!

APP2 的垃圾回收情况

$ jstat -gc 

 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
19968.0 19968.0 16721.1  0.0   603648.0 280066.4 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 291847.9 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 303451.9 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 315350.6 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 347761.3 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 358709.6 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 381216.3 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 403008.5 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 408422.1 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 431113.1 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 446153.7 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 469323.9 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 480306.4 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 496308.4 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 507246.9 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 518646.2 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 529437.0 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 530121.6 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 547551.6 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 558705.0 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 569635.4 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 573555.7 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 589095.8 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162
19968.0 19968.0 16721.1  0.0   603648.0 599538.9 1287680.0   55081.7   32640.0 31965.8 3200.0 3019.2   2116   38.110   1      0.051   38.162

 |
 |
 v
 发生Young GC

21504.0 3584.0  0.0   3424.1 603648.0 10211.4  1287680.0   55089.7   32640.0 31968.0 3200.0 3019.2   2117   38.134   1      0.051   38.185
21504.0 3584.0  0.0   3424.1 603648.0 20917.8  1287680.0   55089.7   32640.0 31968.0 3200.0 3019.2   2117   38.134   1      0.051   38.185

可以看到当发生Young GC 之后,S0 与S1 发生的切换!

APP2 也是大量的char[],导致垃圾回收。最直接的方法就是如何定位在哪里创建的,但是怎么定位?

想到的一个粗暴的方法是,使用jdb 附加到APP2 进程上,然后逐个的suspend 线程,看哪个线程被阻塞后会导致不再出现垃圾回收,那么基本就确定是哪个线程导致垃圾生成,然后再查看这个线程的调用栈去分析代码

jdb 调试JVM 进程

使用下面的命令,Debug 的方式启动APP2 进程

java -server -Xms1885m -Xmx1885m -Xdebug -Xrunjdwp:transport=dt_socket,address=7077,server=y,suspend=y -cp XXXZ/xxxcld.jar com.tst.xxx.api.xxxcld.XXXCLD_APPStart com.tst.xxx.api.xxxolt.XXXOLT_APPStart APP2

然后使用jdb 连接上进程。附加上去后执行jdb 的run 命令启动进程

$ jdb -attach localhost:7077

Set uncaught java.lang.Throwable
Set deferred uncaught java.lang.Throwable
Initializing jdb ...
>
VM Started: No frames on the current call stack
 
main[1] run
  • list 查看源码,不过一般会报这种错Source file not found: Test.java,因为javac 编译时没有加-g 参数
  • threads 查看所有线程
  • thread 0x1 切换到指定线程
  • locals 查看本地变量
  • dump args 查看某个变量的值
  • stop in com.tst.app.wrk.test.Test.sendMessage 在特定方法处下断点
  • stop at com.tst.app.wrk.test.Test:100 在特定行下断点
  • cont 在一个断点、异常或者步骤之后,继续待调试的应用程序的执行
  • clear 查看已经设置的断点
  • clear com.tst.app.wrk.test.Test.sendMessage 删除断点
  • where 查看当前运行的堆栈信息
  • next 执行下一步
  • step 进入函数内部
  • stepi 指令级别的单步
  • step up 从当前函数跳出
  • help jdb的更多用法,help命令去详细看一下

然后在一个新的终端jstat 监控这个进程,Eden 区确实内存不断增长的

$ jstat -gc 4448 6000 1000

 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
80384.0 80384.0 12111.0  0.0   482816.0 253033.3 1287680.0   14813.3   26880.0 26221.1 2816.0 2712.6      2    0.059   1      0.059    0.118
80384.0 80384.0 12111.0  0.0   482816.0 267804.6 1287680.0   14813.3   26880.0 26221.1 2816.0 2712.6      2    0.059   1      0.059    0.118
80384.0 80384.0 12111.0  0.0   482816.0 268058.7 1287680.0   14813.3   26880.0 26221.1 2816.0 2712.6      2    0.059   1      0.059    0.118
80384.0 80384.0 12111.0  0.0   482816.0 268312.8 1287680.0   14813.3   26880.0 26221.1 2816.0 2712.6      2    0.059   1      0.059    0.118
80384.0 80384.0 12111.0  0.0   482816.0 268566.9 1287680.0   14813.3   26880.0 26221.1 2816.0 2712.6      2    0.059   1      0.059    0.118
80384.0 80384.0 12111.0  0.0   482816.0 268821.0 1287680.0   14813.3   26880.0 26221.1 2816.0 2712.6      2    0.059   1      0.059    0.118
80384.0 80384.0 12111.0  0.0   482816.0 280595.1 1287680.0   14813.3   26880.0 26221.1 2816.0 2712.6      2    0.059   1      0.059    0.118
80384.0 80384.0 12111.0  0.0   482816.0 280849.2 1287680.0   14813.3   26880.0 26221.1 2816.0 2712.6      2    0.059   1      0.059    0.118

然后在快要产生Young GC 的时候(EU的值快要达到EC的时候),执行下面命令 jmap -F -histo 4448 > heap1.txt 看一下内存中哪些对象比较多。执行jmap 命令的时候可以看到jstat -gc 的各个输出值是不变的,所以jmap 基本可以确定是会导致被处理进程挂住的

然后在发生了Young GC 的时候,再查看一下对象,jmap -F -histo 4448 > heap2.txt

两次的对比结果是这样的。vimdiff heap1.txt heap2.txt

Server compiler detected.                                                                  |  Server compiler detected.
  JVM version is 25.191-b12                                                                  |  JVM version is 25.191-b12
  Object Histogram:                                                                          |  Object Histogram:
                                                                                             |
  num       #instances    #bytes  Class description                                          |  num       #instances    #bytes  Class description
  --------------------------------------------------------------------------                 |  --------------------------------------------------------------------------
  1:              873976  80240056        char[]                                             |  1:              15042   14097896        byte[]
  2:              158548  55130104        byte[]                                             |  2:              71894   8099184 char[]
  3:              33523   53294696        int[]                                              |  3:              5276    2140496 int[]
  4:              506958  16222656        java.util.ArrayList$Itr                            |  4:              69760   1674240 java.lang.String
  5:              615746  14777904        java.lang.String                                   |  5:              27551   881632  java.util.HashMap$Node
  6:              245120  5882880 java.lang.Double                                           |  6:              13493   819720  java.util.HashMap$Node[]
  7:              99884   4717976 java.lang.Object[]                                         |  7:              19748   789920  java.util.LinkedHashMap$Entry
  8:              145127  4644064 java.util.Hashtable$Entry                                  |  8:              24682   789824  java.util.ArrayList$Itr
  9:              100548  3217536 java.util.HashMap$Node                                     |  9:              14279   730216  java.lang.Object[]
  10:             11265   2994808 java.util.Hashtable$Entry[]                                |  10:             9922    555632  java.util.LinkedHashMap
  11:             56557   2714736 java.nio.HeapByteBuffer                                    |  11:             15751   504032  java.util.concurrent.ConcurrentHashMap$Node
  12:             48075   2704552 java.util.HashMap$Node[]                                   |  12:             4134    486408  java.lang.Class
  13:             61240   2449600 java.util.HashMap$EntryIterator                            |  13:             15300   367200  java.lang.Double
  14:             73844   2363008 java.util.ArrayDeque$DeqIterator                           |  14:             10670   341440  java.util.Hashtable$Entry
  15:             91932   2206368 java.lang.StringBuilder                                    |  15:             9226    221424  java.util.ArrayList
  16:             62922   2013504 java.util.concurrent.locks.AbstractQueuedSynchronizer$Node |  16:             5508    220320  java.lang.ref.Finalizer
  17:             39712   1906176 java.util.HashMap                                          |  17:             6683    213856  org.apache.kafka.common.MetricName
  18:             53883   1724256 java.text.StringCharacterIterator                          |  18:             6683    213856  org.apache.kafka.common.metrics.KafkaMetric
  19:             49635   1588320 java.util.LinkedHashMap$LinkedValueIterator                |  19:             4427    212496  java.util.HashMap
  20:             76888   1230208 java.util.Collections$UnmodifiableMap$UnmodifiableEntrySet$|  20:             4241    203568  org.apache.kafka.common.metrics.stats.SampledStat$Sample
  21:             47854   1148496 java.util.ArrayList                                        |  21:             806     177144  java.util.Hashtable$Entry[]
  22:             26545   1061800 java.util.HashMap$KeyIterator                              |  22:             10304   164864  java.lang.Object
  23:             15079   965056  sun.nio.cs.ext.DoubleByte$Encoder                          |  23:             214     160480  java.nio.ByteBuffer[]
  24:             15899   890344  sun.nio.cs.ext.DoubleByte$Decoder                          |  24:             171     145552  java.util.concurrent.ConcurrentHashMap$Node[]
  25:             20724   828960  java.util.LinkedHashMap$Entry                              |  25:             2685    128880  java.nio.HeapByteBuffer
  26:             15366   737568  java.nio.HeapCharBuffer                                    |  26:             1903    121792  org.apache.kafka.common.metrics.Sensor
  27:             18753   600096  javax.management.MBeanAttributeInfo                        |  27:             6738    107808  java.util.LinkedHashMap$LinkedEntrySet
  28:             10561   591416  java.util.LinkedHashMap                                    |  28:             1856    103936  java.util.zip.ZipFile$ZipFileInputStream
  29:             23569   565656  org.apache.kafka.common.protocol.types.Struct              |  29:             1854    103824  java.util.zip.ZipFile$ZipFileInflaterInputStream
  30:             16309   521888  java.util.concurrent.ConcurrentHashMap$Node                |  30:             1070    94160   java.lang.reflect.Method
  31:             7803    499392  java.util.regex.Matcher                                    |  31:             2897    92704   java.util.concurrent.locks.AbstractQueuedSynchronizer$Node
  32:             15251   488032  java.lang.ref.WeakReference                                |  32:             2468    78976   java.text.StringCharacterIterator
  33:             4134    486408  java.lang.Class                                            |  33:             3155    75720   org.apache.kafka.common.requests.ApiVersionsResponse$ApiVer
  34:             29727   475632  java.lang.Integer                                          |  34:             1877    75080   java.util.HashMap$EntryIterator
  35:             16840   404160  java.lang.Long                                             |  35:             2144    68608   org.apache.kafka.common.metrics.stats.Meter
  36:             2458    346296  short[]                                                    |  36:             584     65408   java.net.SocksSocketImpl
  37:             5514    308784  javax.management.MBeanServerNotification                   |  37:             1837    58784   java.util.ArrayDeque$DeqIterator
  38:             9210    294720  java.util.LinkedHashMap$LinkedEntryIterator                |  38:             917     58688   java.net.URL
  39:             4885    273560  sun.nio.cs.UTF_8$Encoder                                   |  39:             1679    53728   java.util.LinkedHashMap$LinkedValueIterator
  40:             6817    272680  java.lang.ref.Finalizer                                    |  40:             2144    51456   org.apache.kafka.common.metrics.stats.Total
  41:             16743   267888  java.util.HashSet                                          |  41:             2144    51456   org.apache.kafka.common.metrics.stats.Rate
  42:             6646    265840  java.util.HashMap$ValueIterator                            |  42:             47      50760   oracle.jdbc.driver.T4CPreparedStatement
  43:             3626    261072  com.alibaba.fastjson.serializer.JSONSerializer             |  43:             1268    50720   java.lang.ref.SoftReference
  44:             7774    259128  long[]                                                     |  44:             996     46680   java.lang.String[]

分析堆内存找到DirectByteBuffer 的引用和大小,DirectByteBuffer 会指向堆外内存,如果 DirectByteBuffer 的数量很多,那么可能表示堆外内存很多!但上面的情况看到 DirectByteBuffer 不是很多,所以不太可能是堆外内存导致的

查看堆内存中DirectByteBuffer 的数量是分析堆外内存是否占用过高的一个切入点

操作系统维度的分析

现在看到APP2 也存在类似的GC 行为,暂时认为和是否jboss 应用无关,所以先去针对APP2 这个TCP 应用进行分析。查看4448 进程的物理内存和虚拟内存

$ ps -p 4448 -o rss,vsz  
  RSS    VSZ
519936 4671584
 
 
$ top -p 4448
top - 09:54:06 up 175 days, 23 min,  7 users,  load average: 0.11, 0.32, 0.35
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  1.8 us,  2.6 sy,  0.0 ni, 95.6 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  3861512 total,   303088 free,  3249440 used,   308984 buff/cache
KiB Swap:  8388604 total,  7909628 free,   478976 used.   386956 avail Mem
 
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  4448 root      20   0  4.455g 0.497g 0.006g S   0.0 13.5   0:31.46 java

pmap 查看进程的内存分配

为了进一步分析问题,我们使用pmap 查看进程的内存分配,通过RSS升序序排列。结果发现除了地址 000000008a200000 上分配的1888.875M 堆以外(和JVM启动参数中的 -Xms1885m -Xmx1885m 一致)

可以看到Java 堆内存是预先分配好的!

pmap -x 4448  | sort -n -k3
---------------- ------- ------- -------
0000000000400000       4       0       0 r-x-- java
00000001002e0000 1045632       0       0 -----   [ anon ]
00007fa321416000    1548       0       0 -----   [ anon ]
...
00007fa327bfc000      12       0       0 -----   [ anon ]
00007fa327cfd000      12       0       0 -----   [ anon ]
00007fa327dfe000      12       0       0 -----   [ anon ]
00007fa327eff000      12       0       0 -----   [ anon ]
00007fa32802c000   65360       0       0 -----   [ anon ]
00007fa32c092000      12       0       0 -----   [ anon ]
...
00007fa32dbab000      12       0       0 -----   [ anon ]
00007fa32dcac000      12       0       0 -----   [ anon ]
00007fa32dfad000      28       0       0 r-x-- libawt_headless.so
00007fa32dfb4000    2044       0       0 ----- libawt_headless.so
00007fa32e1b5000     636       0       0 r-x-- libawt.so
00007fa32e254000    2048       0       0 ----- libawt.so
00007fa32e485000      12       0       0 -----   [ anon ]
00007fa32e586000      12       0       0 -----   [ anon ]
00007fa32ec87000      12       0       0 -----   [ anon ]
00007fa32ed88000      12       0       0 -----   [ anon ]
00007fa32ee89000      12       0       0 -----   [ anon ]
00007fa32f59b000    2044       0       0 ----- libnio.so
00007fa32f79c000      60       0       0 r-x-- libbz2.so.1.0.6
00007fa32f7ab000    2044       0       0 ----- libbz2.so.1.0.6
00007fa32f9ac000     148       0       0 r-x-- liblzma.so.5.2.2
00007fa32f9d1000    2044       0       0 ----- liblzma.so.5.2.2
00007fa32fbd2000      84       0       0 r-x-- libz.so.1.2.7
00007fa32fbe7000    2044       0       0 ----- libz.so.1.2.7
00007fa32fde8000      92       0       0 r-x-- libelf-0.168.so
00007fa32fdff000    2044       0       0 ----- libelf-0.168.so
00007fa3300cc000   64720       0       0 -----   [ anon ]
00007fa334037000   65316       0       0 -----   [ anon ]
00007fa33bb80000    4608       0       0 -----   [ anon ]
...
00007fa35c02c000   65360       0       0 -----   [ anon ]
00007fa3600f5000      16       0       0 r-x-- libattr.so.1.1.0
00007fa3600f9000    2044       0       0 ----- libattr.so.1.1.0
00007fa3602fa000      84       0       0 r-x-- libgcc_s-4.8.5-20150702.so.1
00007fa36030f000    2044       0       0 ----- libgcc_s-4.8.5-20150702.so.1
00007fa364053000   65204       0       0 -----   [ anon ]
00007fa3680b0000      12       0       0 -----   [ anon ]
00007fa3681b1000     272       0       0 r-x-- libdw-0.168.so
00007fa3681f5000    2048       0       0 ----- libdw-0.168.so
00007fa3683f8000      16       0       0 r-x-- libcap.so.2.22
00007fa3683fc000    2044       0       0 ----- libcap.so.2.22
00007fa3685fd000      72       0       0 r-x-- libnss_myhostname.so.2
00007fa36860f000    2044       0       0 ----- libnss_myhostname.so.2
00007fa368812000      88       0       0 r-x-- libresolv-2.17.so
00007fa368828000    2044       0       0 ----- libresolv-2.17.so
00007fa368a29000       8       0       0 rw---   [ anon ]
00007fa368a2b000      20       0       0 r-x-- libnss_dns-2.17.so
00007fa368a30000    2048       0       0 ----- libnss_dns-2.17.so
00007fa368c38000      16       0       0 r--s- jsse.jar
00007fa368c3c000      24       0       0 r--s- charsets.jar
00007fa368c42000       8       0       0 r--s- xxxutl.jar
00007fa368c44000      12       0       0 r--s- xxxpdz.jar
00007fa368c47000      12       0       0 r--s- xxxmsg.jar
00007fa368f60000    2044       0       0 ----- libnet.so
00007fa369169000    2048       0       0 ----- libmanagement.so
00007fa36936b000       4       0       0 r--s- xxxlog.jar
00007fa36936c000       4       0       0 r--s- xxxexp.jar
00007fa36936d000       4       0       0 r--s- xxxctn.jar
...
00007fa369395000       8       0       0 r--s- xxxolt.jar
00007fa369397000       8       0       0 r--s- xxxcmh.jar
00007fa369399000       8       0       0 r--s- xxxcmc.jar
00007fa36939b000       4       0       0 r--s- xxxasy.jar
00007fa36939c000     136       0       0 r--s- guava-12.0.1.jar
00007fa3693be000      24       0       0 r--s- jaxen-1.1-beta-6.jar
00007fa3693c4000      20       0       0 r--s- dom4j-1.6.1.jar
00007fa3693c9000       8       0       0 r--s- snappy-java-1.1.7.1.jar
00007fa3693cb000       4       0       0 r--s- slf4j-log4j12-1.7.21.jar
00007fa3693cc000       8       0       0 r--s- slf4j-api-1.7.25.jar
00007fa3693ce000      12       0       0 r--s- lz4-java-1.4.1.jar
00007fa3693d1000      36       0       0 r--s- log4j-1.2.16.jar
00007fa3693da000     136       0       0 r--s- kafka-clients-2.0.0.jar
00007fa3693fc000      28       0       0 r--s- fastjson-1.2.4.jar
00007fa369403000       8       0       0 r--s- cmbkafka-client-5.1.0.jar
00007fa369405000      16       0       0 r--s- args4j-2.33.jar
00007fa369409000      36       0       0 r--s- mysql-connector-java-5.1.30-bin.jar
00007fa369412000       8       0       0 r--s- servlet-api.jar
00007fa369414000       4       0       0 r--s- EbcdicEncoding.jar
00007fa369415000      28       0       0 r--s- orai18n.jar
00007fa36941c000      92       0       0 r--s- ojdbc6-11.2.0.4.jar
00007fa369433000       8       0       0 r--s- zn1ntn.jar
...
00007fa3695be000       4       0       0 -----   [ anon ]
00007fa3696bf000      12       0       0 -----   [ anon ]
00007fa3697c0000      16       0       0 -----   [ anon ]
00007fa3698c1000      16       0       0 -----   [ anon ]
00007fa3699c2000      12       0       0 -----   [ anon ]
00007fa369ac3000      12       0       0 -----   [ anon ]
00007fa369bc4000      12       0       0 -----   [ anon ]
00007fa369cc9000    2044       0       0 ----- libdt_socket.so
00007fa369eca000      12       0       0 -----   [ anon ]
00007fa369fcb000      12       0       0 -----   [ anon ]
00007fa36a0cc000      12       0       0 -----   [ anon ]
00007fa36a1cd000       4       0       0 -----   [ anon ]
00007fa36b726000  233152       0       0 -----   [ anon ]
00007fa3826bb000   25876       0       0 -----   [ anon ]
...
00007fa384fd6000       4       0       0 -----   [ anon ]
00007fa3850d7000       4       0       0 -----   [ anon ]
00007fa38582f000    3640       0       0 -----   [ anon ]
00007fa385bd7000    2048       0       0 ----- libzip.so
00007fa385dd9000      48       0       0 r-x-- libnss_files-2.17.so
00007fa385de5000    2044       0       0 ----- libnss_files-2.17.so
00007fa385fe6000      24       0       0 rw---   [ anon ]
00007fa385fec000       8       0       0 r-x-- libnpt.so
00007fa385fee000    2048       0       0 ----- libnpt.so
00007fa38622a000    2044       0       0 ----- libjdwp.so
00007fa386458000    2044       0       0 ----- libjava.so
00007fa38665a000      52       0       0 r-x-- libverify.so
00007fa386667000    2044       0       0 ----- libverify.so
00007fa386869000      28       0       0 r-x-- librt-2.17.so
00007fa386870000    2044       0       0 ----- librt-2.17.so
00007fa386a71000    1028       0       0 r-x-- libm-2.17.so
00007fa386b72000    2044       0       0 ----- libm-2.17.so
00007fa387a55000    2048       0       0 ----- libjvm.so
00007fa387f19000    2048       0       0 ----- libc-2.17.so
00007fa388124000       8       0       0 r-x-- libdl-2.17.so
00007fa388126000    2048       0       0 ----- libdl-2.17.so
00007fa388328000      92       0       0 r-x-- libjli.so
00007fa38833f000    2044       0       0 ----- libjli.so
00007fa388557000    2044       0       0 ----- libpthread-2.17.so
00007fa38877e000       4       0       0 r--s- cfprutpr_int.jar
00007fa38877f000       4       0       0 r--s- aybddz.jar
00007fa388780000       8       0       0 r--s- xxxcld.jar
00007fa38886d000      16       0       0 -----   [ anon ]
00007fa38897b000       4       0       0 r----   [ anon ]
4448:   java -server -Xms1885m -Xmx1885m -Xdebug -Xrunjdwp:transport=dt_socket,address=7077,server=y,suspend=y -cp XXXZ/xxxcld.jar com.tst.xxx.api.xxxcld.XXXCLD_APPStart com.tst.xxx.api.xxxolt.XXXOLT_APPStart APP2
Address           Kbytes     RSS   Dirty Mode  Mapping
ffffffffff600000       4       0       0 r-x--   [ anon ]
0000000000600000       4       4       4 r---- java
0000000000601000       4       4       4 rw--- java
00007fa32e1b3000       4       4       4 r---- libawt_headless.so
00007fa32e1b4000       4       4       4 rw--- libawt_headless.so
00007fa32e454000       4       4       4 r---- libawt.so
00007fa32f79a000       4       4       4 r---- libnio.so
00007fa32f79b000       4       4       4 rw--- libnio.so
00007fa32f9aa000       4       4       4 r---- libbz2.so.1.0.6
00007fa32f9ab000       4       4       4 rw--- libbz2.so.1.0.6
00007fa32fbd0000       4       4       4 r---- liblzma.so.5.2.2
00007fa32fbd1000       4       4       4 rw--- liblzma.so.5.2.2
00007fa32fde6000       4       4       4 r---- libz.so.1.2.7
00007fa32fde7000       4       4       4 rw--- libz.so.1.2.7
00007fa32fffe000       4       4       4 r---- libelf-0.168.so
00007fa32ffff000       4       4       4 rw--- libelf-0.168.so
00007fa3602f8000       4       4       4 r---- libattr.so.1.1.0
00007fa3602f9000       4       4       4 rw--- libattr.so.1.1.0
00007fa36050e000       4       4       4 r---- libgcc_s-4.8.5-20150702.so.1
00007fa36050f000       4       4       4 rw--- libgcc_s-4.8.5-20150702.so.1
00007fa3683f7000       4       4       4 rw--- libdw-0.168.so
00007fa3685fb000       4       4       4 r---- libcap.so.2.22
00007fa3685fc000       4       4       4 rw--- libcap.so.2.22
00007fa368811000       4       4       4 rw--- libnss_myhostname.so.2
00007fa368a27000       4       4       4 r---- libresolv-2.17.so
00007fa368a28000       4       4       4 rw--- libresolv-2.17.so
00007fa368c30000       4       4       4 r---- libnss_dns-2.17.so
00007fa368c31000       4       4       4 rw--- libnss_dns-2.17.so
00007fa36915f000       4       4       4 r---- libnet.so
00007fa369160000       4       4       4 rw--- libnet.so
00007fa369369000       4       4       4 r---- libmanagement.so
00007fa36936a000       4       4       4 rw--- libmanagement.so
00007fa369ec8000       4       4       4 r---- libdt_socket.so
00007fa369ec9000       4       4       4 rw--- libdt_socket.so
00007fa3841d7000    1896       4       0 r--s- rt.jar
00007fa385dd7000       4       4       4 r---- libzip.so
00007fa385dd8000       4       4       4 rw--- libzip.so
00007fa385fe4000       4       4       4 r---- libnss_files-2.17.so
00007fa385fe5000       4       4       4 rw--- libnss_files-2.17.so
00007fa3861ee000       4       4       4 r---- libnpt.so
00007fa3861ef000       4       4       4 rw--- libnpt.so
00007fa386429000       4       4       4 r---- libjdwp.so
00007fa38642a000       4       4       4 rw--- libjdwp.so
00007fa386657000       4       4       4 r---- libjava.so
00007fa386868000       4       4       4 rw--- libverify.so
00007fa386a6f000       4       4       4 r---- librt-2.17.so
00007fa386a70000       4       4       4 rw--- librt-2.17.so
00007fa386d71000       4       4       4 r---- libm-2.17.so
00007fa386d72000       4       4       4 rw--- libm-2.17.so
00007fa388326000       4       4       4 r---- libdl-2.17.so
00007fa388327000       4       4       4 rw--- libdl-2.17.so
00007fa38853e000       4       4       4 r---- libjli.so
00007fa38853f000       4       4       4 rw--- libjli.so
00007fa388756000       4       4       4 r---- libpthread-2.17.so
00007fa388757000       4       4       4 rw--- libpthread-2.17.so
00007fa388758000      16       4       4 rw---   [ anon ]
00007fa38897a000       4       4       4 rw---   [ anon ]
00007fa38897c000       4       4       4 rw---   [ anon ]
00007fa38897d000       4       4       4 r---- ld-2.17.so
00007fa38897e000       4       4       4 rw--- ld-2.17.so
00007fa38897f000       4       4       4 rw---   [ anon ]
00007fffefefe000       8       4       0 r-x--   [ anon ]
00007fa32e460000     148       8       8 rw---   [ anon ]
00007fa3683f5000       8       8       8 r---- libdw-0.168.so
00007fa3695bf000    1024       8       8 rw---   [ anon ]
00007fa3696c2000    1016       8       8 rw---   [ anon ]
00007fa3699c5000    1016       8       8 rw---   [ anon ]
00007fa369ecd000    1016       8       8 rw---   [ anon ]
00007fa379ad6000  103592       8       0 r---- locale-archive
00007fa386658000       8       8       8 rw--- libjava.so
00007fa386866000       8       8       8 r---- libverify.so
00007fa38811d000       8       8       8 rw--- libc-2.17.so
00007fa38875c000     136       8       0 r-x-- ld-2.17.so
00007fa36880e000      12      12      12 r---- libnss_myhostname.so.2
00007fa369cc5000      16      12       0 r-x-- libdt_socket.so
00007fa384fd7000    1024      12      12 rw---   [ anon ]
00007fa369161000      32      16       0 r-x-- libmanagement.so
00007fa369ac6000    1016      16      16 rw---   [ anon ]
00007fa385bbd000     104      16       0 r-x-- libzip.so
00007fa388119000      16      16      16 r---- libc-2.17.so
00007fa3697c4000    1012      20      20 rw---   [ anon ]
00007fa38811f000      20      20      20 rw---   [ anon ]
00007fa388972000      32      20      20 rw-s- 4448
00007fa321599000    1016      24      24 rw---   [ anon ]
00007fa32f58a000      68      24       0 r-x-- libnio.so
00007fa368c4a000    3072      24      24 rw---   [ anon ]
00007fa3698c5000    1012      28      28 rw---   [ anon ]
00007fa38642b000     180      32       0 r-x-- libjava.so
00007fffefe9b000     132      32      32 rw---   [ stack ]
00007fa368f4a000      88      40       0 r-x-- libnet.so
00007fa32e455000      44      44      44 rw--- libawt.so
00007fa388540000      92      52       0 r-x-- libpthread-2.17.so
00007fa354000000     132      64      64 rw---   [ anon ]
00007fa322eb2000    1016      88      88 rw---   [ anon ]
00007fa3235b9000    1016      88      88 rw---   [ anon ]
00007fa3236ba000    1016      88      88 rw---   [ anon ]
...
00007fa32dbae000    1016     108     108 rw---   [ anon ]
00007fa32ec8a000    1016     116     116 rw---   [ anon ]
00007fa3861f0000     232     124       0 r-x-- libjdwp.so
00007fa344000000     140     140     140 rw---   [ anon ]
00007fa388871000    1028     144     144 rw---   [ anon ]
...
00007fa36a1ce000    9248     176     176 rw---   [ anon ]
00007fa387ceb000     196     196     196 rw--- libjvm.so
00007fa387d1c000     236     228     228 rw---   [ anon ]
00007fa364000000     332     244     244 rw---   [ anon ]
00007fa34c000000     280     272     272 rw---   [ anon ]
00007fa384066000    1476     324     324 rw---   [ anon ]
00007fa387d57000    1800     352       0 r-x-- libc-2.17.so
00007fa321396000     512     392     392 rw---   [ anon ]
00007fa360510000   60352     496     496 rw---   [ anon ]
00007fa388782000     940     544     544 rw---   [ anon ]
00007fa387c55000     600     600     600 r---- libjvm.so
00007fa330000000     816     808     808 rw---   [ anon ]
00007fa358000000    1624    1528    1528 rw---   [ anon ]
...
00007fa33c000000    5416    5324    5324 rw---   [ anon ]
00007fa386d73000   13192    6032       0 r-x-- libjvm.so
00007fa3850d8000    7516    6504    6504 rw---   [ anon ]
00007fa3843b1000   12436    8732    8732 rw---   [ anon ]
00007fa36aad6000   12608   11932   11932 rwx--   [ anon ]
00007fa380000000   39660   22020   22020 rw---   [ anon ]
00007fa338000000   60928   44592   44592 rw---   [ anon ]
000000008a200000 1934208  392296  392296 rw---   [ anon ]
total kB         4671588  538276  531552

pref 进行进程分析

perf record -g -p 4448 开启监控栈函数调用。运行一段时间后Ctrl+C 结束,会生成一个文件 perf.data

perf 好像是监控Linux 层面的信息,JVM 层面好像监控不到,对于监控堆外内存、Socket 通信是有用的,但是对于JVM

执行 perf report -i perf.data 查看报告

Samples: 7K of event 'cpu-clock', Event count (approx.): 1846250000
  Children      Self  Command  Shared Object       Symbol                                                                                                                                 ◆
+   59.27%     0.00%  java     libpthread-2.17.so  [.] start_thread                                                                                                                       ▒
+   59.26%     0.00%  java     libjvm.so           [.] java_start                                                                                                                         ▒
+   46.23%     0.00%  java     libjvm.so           [.] JavaThread::run                                                                                                                    ▒
+   45.97%     0.00%  java     libjvm.so           [.] JavaThread::thread_main_inner                                                                                                      ▒
+   24.13%     0.00%  java     libjvm.so           [.] CompileBroker::compiler_thread_loop                                                                                                ▒
+   23.03%     0.03%  java     libjvm.so           [.] CompileBroker::invoke_compiler_on_method                                                                                           ▒
+   21.80%     4.96%  java     libpthread-2.17.so  [.] pthread_cond_timedwait@@GLIBC_2.3.2                                                                                                ▒
+   19.46%     0.28%  java     [kernel.kallsyms]   [k] system_call_fastpath                                                                                                               ▒
+   19.19%     0.00%  java     libjvm.so           [.] C2Compiler::compile_method                                                                                                         ▒
+   19.17%     0.00%  java     libjvm.so           [.] Compile::Compile                                                                                                                   ▒
+   18.39%     0.00%  java     libjvm.so           [.] JavaCalls::call_virtual                                                                                                            ▒
+   18.38%     0.05%  java     libjvm.so           [.] JavaCalls::call_helper                                                                                                             ▒
+   18.38%     0.00%  java     libjvm.so           [.] JavaCalls::call_virtual                                                                                                            ▒
+   18.31%     0.00%  java     libjvm.so           [.] thread_entry                                                                                                                       ▒
+   17.37%     0.00%  java     perf-4448.map       [.] 0x00007fa36aad67a7                                                                                                                 ▒
+   16.29%     0.00%  java     perf-4448.map       [.] 0x00007fa36b3aee78                                                                                                                 ▒
+   15.69%     0.00%  java     perf-4448.map       [.] 0x00007fa36b2a542a                                                                                                                 ▒
+   15.11%     0.39%  java     libjvm.so           [.] Unsafe_Park                                                                                                                        ▒
+   14.71%     0.22%  java     [kernel.kallsyms]   [k] sys_futex                                                                                                                          ▒
+   13.19%     0.64%  java     [kernel.kallsyms]   [k] do_futex                                                                                                                           ▒
+   12.82%     0.00%  java     libjvm.so           [.] Compile::Code_Gen                                                                                                                  ▒
+   10.37%     0.04%  java     libjvm.so           [.] PhaseChaitin::Register_Allocate                                                                                                    ▒
+   10.33%     0.64%  java     [kernel.kallsyms]   [k] futex_wait                                                                                                                         ▒
+    9.06%     0.24%  java     libjvm.so           [.] WatcherThread::run                                                                                                                 ▒
+    8.86%     0.37%  java     [kernel.kallsyms]   [k] futex_wait_queue_me                                                                                                                ▒
+    7.37%     0.05%  java     libjvm.so           [.] Monitor::wait                                                                                                                      ▒
+    7.34%     0.00%  java     perf-4448.map       [.] 0x00007fa36b2ac3f1                                                                                                                 ▒
+    7.15%     0.23%  java     libjvm.so           [.] Monitor::IWait                                                                                                                     ▒
+    7.11%     0.19%  java     libjvm.so           [.] JVM_Sleep                                                                                                                          ▒
+    6.22%     0.08%  java     [kernel.kallsyms]   [k] schedule                                                                                                                           ▒
+    6.12%     0.34%  java     libjvm.so           [.] os::sleep                                                                                                                          ▒
+    6.12%     0.08%  java     [kernel.kallsyms]   [k] __schedule                                                                                                                         ▒
+    5.75%     5.75%  java     [kernel.kallsyms]   [k] finish_task_switch                                                                                                                 ▒
+    5.59%     0.00%  java     perf-4448.map       [.] 0x00007fa36aade35d                                                                                                                 ▒
+    5.39%     0.00%  java     [unknown]           [k] 0x8a201b2020000cf7                                                                                                                 ▒
+    4.96%     0.00%  java     perf-4448.map       [.] 0x00007fa36b3756ec                                                                                                                 ▒
+    4.77%     0.00%  java     perf-4448.map       [.] 0x00007fa36b2ba1a8                                                                                                                 ▒
+    4.55%     0.04%  java     libjvm.so           [.] JVM_MonitorWait                                                                                                                    ▒
+    4.18%     0.00%  java     libjvm.so           [.] Compile::Optimize                                                                                                                  ▒
+    3.83%     3.83%  java     [kernel.kallsyms]   [k] _raw_spin_unlock_irqrestore                                                                                                        ▒
+    3.76%     0.04%  java     libjvm.so           [.] VMThread::loop                                                                                                                     ▒
+    3.76%     0.00%  java     libjvm.so           [.] VMThread::run                                                                                                                      ▒
+    3.75%     0.31%  java     libjvm.so           [.] ObjectMonitor::wait                                                                                                                ▒
+    3.63%     0.00%  java     perf-4448.map       [.] 0x00007fa36b0fad24                                                                                                                 ▒
+    3.62%     0.00%  java     libjvm.so           [.] Compilation::compile_method                                                                                                        ▒
+    3.62%     0.00%  java     libjvm.so           [.] Compilation::Compilation                                                                                                           ▒
+    3.62%     0.00%  java     libjvm.so           [.] Compiler::compile_method

扩展

关于Linux 系统层面的监控和分析工具,也是很好的用于排查各种问题的切入点

  • pmap
  • pref
  • strace
  • gdb
  • /proc/pid 下的进程各种信息
  • tcpdump

这些工具的用法,及其背后的计算机原理,后续会针对性补充!




如果本篇文章对您有所帮助,您可以通过微信(左)或支付宝(右)对作者进行打赏!


上一篇     下一篇