我们在 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 %)。一旦 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 秒。谢谢。