GC问题排查实战二

JDK低版本的bug(GCLocker Initiated GC)的问题

接着上篇，这个就很奇怪，前面刚经过一次young gc，怎么又来，而且年轻代没满，收集了一点点，于是只能百度了，然后发现这个bug，是低版本的，刚好我们用的是1.8.0_162，所以应该要升级下：

具体资料可以看这里：
https://bugs.java.com/bugdatabase/view_bug.do?bug_id=JDK-8048556

具体原因是说为了解决临界区数据一致性的问题，有兴趣的可以看下：

https://www.jianshu.com/p/40e0b88bf5e7?utm_campaign=maleskine&utm_content=note&utm_medium=seo_notes&utm_source=recommendation

https://www.jianshu.com/p/ecc57a81f73c

然后统计了下这个GC的时间，差不多就是在那段时间：


其实后面分析GC CAUSE里也会有显示的。

CMS的最终标记触发young gc的问题

还有一个点触发了young gc回收了580M左右：

然后查看日志，发现CMS在做最终标记的时候触发了一次：

这个原因是因为用了CMS参数**-XX:+CMSScavengeBeforeRemark**，这个作用是因为老年代和年轻代之间的对象存在跨代引用，重新标记的内存范围是整个堆，如果被新生代中的对象引用，那么就会被视为存活对象，即使新生代的对象已经不可达了，也会使用这些不可达的对象当做cms的GC ROOT，来扫描老年代；因此young gc回收掉年轻代无用的对象，并将对象放入幸存带或晋升到老年代，再进行年轻带扫描时，只需要扫描幸存区的对象即可，可以提升效率。

年轻代GC信息分析

看上去也是2个地方好奇怪的，我们放大来看第一个段的：

这个时间段应该就是触发GCLocker Initiated GC的时候，很少的量也触发了，上图对应的是这条：

然后是第二个段应该就是CMS的最终标记之前做的young gc：

老年代GC情况分析

看上还算正常，第4段的时候因为磁盘满了GC信息有丢失，所以有点异常：

年轻代分配和晋升情况分析

这个就分析下突然分配多的点吧，少的点其实就是young gc之后又进行了GCLocker Initiated GC以及CMS的最终标记的时候进行了young gc。看下好像是8:37的时候出现了突然分配多了。

这个估计只能看日志了，发现没有分配那么大的，可能是GC日志不全的问题吧，然后到10点左右有日志了，就恢复正常了：

CMS回收阶段统计分析

可以得到信息：

• 年轻代回收平均8秒一次，回收时间最大480毫秒，可以分析下具体日志
• 老年代进行了4次回收，接近5小时一次，STW的时间最大是290+40=330毫秒，基本消耗在最终标记，可以想办法看看怎么优化
• 可中断的预清理阶段时间不长，可以适当调大CMSMaxAbortablePrecleanTime，将时间拉长，减轻最终标记的压力

找个分析下：

2022-03-03T12:50:13.770+0800: 75377.425: [GC (CMS Final Remark) [YG occupancy: 625903 K (3844800 K)]2022-03-03T12:50:13.770+0800: 75377.425: [GC (CMS Final Remark) 2022-03-03T12:50:13.770+0800: 75377.425: [ParNew: 625903K->29681K(3844800K), 0.0408742 secs] 4820738K->4226018K(12233408K), 0.0409565 secs] [Times: user=0.30 sys=0.00, real=0.04 secs] 
2022-03-03T12:50:13.811+0800: 75377.466: [Rescan (parallel) , 0.0240361 secs]2022-03-03T12:50:13.835+0800: 75377.490: [weak refs processing, 0.0594047 secs]2022-03-03T12:50:13.894+0800: 75377.549: [class unloading, 0.0824481 secs]2022-03-03T12:50:13.977+0800: 75377.632: [scrub symbol table, 0.0313951 secs]2022-03-03T12:50:14.008+0800: 75377.663: [scrub string table, 0.0024446 secs][1 CMS-remark: 4196337K(8388608K)] 4226018K(12233408K), 0.2752567 secs] [Times: user=0.70 sys=0.00, real=0.27 secs] 

最终标记的几个步骤耗时，如果有特别长的要进行优化：

步骤	耗时
YG occupancy	0.0409565
Rescan (parallel)	0.0240361
weak refs processing	0.0594047
class unloading	0.0824481
scrub symbol table	0.0313951
scrub string table	0.0024446

垃圾生成分析

内存泄露分析

GC的原因

没有出现晋升问题和并发内存分配失败问题：

总结

其实大致过程就是看GC的次数和时间，当然你要整体来看有没什么问题是需要有一些工具的，比如gceasy的这种可视化工具，可以一下子看到问题，不然你得一条条日志看过去，也不可能。当然具体的怎么调优肯定是看STW的阶段耗时，怎么让他次数更加少，时间更加少，还要结合业务，调整一下参数，这个可能确实和具体业务场景相关，也很难通用，当然方法应该是差不多的，比如你这里发现最终标记耗时，那就看怎么让他耗时少点，比如让前面并发的一些步骤多做点事，这样就可以减轻后面的压力，比如来一次young gc，回收掉点垃圾，减少跨代引用扫描，这个还是要去理解每个步骤干了什么，有什么参数可以调节等等，具体还是要多多实践拉。

好了，今天就到这里了，希望对学习理解有帮助，大神看见勿喷，仅为自己的学习理解，能力有限。