java - 使用 ConcMarkSweepGC 的连续 CMS 收集

Question

在 Linux 上使用以下 JVM 选项启动 Tomcat(2cpu、4g RAM、800M ehcache 元素):

-Xmn512m
-Xmx2g
-Xms2g
-XX:+UseConcMarkSweepGC
-Xss128k
-XX:PermSize=64m
-XX:MaxPermSize=128m
-XX:+DisableExplicitGC
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails

在凌晨 (06:00) 以低流量、无数据库问题且无批处理的方式运行 20 分钟，然后堆内存达到 -Xmx 值且 CMS 重复运行，最终返回到正常 GC此时消息 Unloading class sun.reflect.GeneratedMethodAccessorXXXXX 被打印到日志中的行为。

请问您可以吗:

1. 建议一些 GC 调整点吗？或
2. 提出可能的原因？

GC日志:

    2011-06-30T06:15:03.494+0900: 145634.229: [GC 145634.230: [ParNew: 463698K->37791K(471872K), 0.0342030 secs] 1848117K->1434326K(2044736K), 0.0343190 secs] [Times: user=0.13 sys=0.01, real=0.03 secs] 
2011-06-30T06:15:12.423+0900: 145643.159: [GC 145643.159: [ParNew: 457247K->36210K(471872K), 0.0302130 secs] 1853782K->1443540K(2044736K), 0.0303470 secs] [Times: user=0.12 sys=0.00, real=0.03 secs] 
2011-06-30T06:15:29.984+0900: 145660.720: [GC 145660.720: [ParNew: 455534K->50720K(471872K), 0.0314960 secs] 1862864K->1458051K(2044736K), 0.0316210 secs] [Times: user=0.12 sys=0.00, real=0.04 secs] 
2011-06-30T06:15:46.756+0900: 145677.492: [GC 145677.492: [ParNew: 470176K->52416K(471872K), 0.0446300 secs] 1877507K->1477425K(2044736K), 0.0447580 secs] [Times: user=0.17 sys=0.01, real=0.05 secs] 
2011-06-30T06:16:06.400+0900: 145697.135: [GC 145697.136: [ParNew: 471872K->35652K(471872K), 0.0451560 secs] 1896881K->1480786K(2044736K), 0.0452730 secs] [Times: user=0.16 sys=0.00, real=0.04 secs] 
2011-06-30T06:16:23.468+0900: 145714.204: [GC 145714.204: [ParNew: 455108K->38442K(471872K), 0.0356610 secs] 1900242K->1498930K(2044736K), 0.0357770 secs] [Times: user=0.13 sys=0.00, real=0.04 secs] 
2011-06-30T06:16:23.505+0900: 145714.240: [GC [1 CMS-initial-mark: 1460487K(1572864K)] 1499562K(2044736K), 0.0099200 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2011-06-30T06:16:23.515+0900: 145714.251: [CMS-concurrent-mark-start]
2011-06-30T06:16:24.768+0900: 145715.504: [CMS-concurrent-mark: 1.253/1.253 secs] [Times: user=1.31 sys=0.00, real=1.25 secs] 
2011-06-30T06:16:24.768+0900: 145715.504: [CMS-concurrent-preclean-start]
2011-06-30T06:16:24.775+0900: 145715.511: [CMS-concurrent-preclean: 0.007/0.007 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
2011-06-30T06:16:24.775+0900: 145715.511: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2011-06-30T06:16:29.811+0900: 145720.547: [CMS-concurrent-abortable-preclean: 0.760/5.036 secs] [Times: user=1.02 sys=0.02, real=5.03 secs] 
2011-06-30T06:16:29.812+0900: 145720.547: [GC[YG occupancy: 197582 K (471872 K)]145720.547: [Rescan (parallel) , 0.0291550 secs]145720.577: [weak refs processing, 0.0005100 secs]145720.577: [class unloading, 0.0349910 secs]145720.612: [scrub symbol & string tables, 0.0054610 secs] [1 CMS-remark: 1460487K(1572864K)] 1658070K(2044736K), 0.0776190 secs] [Times: user=0.16 sys=0.00, real=0.08 secs] 
2011-06-30T06:16:29.889+0900: 145720.625: [CMS-concurrent-sweep-start]
2011-06-30T06:16:30.381+0900: 145721.117: [CMS-concurrent-sweep: 0.491/0.492 secs] [Times: user=0.55 sys=0.00, real=0.49 secs] 
2011-06-30T06:16:30.381+0900: 145721.117: [CMS-concurrent-reset-start]
2011-06-30T06:16:30.394+0900: 145721.130: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2011-06-30T06:16:40.537+0900: 145731.273: [GC 145731.273: [ParNew: 457898K->45230K(471872K), 0.0274660 secs] 1896984K->1484315K(2044736K), 0.0275880 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
2011-06-30T06:16:57.459+0900: 145748.194: [GC 145748.194: [ParNew: 464686K->52416K(471872K), 0.0387420 secs] 1903771K->1505124K(2044736K), 0.0388710 secs] [Times: user=0.14 sys=0.01, real=0.04 secs] 
2011-06-30T06:16:57.500+0900: 145748.235: [GC [1 CMS-initial-mark: 1452708K(1572864K)] 1506926K(2044736K), 0.0130330 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2011-06-30T06:16:57.513+0900: 145748.249: [CMS-concurrent-mark-start]
2011-06-30T06:16:58.777+0900: 145749.513: [CMS-concurrent-mark: 1.265/1.265 secs] [Times: user=1.37 sys=0.01, real=1.27 secs] 
2011-06-30T06:16:58.778+0900: 145749.513: [CMS-concurrent-preclean-start]
2011-06-30T06:16:58.787+0900: 145749.523: [CMS-concurrent-preclean: 0.008/0.009 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2011-06-30T06:16:58.787+0900: 145749.523: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2011-06-30T06:17:03.905+0900: 145754.641: [CMS-concurrent-abortable-preclean: 1.033/5.118 secs] [Times: user=1.40 sys=0.05, real=5.12 secs] 
2011-06-30T06:17:03.906+0900: 145754.642: [GC[YG occupancy: 301453 K (471872 K)]145754.642: [Rescan (parallel) , 0.1761440 secs]145754.818: [weak refs processing, 0.0000280 secs]145754.818: [class unloading, 0.0270100 secs]145754.845: [scrub symbol & string tables, 0.0043090 secs] [1 CMS-remark: 1452708K(1572864K)] 1754161K(2044736K), 0.2132540 secs] [Times: user=0.23 sys=0.00, real=0.22 secs] 
2011-06-30T06:17:04.120+0900: 145754.855: [CMS-concurrent-sweep-start]
2011-06-30T06:17:04.595+0900: 145755.331: [CMS-concurrent-sweep: 0.475/0.475 secs] [Times: user=0.50 sys=0.01, real=0.47 secs] 
2011-06-30T06:17:04.595+0900: 145755.331: [CMS-concurrent-reset-start]
2011-06-30T06:17:04.607+0900: 145755.343: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2011-06-30T06:17:05.951+0900: 145756.687: [GC [1 CMS-initial-mark: 1449550K(1572864K)] 1792244K(2044736K), 0.1979100 secs] [Times: user=0.20 sys=0.00, real=0.20 secs] 
2011-06-30T06:17:06.149+0900: 145756.885: [CMS-concurrent-mark-start]
2011-06-30T06:17:07.408+0900: 145758.144: [CMS-concurrent-mark: 1.259/1.259 secs] [Times: user=1.30 sys=0.01, real=1.26 secs] 
2011-06-30T06:17:07.408+0900: 145758.144: [CMS-concurrent-preclean-start]
2011-06-30T06:17:07.417+0900: 145758.153: [CMS-concurrent-preclean: 0.008/0.009 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2011-06-30T06:17:07.418+0900: 145758.153: [CMS-concurrent-abortable-preclean-start]
2011-06-30T06:17:10.528+0900: 145761.264: [GC 145761.264: [ParNew: 471872K->47677K(471872K), 0.0412690 secs] 1921422K->1507670K(2044736K), 0.0413820 secs] [Times: user=0.13 sys=0.00, real=0.05 secs] 
 CMS: abort preclean due to time 2011-06-30T06:17:12.459+0900: 145763.195: [CMS-concurrent-abortable-preclean: 0.974/5.041 secs] [Times: user=1.55 sys=0.05, real=5.04 secs] 
2011-06-30T06:17:12.460+0900: 145763.195: [GC[YG occupancy: 110735 K (471872 K)]145763.195: [Rescan (parallel) , 0.0157680 secs]145763.211: [weak refs processing, 0.0000140 secs]145763.211: [class unloading, 0.0140640 secs]145763.225: [scrub symbol & string tables, 0.0042960 secs] [1 CMS-remark: 1459992K(1572864K)] 1570728K(2044736K), 0.0399100 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] 
2011-06-30T06:17:12.503+0900: 145763.238: [CMS-concurrent-sweep-start]
2011-06-30T06:17:12.967+0900: 145763.703: [CMS-concurrent-sweep: 0.463/0.464 secs] [Times: user=0.58 sys=0.01, real=0.46 secs] 
2011-06-30T06:17:12.967+0900: 145763.703: [CMS-concurrent-reset-start]
2011-06-30T06:17:12.980+0900: 145763.716: [CMS-concurrent-reset: 0.013/0.013 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2011-06-30T06:17:13.222+0900: 145763.957: [GC [1 CMS-initial-mark: 1459706K(1572864K)] 1645309K(2044736K), 0.0994390 secs] [Times: user=0.10 sys=0.00, real=0.10 secs] 
2011-06-30T06:17:13.321+0900: 145764.057: [CMS-concurrent-mark-start]
2011-06-30T06:17:14.589+0900: 145765.324: [CMS-concurrent-mark: 1.267/1.267 secs] [Times: user=1.37 sys=0.00, real=1.26 secs] 
2011-06-30T06:17:14.589+0900: 145765.324: [CMS-concurrent-preclean-start]
2011-06-30T06:17:14.600+0900: 145765.336: [CMS-concurrent-preclean: 0.010/0.011 secs] [Times: user=0.01 sys=0.01, real=0.02 secs] 
2011-06-30T06:17:14.600+0900: 145765.336: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2011-06-30T06:17:19.697+0900: 145770.433: [CMS-concurrent-abortable-preclean: 1.015/5.097 secs] [Times: user=1.38 sys=0.04, real=5.09 secs] 
2011-06-30T06:17:19.697+0900: 145770.433: [GC[YG occupancy: 422112 K (471872 K)]145770.433: [Rescan (parallel) , 0.2029540 secs]145770.636: [weak refs processing, 0.0000600 secs]145770.636: [class unloading, 0.0140870 secs]145770.650: [scrub symbol & string tables, 0.0042890 secs] [1 CMS-remark: 1459706K(1572864K)] 1881819K(2044736K), 0.2271390 secs] [Times: user=0.24 sys=0.00, real=0.23 secs] 
2011-06-30T06:17:19.925+0900: 145770.661: [CMS-concurrent-sweep-start]
2011-06-30T06:17:20.284+0900: 145771.019: [GC 145771.019: [ParNew: 467133K->38523K(471872K), 0.0340350 secs] 1925973K->1507043K(2044736K), 0.0341500 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
2011-06-30T06:17:20.443+0900: 145771.178: [CMS-concurrent-sweep: 0.479/0.518 secs] [Times: user=0.73 sys=0.01, real=0.52 secs] 
2011-06-30T06:17:20.443+0900: 145771.178: [CMS-concurrent-reset-start]
2011-06-30T06:17:20.455+0900: 145771.191: [CMS-concurrent-reset: 0.013/0.013 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2011-06-30T06:17:22.458+0900: 145773.194: [GC [1 CMS-initial-mark: 1468355K(1572864K)] 1663164K(2044736K), 0.1190060 secs] [Times: user=0.12 sys=0.00, real=0.12 secs] 
2011-06-30T06:17:22.577+0900: 145773.313: [CMS-concurrent-mark-start]
2011-06-30T06:17:23.856+0900: 145774.592: [CMS-concurrent-mark: 1.278/1.279 secs] [Times: user=1.40 sys=0.01, real=1.28 secs] 
2011-06-30T06:17:23.856+0900: 145774.592: [CMS-concurrent-preclean-start]
2011-06-30T06:17:23.870+0900: 145774.606: [CMS-concurrent-preclean: 0.012/0.014 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2011-06-30T06:17:23.870+0900: 145774.606: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2011-06-30T06:17:28.933+0900: 145779.669: [CMS-concurrent-abortable-preclean: 0.780/5.063 secs] [Times: user=0.89 sys=0.02, real=5.06 secs] 
2011-06-30T06:17:28.934+0900: 145779.669: [GC[YG occupancy: 327483 K (471872 K)]145779.669: [Rescan (parallel) , 0.1466580 secs]145779.816: [weak refs processing, 0.0000240 secs]145779.816: [class unloading, 0.0144090 secs]145779.831: [scrub symbol & string tables, 0.0043100 secs] [1 CMS-remark: 1468355K(1572864K)] 1795838K(2044736K), 0.1711490 secs] [Times: user=0.18 sys=0.00, real=0.17 secs] 
2011-06-30T06:17:29.105+0900: 145779.841: [CMS-concurrent-sweep-start]
2011-06-30T06:17:29.592+0900: 145780.328: [CMS-concurrent-sweep: 0.487/0.487 secs] [Times: user=0.57 sys=0.01, real=0.49 secs] 
2011-06-30T06:17:29.592+0900: 145780.328: [CMS-concurrent-reset-start]
2011-06-30T06:17:29.605+0900: 145780.340: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2011-06-30T06:17:31.607+0900: 145782.343: [GC [1 CMS-initial-mark: 1467716K(1572864K)] 1875108K(2044736K), 0.2378610 secs] [Times: user=0.24 sys=0.00, real=0.24 secs] 
2011-06-30T06:17:31.845+0900: 145782.581: [CMS-concurrent-mark-start]
2011-06-30T06:17:33.124+0900: 145783.860: [CMS-concurrent-mark: 1.279/1.279 secs] [Times: user=1.38 sys=0.01, real=1.28 secs] 
2011-06-30T06:17:33.124+0900: 145783.860: [CMS-concurrent-preclean-start]
2011-06-30T06:17:33.136+0900: 145783.872: [CMS-concurrent-preclean: 0.011/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2011-06-30T06:17:33.136+0900: 145783.872: [CMS-concurrent-abortable-preclean-start]
2011-06-30T06:17:33.278+0900: 145784.014: [GC 145784.014: [ParNew: 457979K->34427K(471872K), 0.0331350 secs] 1925695K->1513373K(2044736K), 0.0332490 secs] [Times: user=0.12 sys=0.00, real=0.03 secs] 
 CMS: abort preclean due to time 2011-06-30T06:17:38.148+0900: 145788.884: [CMS-concurrent-abortable-preclean: 1.020/5.012 secs] [Times: user=1.60 sys=0.07, real=5.01 secs] 
2011-06-30T06:17:38.149+0900: 145788.885: [GC[YG occupancy: 225806 K (471872 K)]145788.885: [Rescan (parallel) , 0.0359240 secs]145788.921: [weak refs processing, 0.0000080 secs]145788.921: [class unloading, 0.0141010 secs]145788.935: [scrub symbol & string tables, 0.0042870 secs] [1 CMS-remark: 1478946K(1572864K)] 1704752K(2044736K), 0.0600530 secs] [Times: user=0.15 sys=0.01, real=0.06 secs] 
2011-06-30T06:17:38.209+0900: 145788.945: [CMS-concurrent-sweep-start]
2011-06-30T06:17:38.677+0900: 145789.413: [CMS-concurrent-sweep: 0.468/0.468 secs] [Times: user=0.50 sys=0.00, real=0.47 secs] 
2011-06-30T06:17:38.677+0900: 145789.413: [CMS-concurrent-reset-start]
2011-06-30T06:17:38.689+0900: 145789.425: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2011-06-30T06:17:40.692+0900: 145791.428: [GC [1 CMS-initial-mark: 1478750K(1572864K)] 1772006K(2044736K), 0.1637570 secs] [Times: user=0.17 sys=0.00, real=0.17 secs] 
2011-06-30T06:17:40.856+0900: 145791.591: [CMS-concurrent-mark-start]
2011-06-30T06:17:42.142+0900: 145792.878: [CMS-concurrent-mark: 1.285/1.286 secs] [Times: user=1.46 sys=0.02, real=1.28 secs] 
2011-06-30T06:17:42.142+0900: 145792.878: [CMS-concurrent-preclean-start]
2011-06-30T06:17:42.154+0900: 145792.890: [CMS-concurrent-preclean: 0.010/0.012 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2011-06-30T06:17:42.154+0900: 145792.890: [CMS-concurrent-abortable-preclean-start]
2011-06-30T06:17:44.003+0900: 145794.739: [GC 145794.739: [ParNew: 453806K->49194K(471872K), 0.0277970 secs] 1932556K->1527945K(2044736K), 0.0279130 secs] [Times: user=0.10 sys=0.00, real=0.02 secs]
CMS Log .....
CMS Log .....
CMS Log .....
...
normal gc log....

Answer 1

您在该有问题的时间间隔内遇到 GC 抖动。原因很简单:您在那段时间使用了所有内存。如果您在 CMS 开始之前查看较小的收集，您会发现收集完成后，占用的空间接近 1.5G，这大约是旧代的大小。所以已经满了。如果您在每个 CMS 收集完成后检查相同的值，您会看到类似的值。这意味着您的 CMS 集合不会回收任何内存。由于 CMS 收集器配置为在占用率达到 92% 时启动，因此您在完成最后一个 CMS 后立即开始一个新的 CMS，因为占用率永远不会低于 92%。这就是颠簸的定义。

2011-06-30T06:16:23.468+0900: 145714.204: [GC 145714.204: [ParNew: 455108K->38442K(471872K), 0.0356610 secs] 1900242K->1498930K(2044736K), 0.0357770 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
// CMS happens, but no memory is recovered, old gen still at ~1.5G
2011-06-30T06:16:40.537+0900: 145731.273: [GC 145731.273: [ParNew: 457898K->45230K(471872K), 0.0274660 secs] 1896984K->1484315K(2044736K), 0.0275880 secs] [Times: user=0.11 sys=0.00, real=0.03 secs]

问题是:为什么要在半夜流量最低时使用所有内存？首先，流量本身会生成短暂的、请求范围内的对象，并且很少会导致这样的问题(除非存在内存泄漏)。那时您可能会发生某种后台进程，也许是某种批量缓存刷新之类的。

你能做什么？你没有足够的空间来处理当时发生的任何事情。如果您发现后台进程正在内存中构建巨大的数据结构，请考虑增量构建这些数据结构以减轻内存使用压力。要解开这个谜团，只需在抖动期间进行堆转储即可。消耗所有内存的对象类型应该很明显。它可能是一个 HashMap 或其他东西。

您甚至可以在 JVM 上设置此选项，以便在 JVM 抛出内存不足错误时自动进行堆转储:-XX:+HeapDumpOnOutOfMemoryError。通常，GC 颠簸伴随着 OOM 错误，因为如果 JVM 认为在 GC 上花费了太多时间而没有得到太多返回，则它不会永远颠簸。您的情况看起来可能会出现 OOM 错误，这会杀死正在运行的线程，这可能会消除违规者并释放所有内存。这可能是你在一段时间的痛苦之后恢复正常行为的原因。下次发生这种情况时，早上就会有一个堆转储等着您。