标签：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)。最后发现是由于外部网元发送的消息中的一个字段，不符合平台逻辑所引起的。
小结：
对于生产系统来说，内存泄露问题分为内部引发和外部引发两种，此次问题为外部引发，这种问题较难在版本测试过程中发现。
本文出自 “记忆碎片” 博客，请务必保留此出处http://weikle.blog.51cto.com/3324327/1617277
标签：jvm 内存泄露
原文地址：http://weikle.blog.51cto.com/3324327/1617277
