Java CMS GC，系统空闲时GC线程占用CPU

Question

我们在 tomcat 7、JDK 7、Amazon Linux 中有一个 Web 应用程序。这是我们的 GC 配置:

-XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled"

我们没有启用“PrintGCDetails”。

这是每隔几秒在 gc.log 文件中打印出来的内容(连续 48 小时，当应用程序此时处于 0 负载时 - 绝对没有 Activity ，即使这样，也会打印出以下内容，并且这些线程占用的 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%):

• 系统中没有任何 Activity ，
• 除了这些线程之外，没有其他线程处于 Activity 状态，并且这种情况持续了 48 小时，此时系统处于 0 负载。
• 系统在过去 24 小时内也处于 0 负载状态，然后这些线程变得活跃
• 当这些线程处于 Activity 状态并占用 CPU 时，前面的行会打印在 gc.log 中
• 这种情况持续了 2 天，当我们最终通过在该 JVM 中调用 Web 应用程序 5 分钟来加载负载时，一切都停止了。我们注意到这些线程现在不再占用 CPU(它们占用 <1%)。一旦 FULL GC 发生，问题似乎就自行解决了。 FULL 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 应用程序上引入中等负载并发生 FULL 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 时，这一点尤其重要。吸取的教训。