您的位置：首页 > 其它

JVM成长之路,记录一次内存溢出导致频繁FGC的问题排查及解决

2017-08-04 21:57 1406 查看

现象：

现象截图：

内存：

命令： jmap -heap 30069

GC截图：

FGC 次数 19529 次！！！何等的恐怖！！！！！

命令： jstat -gcutil 30069 1000

现象描述：

Node模块启动后收到请求却未能响应。一直在频繁的FGC。新生代内存爆满。老年代内存爆满！

开始分析：

启动Xmx参数为 -Xmx 128M -Xms 128M
第一次修改： -Xmx 256M -Xms 256M 效果仍然不好 FGC。

=============================================
运行一两天后，Node再次未响应！！！！
=============================================

使用命令查看启动参数：jps -m -l -v

30069 jars/dubhe-node-frame-1.0.0.jar com.dtwave.dipper.dubhe.node.DubheNode --spring.profiles.active=prd -Xms256m -Xmx256m -Xmn64m

什么情况？？？

新生代大小大概是 3/8 256 * 3/8 有 120M 可是却被限制到 64M ....

Xmn只分配了64M。一旦读日志。新生代满了就直接分配到老年代了！！
于是去掉了这个参数给Xmn一个自由！！！

=============================================
运行一两天后，Node再次未响应！！！！
=============================================

于是。给xmx翻个倍！
第二次修改：-Xmx 512M -Xms 512M

这样新生代是3/8 170M 了。这样总没问题了吧！！

=============================================

可是。。。。。。。运行一两天后，Node再次未响应！！！！看来之前的解决方法是错的！！错的！！错的！！

根本不是什么堆空间大小的问题。

=============================================

到底是什么情况！！！！！！！！！！！！！！！！！！！！！！！！！
那就来看看堆里面到底藏了些什么！！！
执行命令：jamp -histro 14273

num #instances #bytes class name

