JVM调优和OOM – 先知先觉的博客

一、问题描述

部分银行的支付交易会通过银保通专线使用Socket进行通信，在银保通前置机（Windows Server 2012R）上使用 SocketDispatch 小程序对请求进行转发操作，长时间的运行会出现宕机问题，通过查询错误日志发现服务出现了内存溢出异常（OutOfMemoryError， OOM）。

二、问题定位

1.日志分析

Exception in thread "Thread-14" java.lang.OutOfMemoryError: Java heap space
	at javax.swing.text.GapContent.allocateArray(GapContent.java:94)
	at javax.swing.text.GapVector.resize(GapVector.java:214)
	at javax.swing.text.GapVector.shiftEnd(GapVector.java:229)
	at javax.swing.text.GapContent.shiftEnd(GapContent.java:345)
	at javax.swing.text.GapVector.open(GapVector.java:201)
	at javax.swing.text.GapVector.replace(GapVector.java:142)
	at javax.swing.text.GapContent.insertString(GapContent.java:132)
	at javax.swing.text.AbstractDocument.handleInsertString(AbstractDocument.java:724)
	at javax.swing.text.AbstractDocument.insertString(AbstractDocument.java:708)
	at javax.swing.text.PlainDocument.insertString(PlainDocument.java:130)
	at javax.swing.JTextArea.append(JTextArea.java:477)
	at click.ButtonFrame2.appendLogger(ButtonFrame2.java:87)
	at click.Server.run(Server.java:65)

ButtonFrame2类是SocketDispatch 小程序的控制页面，appendLogger为日志打印方法，控制页面在打印客户端请求日志时发生了OO异常。

Java 堆内存溢出（Heap Memory)主要有两种形式的错误：

OutOfMemoryError: Java heap space
OutOfMemoryError: GC overhead limit exceeded

OutOfMemoryError: Java heap space

在 Java 堆中只要不断的创建对象，并且 GC-Roots 到对象之间存在引用链，这样 JVM 就不会回收对象。对象的生命周期过长，再次创建新的对象时就会发生堆内存溢出。

OutOfMemoryError: GC overhead limit exceeded

GC overhead limt exceed检查是Hotspot VM 1.6定义的一个策略，通过统计GC时间来预测是否要OOM了，提前抛出异常，防止OOM发生。

2.代码分析

