一次jvm进程内存泄露问题的处理

浏览数：36 / 时间：2015年06月20日

当已经知道一个问题是由于内存泄露引起的时候，问题反而简单了，难点在于前期的识别工作。一款负责国际漫游来访业务处理的平台，其主力业务进程为amms，运行在jvm上，问题开始时的现象如下：

1、amms进程的cpu占用异常，在业务量没有变化的情况下，以前是1%以下，业务异常前，飙到了20%

2、进程不会停止，也不会hang，但业务处理的成功率大幅下降，与其它模块的socket连接出现异常

3、amms进程重启后，业务可恢复，但过一阵子，又出现了类似问题

第3点非常像内存泄露问题所产生的现象，于是开始往这个方向排查。（27833为amms进程号）

1、[roamware@/opt/Roamware]jstat -gcutil 27833 1000
S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT
0.00   0.00 97.14 100.00 98.59 34785 134.042 9473 6525.139 6659.182
0.00   0.00 98.23 100.00 98.59 34785 134.042 9473 6525.139 6659.182
0.00   0.00 99.71 100.00 98.59 34785 134.042 9473 6525.139 6659.182
0.00   0.00 36.63 100.00 98.59 34785 134.042 9474 6525.908 6659.950
0.00   0.00 39.33 100.00 98.59 34785 134.042 9474 6525.908 6659.950
0.00   0.00 40.92 100.00 98.59 34785 134.042 9474 6525.908 6659.950
0.00   0.00 42.45 100.00 98.59 34785 134.042 9474 6525.908 6659.950
0.00   0.00 44.54 100.00 98.59 34785 134.042 9474 6525.908 6659.950
0.00   0.00 46.66 100.00 98.59 34785 134.042 9474 6525.908 6659.950
0.00   0.00 48.38 100.00 98.59 34785 134.042 9474 6525.908 6659.950
0.00   0.00 50.64 100.00 98.59 34785 134.042 9474 6525.908 6659.950
0.00   0.00 52.19 100.00 98.59 34785 134.042 9474 6525.908 6659.950

重点看FGC和FGCT，一个是自程序启动后Full GC的次数，另一个是每次FullGC所花时间（单位为ms)

可以看到，这两个值非常大。为什么jvm需要不断进行Full GC？极有可能是内存泄露了。当然了，还有一点是给jvm设定的内存确实太小了，由于业务并发量的增长不够用了，但前面已经排除了这一点，即，业务量并没有突变。

2、为进一步判断问题，需打开amms的gc日志和dump开关，修改amms的启动项。

修改前为：

nohup java -Dapp="$APPNAME" -server -Xmx1024m -Xms1024m -XX:+UseParallelOldGC
-XX:+UseParallelGC
-XX:ParallelGCThreads=8
com.roamware.sds2.fsmlib.FSMApp &

修改之后为：

nohup java -Dapp="$APPNAME" -server -Xmx1024m -Xms1024m -XX:+UseParallelOldGC
-XX:+UseParallelGC
-XX:ParallelGCThreads=8
-verbose:gc
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps -Xloggc:/logs/tmp/gc.log
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/logs/tmp
com.roamware.sds2.fsmlib.FSMApp &

经过几天的运行后，我们可以对/logs/tmp/gc.log进行分析，有多个维度对gc.log进行观察：

1）观察每次Young GC后，heap占用的趋势；

2015-03-04T15:41:10.458+0800: 229192.000: [GC [PSYoungGen: 347688K->2064K(347904K)] 592499K->247183K(1048320K), 0.0033389 secs] [Tim
es: user=0.02 sys=0.00, real=0.00 secs]
2015-03-04T15:41:42.476+0800: 229224.018: [GC [PSYoungGen: 347664K->2096K(347904K)] 592783K->247523K(1048320K), 0.0032800 secs] [Tim
es: user=0.02 sys=0.00, real=0.00 secs]

这里红色字体的变动就是。

2）观察每次Full GC后，heap占用的趋势；

2014-09-26T19:30:35.237+0800: 81312.973: [Full GC [PSYoungGen: 2160K->0K(347584K)] [ParOldGen: 700192K->102156K(700416K)] 702352K->102156K(1048000K) [PSPermGen: 33220K->32817K(65536K)], 0.3760642 secs] [Times: user=1.52 sys=0.03, real=0.38 secs]
2014-09-27T17:34:34.580+0800: 160751.869: [Full GC [PSYoungGen: 2208K->0K(347328K)] [ParOldGen: 700222K->128688K(700416K)] 702430K->128688K(1047744K) [PSPermGen: 32938K->32844K(65536K)], 0.3050225 secs] [Times: user=1.65 sys=0.00, real=0.31 secs]
2014-09-28T15:35:46.788+0800: 240023.635: [Full GC [PSYoungGen: 2384K->0K(347584K)] [ParOldGen: 700261K->134673K(700416K)] 702645K->134673K(1048000K) [PSPermGen: 33005K->32871K(65536K)], 0.4849297 secs] [Times: user=2.25 sys=0.00, real=0.48 secs]

3）观察Full GC的频率（即每多少次Young GC后引发一次Full GC），辅助观察Full GC所花的时间

如果在一个较长的观察周期内，这些数值都是不断累加的，那么便进一步确认了存在内存泄露的可能性。

3、既然知道了内存泄露，就可以开始用工具分析dump了。前面已经增加了对amms进程增加输出dump（当内存耗尽时）的option，如果想手工马上生成，命令如下：

[roamware@/opt/Roamware]jmap -dump:format=b,file=/opt/Roamware/amms_dump.bin 27833
Dumping heap to /opt/Roamware/amms_dump.bin ...
Heap dump file created

其中27833为amms的pid

分析工具推荐MemoryAnalyzer，这个工具有eclipse插件版，也有独立可直接安装在win上的版本。

分析后可初步判断长期驻留在heap里面的东西是什么数据结构。