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

当已经知道一个问题是由于内存泄露引起的时候，问题反而简单了，难点在于前期的识别工作。一款负责国际漫游来访业务处理的平台，其主力业务进程为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里面的东西是什么数据结构。

这里可以看到，有一个存储在ConcurrentHashMapCache中的数据(FSM状态机)长期驻留在jvm heap，高达763M，而且每个生产线程都有。于是，尝试从业务日志找寻信息，看是否有状态机没有被正常释放。

果然，找到了很多“Saved to persistent store”的日志(正常应该是Release)。最后发现是由于外部网元发送的消息中的一个字段，不符合平台逻辑所引起的。

小结：

1)对于生产系统来说，内存泄露问题分为内部引发和外部引发两种，此次问题为外部引发，这种问题较难在版本测试过程中发现。

2)可以模拟出一种内存泄露的极端情况：

2014-07-02T09:53:18.073+0800: 39.583: [Full GC [PSYoungGen: 1791K->1791K(2880K)] [ParOldGen: 8190K->8190K(8192K)] 9982K->9982K(11072K) [PSPermGen: 25096K->25096K(26624K)]      GC time would exceed GCTimeLimit of 98%

2014-07-02T09:53:18.973+0800: 40.483: [Full GC [PSYoungGen: 1791K->1791K(2880K)] [ParOldGen: 8190K->8190K(8192K)] 9982K->9982K(11072K) [PSPermGen: 25096K->25096K(26624K)]      GC time would exceed GCTimeLimit of 98%

2014-07-02T09:53:19.466+0800: 40.977: [Full GC [PSYoungGen: 1791K->1791K(2880K)] [ParOldGen: 8190K->8190K(8192K)] 9982K->9982K(11072K) [PSPermGen: 25096K->25096K(26624K)]      GC time would exceed GCTimeLimit of 98%

可以看到，此时jvm通过FGC已经捣腾不出任何空间了，heap占用在FGC前后无任何变化。