public class ButtonFrame2 extends JFrame {
	static JTextArea jTextArea1 = new JTextArea();
    //.....
    public static void appendLogger(String str) {
		jTextArea1.append("[" + getCurrentDateTime("yyyyMMdd-HH:mm:ss") + "] " + str);
	}

判断一个对象是否可被回收？

Java虚拟机通过可达性分析算法来判断一个对象是否可以被回收，换言之一个对象是否可被回收与引用有关。而被强引用关联的对象不会被回收。

可以看到 jTextArea1 作为静态变量会长时间驻留在服务中，不断地消耗JVM分配给该服务的内存，因此考虑通过将日志保存到本地文件改善该问题

if (inI.length != list.length) {
			SysLog.severe("Transfer Server Error Cfg AllowClient : " + route.toString());
			return false;//保持日志到本地文件
}

此时OOM问题并没有完全确定，因为可能存在其他对象使用相同的方法不断的在消耗堆内存。因此有必要通过压测进一步验证。

3.压力测试

测试前准备：

将SocketDispatch 项目打包为jar包，使用如下指令进行启动：

java -jar -server -Xmx50m -Xms50m -Xmn12m -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=70 -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./my-heap-dump02.hprof SocketDispatch.jar click.ButtonFrame2

参数说明如下：

-Xmx50m ：堆最小值

-Xms50m ：堆最大堆值。-Xms与-Xmx 的单位默认字节都是以k、m做单位的。通常这两个配置参数相等，避免每次空间不足，动态扩容带来的影响

-Xmn12m ：新生代大小

-XX:+UseConcMarkSweepGC：新生代使用并行，老年代使用CMS(一般都是使用这种方式)，CMS是Concurrent Mark Sweep的缩写，并发标记清除

-XX:+CMSParallelRemarkEnabled ：降低标记停顿

-XX:CMSInitiatingOccupancyFraction=70 ：使用CMS作为垃圾回收，使用70%后开始CMS收集

-verbose:gc ：输出JVM的GC情况

-XX:+PrintGCTimeStamps ：打印GC时间戳

-XX:+PrintGCDetails ：打印GC详细信息

-Xloggc:gc.log ：GC日志保存文件名

-XX:+HeapDumpOnOutOfMemoryError ：出现OOM时生成dump文件

-XX:HeapDumpPath=./my-heap-dump02.hprof：dump文件保存地址

jps

jps是jdk提供的一个查看当前java进程的小工具，可以看做是JavaVirtual Machine Process Status Tool的缩写。

jmap

命令jmap是一个多功能的命令。它可以生成 java 程序的 dump 文件，也可以查看堆内对象示例的统计信息、查看 ClassLoader 的信息以及 finalizer 队列。

JConsole

Jconsole （Java Monitoring and Management Console），JDK自带的基于JMX的可视化监视、管理工具。官方文档可以参考这里

Eclipse Memory Analyzer (MAT)

MAT 是一种快速且功能丰富的 Java 堆分析器，可帮助你发现内存泄漏并减少内存消耗。 MAT在的堆内存分析问题使用极为广泛，需要重点掌握。可以在这里 (opens new window)下载，官方文档可以看这里

测试过程

启动 SocketDispatch 时，同时启动Jconsole 选择本地本地进程 SocketDispatch.jar click.ButtonFrame2，如下图所示：

本地启动5个线程，每个线程对该服务其中一个端口循环请求2000次，连续测试3轮，每轮间隔10秒钟，Jconsole效果显示如下：

可以看到堆内存的使用情况，三轮压力测试过程中，整体的内存占用比例呈上升趋势，GC 日志如下：

26.047: [GC (CMS Initial Mark) [1 CMS-initial-mark: 19940K(38912K)] 21219K(49984K), 0.0014178 secs] [Times: user=0.13 sys=0.00, real=0.00 secs] 
26.049: [CMS-concurrent-mark-start]
26.060: [CMS-concurrent-mark: 0.010/0.010 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
26.061: [CMS-concurrent-preclean-start]
26.061: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
26.068: [GC (CMS Final Remark) [YG occupancy: 2126 K (11072 K)]26.068: [Rescan (parallel) , 0.0013849 secs]26.070: [weak refs processing, 0.0000339 secs]26.070: [class unloading, 0.0045367 secs]26.074: [scrub symbol table, 0.0011438 secs]26.075: [scrub string table, 0.0002137 secs][1 CMS-remark: 19940K(38912K)] 22067K(49984K), 0.0077287 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
26.077: [CMS-concurrent-sweep-start]
26.082: [CMS-concurrent-sweep: 0.005/0.005 secs] [Times: user=0.03 sys=0.03, real=0.00 secs] 
26.082: [CMS-concurrent-reset-start]

Java 垃圾回收器使用CMS对老生代对象进行回收，但并没有阻止内存持续升高。

使用MAT对生成的dump文件进行分析，如下图所示：

这里重点分析 dominator_tree 视图，可以看到每个对象占用内存的比例

com.sun.jmx.remote.internal.ArrayNotificationBuffer ：该对象为JAVA自带的JMX监视程序使用，可忽略

click.Server ：为服务启动时监听各个端口的请求服务

java.lang.ref.Finalizer：当某个类重写了finalize()方法，JVM在GC时会判断该对象是否执行了finalize方法，如果没有执行，则将对象放到由JVM创建的Finalizer线程维护的F-Queue（java.lang.ref.Finalizer.ReferenceQueue）队列中，具体说明可请参考这里

打开 click.Server 效果如下：

可以看到这里有个 Vector 集合类对象，里面存储了大量的 click.Transfer 对象，对象个数和压测过程中的请求总数保持一致，可以判断OOM的原因在于该对象没有及时释放。

再次分析代码：

package click;
//...
public class Server{
//...    
if (checkIP(route, clientIP)) {
    SysLog.info("Transfer Server : " + route.toString() + "  Incoming:" + sock.getInetAddress());
    sock.setSoTimeout(0);
    connCounter++;
    Transfer myt = new Transfer(sock, route);
    connectionQueue.add(myt);//问题代码
}
//...
private Vector connectionQueue = null;
//...
}

connectionQueue 用于保存每次请求的Transfer信息，而 Server 对象为强引用对象，一直存在于服务运行过程中。

修复bug:

if (checkIP(route, clientIP)) {
    SysLog.info("Transfer Server : " + route.toString() + "  Incoming:" + sock.getInetAddress());
    sock.setSoTimeout(0);
    connCounter++;
    new Transfer(sock, route);
    //connectionQueue.add(myt);
}

重新进行压测，Jconsole效果如下：

可以看到在内存达到近70%的情况下，GC 通过CMS垃圾回收器对内存进行回收，保证内存使用情况正常

JVM参数优化

SocketDispatch 实际通过exe4j 打包为exe文件在前置机上运行，通过在同目录下新增 SocketDisPatch.exe.vmoptions文件配置JVM参数，考虑到银保通前置的硬件配置情况，以及收付费系统请求的并发量，完整JVM参数如下：

-Xmx100m
-Xms100m
-Xmn25m
-XX:+DisableExplicitGC
-XX:+UseConcMarkSweepGC
-XX:+CMSParallelRemarkEnabled
-XX:+UseCMSInitiatingOccupancyOnly
-XX:CMSInitiatingOccupancyFraction=70
-verbose:gc
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-Xloggc:./log/gc-%t.log
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=14
-XX:GCLogFileSize=100M
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=./my-heap-dump.hprof

参数说明：

-XX:+PrintGCDateStamps：打印日期

-Xloggc:./log/gc-%t.log：GC日志输出的文件路径

-XX:+UseGCLogFileRotation：开启日志文件分割

-XX:NumberOfGCLogFiles=14：最多分割几个文件，超过之后从头开始写

-XX:GCLogFileSize=100M：每个文件上限大小，超过就触发分割

生产环境更新应用后，内存使用保持在44.8MB上下，并未出现内存持续升高现象，如下图所示：

三、总结

本次Java问题排查只用到了基本的调试工具，如：jps，jmap，jconsole，mat，还有更多进阶调试工具 btrace，Arthas 等适合分析更复杂的JVM问题。
系统服务在生产部署时可通过添加启动参数打印GC日志，在发生OOM时生成dump文件，保留事故发生现场，便于后续的问题分析。
Java原生的Socket类在处理网络请求时存在性能不足等问题，建议使用netty实现，后续考虑进行替换。

本文作者:jonyliu, 联系方式：liu_zengqiang@126.com