----------------------------------------------

 1: 1001750 155802576 [B

 2: 137954 32307952 [C

 3: 983424 23602176 java.util.LinkedList$Node

 4: 134617 3230808 java.lang.String

 5: 34867 3091056 [Ljava.util.HashMap$Node;

 6: 74748 2391936 java.util.HashMap$Node

 7: 34156 1639488 java.util.HashMap

 8: 8932 1523896 [Ljava.lang.Object;

 9: 8216 1508664 [Ljava.util.concurrent.ConcurrentHashMap$Node;

 10: 16393 1311440 org.apache.zookeeper.data.Stat

 11: 35150 1124800 java.util.concurrent.ConcurrentHashMap$Node

 12: 7604 847288 java.lang.Class

 13: 49187 786992 java.util.concurrent.atomic.AtomicReference

 14: 16393 655720 org.apache.curator.framework.recipes.cache.TreeCache$TreeNode

 15: 1704 640704 java.lang.Thread

 16: 8373 535872 java.util.concurrent.ConcurrentHashMap

 17: 33135 530160 java.util.HashSet

这是什么？？？

1: 1001750 155802576 [B

果断看不出这是什么？

回忆一下：

比较明显的现象：

1. O区满的。

2. E区却没有满。

[deploy@dipper_prd_2 ~]$ jstat -gccause 26003 1000

S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC

0.00 0.00 58.63 99.93 97.37 96.66 280 6.302 111 37.851 44.153 Allocation Failure No GC

3.FGC 次数增了，YGC倒是没有增长。

E区没满，O却满了。！！有什么奇怪的东西跑进了O区吗？？？？？？？看了一下代码。最近Node修改的只有日志。读日志！！读日志生成的对象 E没满并不会进O区！排除读日志的影响！

那到底是什么奇怪的东西进入了O区？？

看了一圈代码。发现不了问题。。

只能用终极大法了。dump堆内存分析。

dump堆内存到文件中通过MAT软件分析。

命令： jmap -dump:format=b,file=jconsole.dump 26003

安装好eclipse的memory analysis tool （MAT），切换成mat视图。将文件导入到eclipse中。

不分析不知道。一分析吓一跳！！看到没有，内存中最大的那块区域！！是一个concurrentHashMap！！！！！！！！！

原来是有个concurrentHashMap在作怪！！

为什么这个对象会占据如此多的内存！查看代码后发现。这个concurrentHashMap 在NodeContext中。

这个数据结构存储了所有运行的作业的信息。每新进一个作业，会在此结构添加一个Code对象。

然而。从未调用过remove方法！！！！！！这块又是个单例对象的static对象，从来不会被回收。只进不出，内存溢出！Node跑一两天就完蛋！！

public class NodeContext{

private static NodeContext ourInstance = new NodeContext();

 //存储用户的代码
 private static Map<String, Code> codesMap;

public static NodeContext singleton() {
return ourInstance;
 }

private NodeContext() {
codesMap = new ConcurrentHashMap<>();
 scheduler = SchedulerFactory.singleton().createOrGetParallelScheduler(NodeConfig.PARALLELISM_MAX_NUM);
 }

}

解决：

解决过程中又遇到了一个坑！！！

错误解决：在一个实例运行完的代码finally部分调用NodeContext.remove(codeId) 移除掉这个运行的实例！！！

发布测试环境！！！运行报错！！！！

正确解决：

在监听实例上报状态到ZK后再做这个移除操作！！！

修改后的现象：

第一天：

S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC

0.00 18.29 97.31 50.26 97.42 95.25 41 0.855 2 0.393 1.247 Allocation Failure No GC

0.00 18.29 97.80 50.26 97.42 95.25 41 0.855 2 0.393 1.247 Allocation Failure No GC

0.00 18.29 99.27 50.26 97.42 95.25 41 0.855 2 0.393 1.247 Allocation Failure No GC

21.00 0.00 0.07 50.27 96.99 95.31 42 0.879 2 0.393 1.272 Allocation Failure No GC

21.00 0.00 0.89 50.27 96.99 95.31 42 0.879 2 0.393 1.272 Allocation Failure No GC

21.00 0.00 2.12 50.27 96.99 95.31 42 0.879 2 0.393 1.272 Allocation Failure No GC

21.00 0.00 2.95 50.27 96.99 95.31 42 0.879 2 0.393 1.272 Allocation Failure No GC

21.00 0.00 3.91 50.27 96.99 95.31 42 0.879 2 0.393 1.272 Allocation Failure No GC

21.00 0.00 4.49 50.27 96.99 95.31 42 0.879 2 0.393 1.272 Allocation Failure No GC

21.00 0.00 5.10 50.27 96.99 95.31 42 0.879 2 0.393 1.272 Allocation Failure No GC

第二天：O区只增长了2%

S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC

0.00 97.82 50.26 52.21 97.59 95.44 53 1.012 2 0.393 1.405 Allocation Failure No GC

0.00 97.82 50.26 52.21 97.59 95.44 53 1.012 2 0.393 1.405 Allocation Failure No GC

0.00 97.82 50.26 52.21 97.59 95.44 53 1.012 2 0.393 1.405 Allocation Failure No GC

0.00 97.82 50.26 52.21 97.59 95.44 53 1.012 2 0.393 1.405 Allocation Failure No GC

0.00 97.82 50.26 52.21 97.59 95.44 53 1.012 2 0.393 1.405 Allocation Failure No GC

0.00 97.82 50.26 52.21 97.59 95.44 53 1.012 2 0.393 1.405 Allocation Failure No GC

0.00 97.82 50.27 52.21 97.59 95.44 53 1.012 2 0.393 1.405 Allocation Failure No GC

0.00 97.82 50.27 52.21 97.59 95.44 53 1.012 2 0.393 1.405 Allocation Failure No GC

0.00 97.82 50.27 52.21 97.59 95.44 53 1.012 2 0.393 1.405 Allocation Failure No GC

若干天后：发生了一次FGC 但是 O区已经降低至 30.18% 到此，成功解决此内存溢出的问题！！！

[deploy@dipper_prd_2 ~]$ jstat -gcutil 3519 1000

S0 S1 E O M CCS YGC YGCT FGC FGCT GCT

0.00 4.45 65.14 30.18 96.89 93.87 671 5.568 3 0.742 6.310

0.00 4.45 65.14 30.18 96.89 93.87 671 5.568 3 0.742 6.310

0.00 4.45 65.14 30.18 96.89 93.87 671 5.568 3 0.742 6.310

0.00 4.45 65.15 30.18 96.89 93.87 671 5.568 3 0.742 6.310

0.00 4.45 65.15 30.18 96.89 93.87 671 5.568 3 0.742 6.310

0.00 4.45 65.15 30.18 96.89 93.87 671 5.568 3 0.742 6.310

0.00 4.45 65.15 30.18 96.89 93.87 671 5.568 3 0.742 6.310

0.00 4.45 65.15 30.18 96.89 93.87 671 5.568 3 0.742 6.310

0.00 4.45 65.18 30.18 96.89 93.87 671 5.568 3 0.742 6.310

0.00 4.45 65.18 30.18 96.89 93.87 671 5.568 3 0.742 6.310

内容来自用户分享和网络整理，不保证内容的准确性，如有侵权内容，可联系管理员处理

标签：

相关文章推荐

新的分享

章节导航