GC日志中显示的常见问题和解决方案

本节确定您可能在GC日志中发现的常见问题以及如何解决这些问题。您还可以使用通用GC日志分析器来分析GC日志。

1. Young generation - 太小

以下日志片段显示了年轻一代堆大小太小的问题：

1.813: [GC1.813: [ParNew: 1152K­>128K(1152K), 0.0008100 secs] 16620K­->15756K(26936K), 0.0008350 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.816: [GC1.816: [ParNew: 1152K­>128K(1152K), 0.0006430 secs] 16780K­->15913K(26936K), 0.0006640 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.819: [GC1.819: [ParNew: 1152K­>128K(1152K), 0.0005370 secs] 16937K-­>16038K(26936K), 0.0005570 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

可以看到，一秒钟内发生多个GC。这意味着需要增加年轻代的大小（NewSize和MaxNewSize），并且可能还需要增加堆的总大小来补偿此更改（Xms和Xmx）。或者，可以更改NewRatio选项（默认情况下，该选项设置为2，这意味着长期生成堆的大小是年轻生成堆的两倍，或者年轻生成堆的大小是长期生成堆的1/3）。

2. 年轻代-太大/年老代-太小
   下面的日志片段显示了一个问题，即年轻代堆大小过大，因此年老代堆大小过小：

276.716: [GC (CMS Initial Mark) [1 CMS-initial-mark: 104176K(135168K)] 2758985K(6741248K), 0.8762860 secs] [Times: user=0.88 sys=0.00, real=0.88 secs] 
277.592: [CMS-concurrent-mark-start]
277.657: [CMS-concurrent-mark: 0.063/0.065 secs] [Times: user=0.12 sys=0.00, real=0.06 secs] 
277.657: [CMS-concurrent-preclean-start]
277.658: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
277.658: [CMS-concurrent-abortable-preclean-start]
277.658: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
277.658: [GC (CMS Final Remark)[YG occupancy: 2657419 K (6606080 K)]277.658: [Rescan (parallel) , 0.9815460 secs]278.639: [weak refs processing, 0.0000320 secs]278.640: [scrub string table, 0.0011700 secs] [1 CMS-remark: 104176K(135168K)] 2761595K(6741248K), 0.9828250 secs] [Times: user=7.18 sys=0.09, real=0.99 secs] 
278.641: [CMS-concurrent-sweep-start]
278.668: [CMS-concurrent-sweep: 0.026/0.027 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
278.668: [CMS-concurrent-reset-start]
278.668: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
280.673: [GC (CMS Initial Mark) [1 CMS-initial-mark: 104079K(135168K)] 2774091K(6741248K), 0.9033730 secs] [Times: user=0.90 sys=0.00, real=0.90 secs] 
281.577: [CMS-concurrent-mark-start]
281.640: [CMS-concurrent-mark: 0.063/0.063 secs] [Times: user=0.13 sys=0.00, real=0.07 secs] 
281.640: [CMS-concurrent-preclean-start]
281.641: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
281.641: [CMS-concurrent-abortable-preclean-start]
281.641: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
281.641: [GC (CMS Final Remark)[YG occupancy: 2670011 K (6606080 K)]281.641: [Rescan (parallel) , 0.9914290 secs]282.633: [weak refs processing, 0.0000110 secs]282.633: [scrub string table, 0.0008100 secs] [1 CMS-remark: 104079K(135168K)] 2774091K(6741248K), 0.9923100 secs] [Times: user=7.14 sys=0.11, real=0.99 secs] 
282.634: [CMS-concurrent-sweep-start]
282.659: [CMS-concurrent-sweep: 0.024/0.025 secs] [Times: user=0.06 sys=0.01, real=0.02 secs] 
282.659: [CMS-concurrent-reset-start]
282.659: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

可以看到，CMS回收出现的频率太高，中间没有任何ParNew 的回收。这是因为年轻代的堆大小太大，所以每次发生ParNew 回收时，年老代堆大小立即变满，CMS回收开始运行。如果在不增加堆的总大小的情况下增加年轻代堆的大小，就会发生这种情况。如果内存泄漏，也可能发生此日志片段。

3. CMS failure
   如下日志片段展示了一个 CMS failure (concurrent mode failure):

 (concurrent mode failure): 1551948K->1548050K(1572864K), 15.1154540 secs] 1986510K->1548050K(2044736K), [CMS Perm : 78597K->78588K(524288K)], 15.4406700 secs] [Times: user=15.52 sys=0.00, real=15.44 secs] 
703240.983: [GC [1 CMS-initial-mark: 1548050K(1572864K)] 1561545K(2044736K), 0.0059690 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

此错误意味着CMS收集器无法跟上生成的垃圾量（老年代堆空间已满约90%），GCs占用的时间更长，这意味着应用程序停止的时间更长。此示例显示应用程序停止超过15秒，这将对性能产生重大影响。
可以添加如下GC参数避免CMS failure:

-XX:CMSInitiatingOccupancyFraction=n
-XX:+UseCMSInitiatingOccupancyOnly

应该将-XX:CMSInitiatingOccupancyFraction设置为70或80%（而不是默认值~90%），这样可以使CMS收集器跟上正在生成的垃圾量。

4. Full GC
   如下日志片段展示了一个 Full GC：

25.466: [Full GC )25.466: [CMS: 68756K­>75361K(1987392K), 0.2548820 secs] 96571K­->75361K(2064064K), [CMS Perm : 61069K­>60722K(61376K)], 0.2551850 secs] [Times: user=0.25 sys=0.01, real=0.25 secs]
26.185: [Full GC (System.gc())26.185: [CMS: 75361K­>73283K(1987392K), 0.2398450 secs] 76136K-­>73283K(2064064K), [CMS Perm : 60723K­>60723K(101204K)], 0.2400120 secs] [Times: user=0.24 sys=0.00, real=0.24 secs]
27.293: [Full GC (System.gc())27.293: [CMS: 73283K­>73291K(1987392K), 0.2111960 secs] 74096K­>73291K(2064064K), [CMS Perm : 60723K­>60723K(101396K)], 0.2112730 secs] [Times: user=0.21 sys=0.00, real=0.22 secs]
68.081: [Full GC (Heap Inspection Initiated GC)68.081: [CMS: 73291K­->73187K(1987392K), 0.2172670 secs] 77634K­>73187K(2064064K), [CMS Perm : 60742K­>60742K(101396K)], 0.2174520 secs] [Times: user=0.22 sys=0.00, real=0.21 secs]

这些日志片段指的是发生的完整gc，这意味着整个堆正在被清除（年轻代和年老代）；这通常是由于诸如RMI之类的系统进程造成的，RMI每小时都会执行一次完整的GC。PrintGCCause选项非常有用，可以帮助找出GC发生的原因（上面日志中的最后三行显示了该选项输出的附加信息，明确了哪些信息与系统相关）。还可以设置DisableExplicitGC选项以防止发生与系统相关的完整GCs。

堆优化准则
尽管我们不能给出建议的堆设置，因为它们在环境和应用程序之间有很大的差异，但在进行优化时，您应该遵循以下指导原则：
您应该始终使用支持的最新软件版本。

您应该按照ForgeRock的建议使用cmsgc。

• 堆的总大小不能超过可用的物理RAM的数量。

• 您必须留下一些物理RAM，以便其他应用程序在您的计算机上运行。

• 您应该将Xms和Xmx设置为相同的值以获得最佳性能。这些选项决定了堆的总大小。

• 您应该将NewSize和MaxNewSize设置为相同的值。这些选项决定如何在代之间分配堆。

• 您应该设置DisableExplicitGC选项以防止与系统相关的完整GCs运行。

• 你不能一次添加很多选项或者添加你不理解的选项。

• 不能从其他应用程序复制和粘贴选项。

• 您应该使用GC日志来帮助识别调优中的问题。
  总结

• 收集器，应该是CMS。

• 总堆大小，其中Xmx=Xms。

• 使用NewSize或NewRatio，其中NewSize=MaxNewSize，在代之间进行拆分。

翻译自：https://backstage.forgerock.com/knowledge/kb/article/a35746010