java程序异常退出排查

1.前言

由于公司线上的一个服务近期一直异常退出，按照往常经验，内存溢出！启动参数加个打印内存溢出时配置，然后坐等下一次内存溢出出现，再分析一下hprof 具体请 点击查看
添加配置信息 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/usr/webser/logs/error.hprof

然而，事情总不会这么一帆风顺，程序还是照样退出，并且没有dump文件生成，what？？？

2.原因分析

接下来我们带着问题分析
1.为什么没有get到dump文件？
2.为什么程序会down掉？
3.假设是溢出，该怎么配置堆内存？
4.假设是内存溢出，哪里溢出了？

首先我们要知道jvm的内存分配机制 点击查看

于是猜想程序异常退出是不是有两种情况，一种是jvm杀死，一种是linux系统杀死？之后查看linux系统日志如下

.tail -300f /var/log/messages

Apr 17 14:23:41 iZbp1g9hysunkzqd9qadsxZ kernel: Out of memory: Kill process 13466 (java) score 793 or sacrifice child
Apr 17 14:23:41 iZbp1g9hysunkzqd9qadsxZ kernel: Killed process 13466 (java) total-vm:2755444kB, anon-rss:803356kB, file-rss:0kB, shmem-rss:0kB
Apr 17 14:23:41 iZbp1g9hysunkzqd9qadsxZ systemd-logind: Removed session 4071.

由日志可知，确实是内存溢出被杀死了。

那么内存是如何溢出的呢？我们来统计一下内存占用信息

（1）系统未运行程序时的内存信：总共1g，使用了112M，buff 231M，空闲670M

（2）程序初次运行后内存信息：java程序占用469-112 = 357M，buff232M，空闲 313M

（3）那么问题来了，假设我们的堆内存设置了400M会出现什么情况？现在系统的剩余内存是313M，而400M的堆内存目前只使用了 84M（下图展示），代表还有 400-84 = 316M未使用，316>313 这种情况就危险了，假设堆内存使用达到了峰值，那么就会出现内存飙升，linux系统识别到内存不够用了，就把我们的java程序kill掉！下面的信息是通过jmap -heap [进程id]查看java堆内存使用信息

注：上述分析还不包含Meta Space，这个空间是存储永久代对象，如果没有设置它的大小会无限增加

3.如何解决

我们现在知道了是内存溢出的问题，那么哪里溢出了呢，怎么优化呢？我们照样带着问题解决

1.假设是代码编写问题，产生大量对象占用内存（更糟糕的写法的产生的对象没有被回收！！）
2.由上可知1g内存总量，堆内存配置400M过大，那么该如何配置？
3.ecache缓存问题？（用到了ecache，并且手动生成线上的堆dump进行分析，发现ecache占用了大量堆内存）

#生成dump文件
jmap -dump:live,format=b,file=/path/heap.hprof 进程ID

（1）代码上的优化
正确使用ecache，不要丢过多的数据到ecache

正确分配对象，不要产生过多无用对象（更可怕的是无法回收的对象 点击查看对象回收原理）

（2）linux上的优化
由上图可知我们系统的buff偏大（我1g的系统，初始buff正常是100M），可以清理一下 linux buff/cache过大，清理脚本

堆内存配置，由上分析我们可以计算出对内存配置256~320是合理的，大于400M会出现溢出
堆配置一般选择 1024,、512、256、128（为什么要这样分配的，因为磁盘扇区，比如配置260，那么就多分配了一个扇区，导致数据读取要多加载）

4.其他弯路

尝试使用监控工具分析问题（点击查看），然而还不如直接生成dump分析堆内存

#分析日志
nohup /usr/java/jdk1.7.0_71/bin/java -Xms256m -Xmx256m -verbose:gc -Xloggc:/usr/webser/logs/jvmgc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/usr/webser/logs/error.hprof -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal -XX:+PrintGCDetails -XX:+UseG1GC -Dloader.path=/usr/webser/springboot/common_libs/ -jar /usr/webser/springboot/pddapi.jar --spring.config.location=/usr/webser/springboot/pddapi_conf/application.properties --spring.profiles.active=pro,order_pdd > /dev/null 2>&1 &
 

 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.port=9004 -Dcom.sun.management.jmxremote.rmi.port=9004 -Djava.rmi.server.hostname=172.16.223.16
 
nohup java  \
-Djava.rmi.server.hostname=172.16.223.16 \
-Dcom.sun.management.jmxremote.port=9004 \
-Dcom.sun.management.jmxremote.authenticate=false \
-Dcom.sun.management.jmxremote.ssl=false \
-Dloader.path=/usr/webser/springboot/common_libs/ -jar /usr/webser/springboot/pddapi.jar --spring.config.location=/usr/webser/springboot/pddapi_conf/application.properties --spring.profiles.active=pro,order_pdd > /dev/null 2>&1 & 

 
172.16.223.16（内）
47.111.10.xx:9004（外）
monitorRole QED

47.111.10.xx iZbp1g9hysunkzqd9qadsxZ 

 
-XX:+UseG1GC
-XX:+UseCMSCompactAtFullCollection 
-Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.port=9004 -Djava.rmi.server.hostname=47.111.10.xx


nohup /usr/java/jdk1.7.0_71/bin/java -server -Xms400m -Xmx400m -XX:NewSize=256m -XX:MaxNewSize=256m -XX:PermSize=64m -XX:MaxPermSize=128m -Xss256k -Dloader.path=/usr/webser/springboot/common_libs/ -jar /usr/webser/springboot/pddapi.jar --spring.config.location=/usr/webser/springboot/pddapi_conf/application.properties --spring.profiles.active=pro,order_pdd > /dev/null 2>&1 &


[Full GC (Metadata GC Threshold) 28.629: [Tenured: 45403K->49950K(273088K), 0.2043653 secs] 130237K->49950K(395968K), [Metaspace: 57984K->57984K(1101824K)], 0.2044567 secs] [Times: user=0.20 sys=0.01, real=0.20 secs] 

[GC (Allocation Failure) 64.026: [DefNew: 112585K->8406K(122880K), 0.0323023 secs] 162536K->58357K(395968K), 0.0324265 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 

[GC (Allocation Failure) [DefNew: 6144K->0K(9216K), 0.0040708 secs] 0K->0K(19456K), 0.0041138 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
一次分配失败GC，处理新生代从6144K到0 k空间（新生代共9216K空间），堆 共19456K空间）

5.参考

某Java服务异常退出原因排查过程分享
JVM参数MetaspaceSize的误解