垃圾回收 - Java CMS GC，GC 线程在系统空闲时占用 CPU

Question

我们在tomcat 7，JDK 7，Amazon Linux中有一个Web应用程序。这是我们对 GC 配置所拥有的：

-XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled"

我们没有启用"PrintGCDetails"。

这是每隔几秒钟在 gc.log 文件中打印的内容（此时应用程序负载为 0 时连续 48 小时 - 绝对没有活动，即使这样，以下内容也会被打印出来，这些线程占用的 CPU 为 15%）（请参阅下面的上下文）：

940568.925: [GC 7425641K(8277888K), 0.2201750 secs]
940572.415: [GC 7425641K(8277888K), 0.1782950 secs]
940574.101: [GC 7425641K(8277888K), 0.1736550 secs]
940577.545: [GC 7425647K(8277888K), 0.1779190 secs]

我们看到以下 GC 线程占用了 CPU（总体占用率约为 15%），即使：

• 系统中没有活动，
• 除了这些线程之外，没有其他线程处于活动状态，这种情况持续 48 小时，此时系统处于 0 负载下。
• 系统在过去 24 小时内也处于 0 负载下，然后这些线程变为活动状态
• 当这些线程处于活动状态并占用 CPU 时，前面的行将打印在 GC 中.log
• 这种情况持续了 2 天，当我们最终通过在此 JVM 中调用 Web 应用程序来加载 5 分钟时，一切都停止了。我们注意到这些线程不再占用CPU（它们现在占用<1%）。一旦发生完整的 GC，问题似乎已经自行解决。完整的 GC 发生在系统负载下之后。
• 简而言之，当系统处于 0 负载状态 48 小时时，GC 线程继续占用 15% 的 CPU。

这些是线程：

"Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x00007fad9402e000 nid=0x629d runnable
"Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x00007fad94030000 nid=0x629e runnable
"Gang worker#2 (Parallel GC Threads)" prio=10 tid=0x00007fad94031800 nid=0x629f runnable
"Gang worker#3 (Parallel GC Threads)" prio=10 tid=0x00007fad94033800 nid=0x62a0 runnable
"Gang worker#4 (Parallel GC Threads)" prio=10 tid=0x00007fad94035800 nid=0x62a1 runnable
"Gang worker#5 (Parallel GC Threads)" prio=10 tid=0x00007fad94037000 nid=0x62a2 runnable
"Gang worker#6 (Parallel GC Threads)" prio=10 tid=0x00007fad94039000 nid=0x62a3 runnable
"Gang worker#7 (Parallel GC Threads)" prio=10 tid=0x00007fad9403b000 nid=0x62a4 runnable
"Gang worker#8 (Parallel GC Threads)" prio=10 tid=0x00007fad9403d000 nid=0x62a5 runnable
"Gang worker#9 (Parallel GC Threads)" prio=10 tid=0x00007fad9403e800 nid=0x62a6 runnable
"Gang worker#10 (Parallel GC Threads)" prio=10 tid=0x00007fad94040800 nid=0x62a7 runnable
"Gang worker#11 (Parallel GC Threads)" prio=10 tid=0x00007fad94042800 nid=0x62a8 runnable
"Gang worker#12 (Parallel GC Threads)" prio=10 tid=0x00007fad94044000 nid=0x62a9 runnable
"Concurrent Mark-Sweep GC Thread" prio=10 tid=0x00007fad9418b000 nid=0x62ae runnable
"Gang worker#0 (Parallel CMS Threads)" prio=10 tid=0x00007fad94183000 nid=0x62aa runnable
"Gang worker#1 (Parallel CMS Threads)" prio=10 tid=0x00007fad94185000 nid=0x62ab runnable
"Gang worker#2 (Parallel CMS Threads)" prio=10 tid=0x00007fad94187000 nid=0x62ac runnable
"Gang worker#3 (Parallel CMS Threads)" prio=10 tid=0x00007fad94188800 nid=0x62ad runnable

问题 1：当这些线程占用 15% 的 CPU 时，为什么 gc 日志会填充以下内容？

940568.925: [GC 7425641K(8277888K), 0.2201750 secs]
940572.415: [GC 7425641K(8277888K), 0.1782950 secs]

问题 2：上述日志是否指示 CMS 出现故障（标记、扫描等）？

问题 3：当我们在 Web 应用程序上引入中等负载并发生完整 GC 时，为什么它会自行解决？

是的，我将尝试在启用了 printGCDetails 的另一个环境中复制该问题，并返回信息或解决方案——如果有人之前看到过这种情况，请添加到对话中。

编辑 1：这是启用"PrintGCDetails"时的日志：

1376.326: [GC [1 CMS-initial-mark: 6481517K(7281088K)] 6536750K(8277888K), 0.0094620 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
1376.336: [CMS-concurrent-mark-start]
1377.992: [CMS-concurrent-mark: 1.656/1.656 secs] [Times: user=6.62 sys=0.00, real=1.66 secs] 
1377.992: [CMS-concurrent-preclean-start]
1378.005: [CMS-concurrent-preclean: 0.014/0.014 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
1378.006: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 1413.110: [CMS-concurrent-abortable-preclean: 4.169/35.104 secs] [Times: user=4.23 sys=0.01, real=35.11 secs] 
1413.111: [GC[YG occupancy: 55233 K (996800 K)]1413.111: [Rescan (parallel) , 0.0154040 secs]1413.126: [weak refs processing, 0.0001380 secs]1413.126: [class unloading, 0.0013450 secs]1413.128: [scrub symbol table, 0.0023140 secs]1413.130: [scrub string table, 0.0004850 secs] [1 CMS-remark: 6481517K(7281088K)] 6536751K(8277888K), 0.0201870 secs] [Times: user=0.20 sys=0.00, real=0.02 secs] 
1413.131: [CMS-concurrent-sweep-start]
1414.151: [CMS-concurrent-sweep: 1.020/1.020 secs] [Times: user=1.02 sys=0.00, real=1.02 secs] 
1414.151: [CMS-concurrent-reset-start]
1414.177: [CMS-concurrent-reset: 0.026/0.026 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 

另请注意："CMSMaxAbortablePrecleanTime"设置为 35 秒。谢谢。

Answer 1

在占用的堆和可用的堆之间必须有足够的缓冲区。增加（最大）堆的大小，使占用的堆占总数的 70% 解决了问题。当算法是CMS时，这一点尤其重要。吸取的教训。