CMS GC log weak refs processing 耗时长问题 分析

Question

问题描述

线上服务 运行一段时间后，出现 服务调用超时情况，一看gc log发现 cms gc大概用了 57 秒，求分析下可能的原因

gc log

2019-03-18T17:14:12.361+0800: 5445049.475: [GC (CMS Initial Mark) [1 CMS-initial-mark: 917512K(1310720K)] 919654K(2018560K), 0.2888816 secs] [Times: user=0.00 sys=0.07, real=0.29 secs] 
2019-03-18T17:14:12.650+0800: 5445049.772: [CMS-concurrent-mark-start]
2019-03-18T17:14:27.695+0800: 5445064.809: [CMS-concurrent-mark: 15.022/15.037 secs] [Times: user=14.52 sys=2.13, real=15.05 secs] 
2019-03-18T17:14:27.695+0800: 5445064.810: [CMS-concurrent-preclean-start]
2019-03-18T17:14:27.762+0800: 5445064.877: [CMS-concurrent-preclean: 0.067/0.067 secs] [Times: user=0.03 sys=0.00, real=0.06 secs] 
2019-03-18T17:14:27.762+0800: 5445064.877: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2019-03-18T17:14:32.779+0800: 5445069.894: [CMS-concurrent-abortable-preclean: 1.112/5.017 secs] [Times: user=1.76 sys=0.00, real=5.02 secs] 
2019-03-18T17:14:32.794+0800: 5445069.909: [GC (CMS Final Remark) [YG occupancy: 72917 K (707840 K)]2019-03-18T17:14:32.795+0800: 5445069.909: [GC (CMS Final Remark) 2019-03-18T17:14:32.795+0800: 54
45069.910: [ParNew: 72917K->1081K(707840K), 0.0163264 secs] 990430K->918675K(2018560K), 0.0167292 secs] [Times: user=0.34 sys=0.00, real=0.01 secs] 
2019-03-18T17:14:32.811+0800: 5445069.926: [Rescan (parallel) , 0.0205543 secs]2019-03-18T17:14:32.832+0800: 5445069.947: [weak refs processing, 47.5740649 secs]2019-03-18T17:15:20.406+0800: 5445117
.521: [class unloading, 8.0378325 secs]2019-03-18T17:15:28.444+0800: 5445125.559: [scrub symbol table, 2.2831109 secs]2019-03-18T17:15:30.727+0800: 5445127.842: [scrub string table, 0.0049668 secs][
1 CMS-remark: 917594K(1310720K)] 918675K(2018560K), 57.9695775 secs] [Times: user=1.09 sys=1.95, real=57.97 secs] 
2019-03-18T17:15:30.766+0800: 5445127.880: [CMS-concurrent-sweep-start]
2019-03-18T17:16:25.035+0800: 5445182.150: [CMS-concurrent-sweep: 53.746/54.270 secs] [Times: user=9.39 sys=12.02, real=54.27 secs] 
2019-03-18T17:16:25.039+0800: 5445182.153: [CMS-concurrent-reset-start]
2019-03-18T17:16:25.250+0800: 5445182.365: [CMS-concurrent-reset: 0.212/0.212 secs] [Times: user=0.00 sys=0.07, real=0.21 secs] 

如上，remark阶段用了 57.9695775 secs，其中 weak refs processing 用了 47.5740649 secs，求分析

配置如下

-Xmn768m 
-Xms2048m 
-Xmx2048m 
-XX:MetaspaceSize=128m 
-XX:MaxMetaspaceSize=512m 
-XX:+UseConcMarkSweepGC 
-XX:+UseParNewGC 
-XX:+CMSParallelRemarkEnabled 
-XX:+UseFastAccessorMethods 
-XX:CMSInitiatingOccupancyFraction=70 
-XX:+CMSScavengeBeforeRemark 
-XX:+ExplicitGCInvokesConcurrent

当时没保留现场，是什么 能导致 weak refs processing耗时这么长？

Answer 1

这可能是由于弱引用过多所引起的，可以减少缓存，或者增加弱引用的并行处理来解决。尝试加入下面的参数：+ParallelRefProcEnabled