JVM垃圾收集应用程序停止时间差异
我正在使用以下版本的java运行tomcat的大型实例：
java版“1.6.0_20”
OpenJDK运行时环境（IcedTea6 1.9.7）（6b20-1.9.7-0ubuntu1~10.04.1
OpenJDK 64位服务器VM（内置19.0-b09，混合模式）
并使用以下参数设置：
-Xms13152m -Xmx13152m -Xmn768m -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=60 -XX:+CMSIncrementalMode -XX:+CMSIncrementalPacing -XX:CMSIncrementalDutyCycleMin=0 -XX:CMSIncrementalDutyCycle=10 -XX:+DisableExplicitGC 启用GC调试语句。 每隔几个小时我就会看到发生次要GC并且应用程序停止很长时间的行为，但GC本身似乎没有花费那么多时间：
{Heap before GC invocations=392 (full 74): par new generation total 707840K, used 698252K [0x00000004bfa00000, 0x00000004efa00000, 0x00000004efa00000) eden space 629248K, 99% used [0x00000004bfa00000, 0x00000004e607de48, 0x00000004e6080000) from space 78592K, 87% used [0x00000004ead40000, 0x00000004ef0a5370, 0x00000004efa00000) to space 78592K, 0% used [0x00000004e6080000, 0x00000004e6080000, 0x00000004ead40000) concurrent mark-sweep generation total 12681216K, used 10877603K [0x00000004efa00000, 0x00000007f5a00000, 0x00000007f5a00000) concurrent-mark-sweep perm gen total 50260K, used 30106K [0x00000007f5a00000, 0x00000007f8b15000, 0x0000000800000000) 13120.154: [GC 13120.154: [ParNew Desired survivor size 40239104 bytes, new threshold 1 (max 4) - age 1: 41912720 bytes, 41912720 total: 698252K->41387K(707840K), 0.1239080 secs] 11575856K->10987714K(13389056K) icms_dc=20 , 0.1239930 secs] [Times: user=0.00 sys=0.00, real=0.12 secs] Heap after GC invocations=393 (full 74): par new generation total 707840K, used 41387K [0x00000004bfa00000, 0x00000004efa00000, 0x00000004efa00000) eden space 629248K, 0% used [0x00000004bfa00000, 0x00000004bfa00000, 0x00000004e6080000) from space 78592K, 52% used [0x00000004e6080000, 0x00000004e88eace0, 0x00000004ead40000) to space 78592K, 0% used [0x00000004ead40000, 0x00000004ead40000, 0x00000004efa00000) concurrent mark-sweep generation total 12681216K, used 10946327K [0x00000004efa00000, 0x00000007f5a00000, 0x00000007f5a00000) concurrent-mark-sweep perm gen total 50260K, used 30106K [0x00000007f5a00000, 0x00000007f8b15000, 0x0000000800000000) } Total time for which application threads were stopped: 32.1614890 seconds
在这种情况下，我希望GC最多停止应用程序.12秒。 有谁知道为什么应用程序停止时间和GC时间之间存在如此巨大的差异？
更新我在GClog中添加了一个更长的片段：
{Heap before GC invocations=201 (full 18): par new generation total 707840K, used 639557K [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000) eden space 629248K, 100% used [0x00000004c4e00000, 0x00000004eb480000, 0x00000004eb480000) from space 78592K, 13% used [0x00000004eb480000, 0x00000004ebe917e8, 0x00000004f0140000) to space 78592K, 0% used [0x00000004f0140000, 0x00000004f0140000, 0x00000004f4e00000) concurrent mark-sweep generation total 12681216K, used 6634693K [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 47232K, used 28977K [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) 2011-04-12T18:42:16.450+0000: 12770.352: [GC 12770.352: [ParNew Desired survivor size 40239104 bytes, new threshold 15 (max 15) - age 1: 3701392 bytes, 3701392 total - age 2: 517360 bytes, 4218752 total - age 3: 2113840 bytes, 6332592 total - age 4: 3489008 bytes, 9821600 total : 639557K->12278K(707840K), 0.0948620 secs] 7274251K->6646972K(13389056K) icms_dc=0 , 0.0949550 secs] [Times: user=0.00 sys=0.00, real=0.10 secs] Heap after GC invocations=202 (full 18): par new generation total 707840K, used 12278K [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000) eden space 629248K, 0% used [0x00000004c4e00000, 0x00000004c4e00000, 0x00000004eb480000) from space 78592K, 15% used [0x00000004f0140000, 0x00000004f0d3dbf0, 0x00000004f4e00000) to space 78592K, 0% used [0x00000004eb480000, 0x00000004eb480000, 0x00000004f0140000) concurrent mark-sweep generation total 12681216K, used 6634693K [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 47232K, used 28977K [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) } Total time for which application threads were stopped: 0.0952670 seconds Application time: 5.0191420 seconds Total time for which application threads were stopped: 0.0001670 seconds Application time: 2.2198130 seconds Total time for which application threads were stopped: 0.0004480 seconds Application time: 5.5295710 seconds Total time for which application threads were stopped: 0.0001950 seconds Application time: 0.0097140 seconds Total time for which application threads were stopped: 0.0000530 seconds Application time: 7.1299730 seconds Total time for which application threads were stopped: 0.0001610 seconds Application time: 12.0198160 seconds Total time for which application threads were stopped: 0.0001550 seconds Application time: 1.5298610 seconds Total time for which application threads were stopped: 0.0001630 seconds Application time: 0.0097650 seconds Total time for which application threads were stopped: 0.0000590 seconds Application time: 0.1199330 seconds Total time for which application threads were stopped: 0.0000550 seconds Application time: 10.0998880 seconds Total time for which application threads were stopped: 0.0003490 seconds Application time: 1.0093980 seconds Total time for which application threads were stopped: 0.0003040 seconds Application time: 0.6099830 seconds Total time for which application threads were stopped: 0.0001700 seconds Application time: 0.0298490 seconds Total time for which application threads were stopped: 0.0000930 seconds Application time: 0.2025080 seconds Total time for which application threads were stopped: 0.0023430 seconds Application time: 0.0190510 seconds Total time for which application threads were stopped: 0.0003010 seconds Application time: 0.1793310 seconds Total time for which application threads were stopped: 0.0002150 seconds Application time: 0.0560830 seconds Total time for which application threads were stopped: 0.0010000 seconds Application time: 1.7072960 seconds {Heap before GC invocations=202 (full 18): par new generation total 707840K, used 641302K [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000) eden space 629248K, 99% used [0x00000004c4e00000, 0x00000004eb447fd8, 0x00000004eb480000) from space 78592K, 15% used [0x00000004f0140000, 0x00000004f0d3dbf0, 0x00000004f4e00000) to space 78592K, 0% used [0x00000004eb480000, 0x00000004eb480000, 0x00000004f0140000) concurrent mark-sweep generation total 12681216K, used 6634693K [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 47232K, used 29039K [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) 2011-04-12T18:43:04.052+0000: 12817.954: [GC 12817.955: [ParNew Desired survivor size 40239104 bytes, new threshold 4 (max 15) - age 1: 36162128 bytes, 36162128 total - age 2: 2531664 bytes, 38693792 total - age 3: 420840 bytes, 39114632 total - age 4: 2052544 bytes, 41167176 total - age 5: 3484040 bytes, 44651216 total : 641302K->44375K(707840K), 0.2037750 secs] 7275996K->6679069K(13389056K) icms_dc=0 , 0.2039060 secs] [Times: user=0.00 sys=0.00, real=0.21 secs] Heap after GC invocations=203 (full 18): par new generation total 707840K, used 44375K [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000) eden space 629248K, 0% used [0x00000004c4e00000, 0x00000004c4e00000, 0x00000004eb480000) from space 78592K, 56% used [0x00000004eb480000, 0x00000004edfd5f88, 0x00000004f0140000) to space 78592K, 0% used [0x00000004f0140000, 0x00000004f0140000, 0x00000004f4e00000) concurrent mark-sweep generation total 12681216K, used 6634693K [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 47232K, used 29039K [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) } Total time for which application threads were stopped: 0.2043140 seconds Application time: 0.0001040 seconds Total time for which application threads were stopped: 0.0000890 seconds Application time: 4.0399400 seconds {Heap before GC invocations=203 (full 18): par new generation total 707840K, used 673623K [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000) eden space 629248K, 100% used [0x00000004c4e00000, 0x00000004eb480000, 0x00000004eb480000) from space 78592K, 56% used [0x00000004eb480000, 0x00000004edfd5f88, 0x00000004f0140000) to space 78592K, 0% used [0x00000004f0140000, 0x00000004f0140000, 0x00000004f4e00000) concurrent mark-sweep generation total 12681216K, used 6634693K [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 47232K, used 29040K [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) 2011-04-12T18:44:23.258+0000: 12897.160: [GC 12897.160: [ParNew Desired survivor size 40239104 bytes, new threshold 1 (max 15) - age 1: 46278472 bytes, 46278472 total - age 2: 23234248 bytes, 69512720 total - age 3: 2144024 bytes, 71656744 total - age 4: 391464 bytes, 72048208 total : 673623K->78592K(707840K), 0.1607580 secs] 7308317K->6752580K(13389056K) icms_dc=0 , 0.1608520 secs] [Times: user=0.00 sys=0.00, real=0.16 secs] Heap after GC invocations=204 (full 18): par new generation total 707840K, used 78592K [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000) eden space 629248K, 0% used [0x00000004c4e00000, 0x00000004c4e00000, 0x00000004eb480000) from space 78592K, 100% used [0x00000004f0140000, 0x00000004f4e00000, 0x00000004f4e00000) to space 78592K, 0% used [0x00000004eb480000, 0x00000004eb480000, 0x00000004f0140000) concurrent mark-sweep generation total 12681216K, used 6673988K [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 47232K, used 29040K [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) } Total time for which application threads were stopped: 75.1222720 seconds Application time: 0.0660880 seconds Total time for which application threads were stopped: 0.0001500 seconds Application time: 0.0001110 seconds Total time for which application threads were stopped: 0.0000620 seconds Application time: 0.0000320 seconds Total time for which application threads were stopped: 0.0000620 seconds Application time: 0.5790490 seconds Total time for which application threads were stopped: 0.0151370 seconds Application time: 0.0241790 seconds Total time for which application threads were stopped: 0.0111420 seconds Application time: 0.1488160 seconds Total time for which application threads were stopped: 0.0168360 seconds Application time: 0.0237110 seconds Total time for which application threads were stopped: 0.0008580 seconds Application time: 0.0594260 seconds Total time for which application threads were stopped: 0.0179450 seconds Application time: 0.0331740 seconds Total time for which application threads were stopped: 0.0072850 seconds Application time: 1.2617710 seconds {Heap before GC invocations=204 (full 18): par new generation total 707840K, used 707840K [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000) eden space 629248K, 100% used [0x00000004c4e00000, 0x00000004eb480000, 0x00000004eb480000) from space 78592K, 100% used [0x00000004f0140000, 0x00000004f4e00000, 0x00000004f4e00000) to space 78592K, 0% used [0x00000004eb480000, 0x00000004eb480000, 0x00000004f0140000) concurrent mark-sweep generation total 12681216K, used 6673988K [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 47232K, used 29089K [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) 2011-04-12T18:44:25.690+0000: 12899.592: [GC 12899.592: [ParNew Desired survivor size 40239104 bytes, new threshold 1 (max 15) - age 1: 42048296 bytes, 42048296 total : 707840K->58684K(707840K), 0.1654070 secs] 7381828K->6802196K(13389056K) icms_dc=0 , 0.1655450 secs] [Times: user=0.00 sys=0.00, real=0.17 secs] Heap after GC invocations=205 (full 18): par new generation total 707840K, used 58684K [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000) eden space 629248K, 0% used [0x00000004c4e00000, 0x00000004c4e00000, 0x00000004eb480000) from space 78592K, 74% used [0x00000004eb480000, 0x00000004eedcf320, 0x00000004f0140000) to space 78592K, 0% used [0x00000004f0140000, 0x00000004f0140000, 0x00000004f4e00000) concurrent mark-sweep generation total 12681216K, used 6743511K [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 47232K, used 29089K [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) } Total time for which application threads were stopped: 0.1709510 seconds Application time: 1.0183040 seconds Total time for which application threads were stopped: 0.0009220 seconds Application time: 0.0209220 seconds Total time for which application threads were stopped: 0.0009260 seconds Application time: 0.0181760 seconds Total time for which application threads were stopped: 0.0002780 seconds Application time: 0.0773630 seconds Total time for which application threads were stopped: 0.0019720 seconds Application time: 0.0045340 seconds Total time for which application threads were stopped: 0.0001400 seconds Application time: 0.0245930 seconds Total time for which application threads were stopped: 0.0004070 seconds Application time: 0.4811530 seconds Total time for which application threads were stopped: 0.0043100 seconds Application time: 0.0015090 seconds Total time for which application threads were stopped: 0.0052290 seconds Application time: 0.0264570 seconds Total time for which application threads were stopped: 0.0072530 seconds Application time: 0.0135600 seconds Total time for which application threads were stopped: 0.0121400 seconds Application time: 0.0278510 seconds Total time for which application threads were stopped: 0.0078060 seconds Application time: 0.0136080 seconds Total time for which application threads were stopped: 0.0121390 seconds Application time: 0.0066360 seconds Total time for which application threads were stopped: 0.0004330 seconds Application time: 0.0107480 seconds Total time for which application threads were stopped: 0.0001900 seconds Application time: 0.0027230 seconds Total time for which application threads were stopped: 0.0132610 seconds Application time: 0.0126600 seconds Total time for which application threads were stopped: 0.0003420 seconds Application time: 0.5384840 seconds {Heap before GC invocations=205 (full 18): par new generation total 707840K, used 687932K [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000) eden space 629248K, 100% used [0x00000004c4e00000, 0x00000004eb480000, 0x00000004eb480000) from space 78592K, 74% used [0x00000004eb480000, 0x00000004eedcf320, 0x00000004f0140000) to space 78592K, 0% used [0x00000004f0140000, 0x00000004f0140000, 0x00000004f4e00000) concurrent mark-sweep generation total 12681216K, used 6743511K [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 47232K, used 29092K [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) 2011-04-12T18:44:28.223+0000: 12902.125: [GC 12902.125: [ParNew Desired survivor size 40239104 bytes, new threshold 15 (max 15) - age 1: 5906520 bytes, 5906520 total : 687932K->45478K(707840K), 0.2139570 secs] 7431444K->6860368K(13389056K) icms_dc=0 , 0.2142010 secs] [Times: user=0.00 sys=0.00, real=0.21 secs] Heap after GC invocations=206 (full 18): par new generation total 707840K, used 45478K [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000) eden space 629248K, 0% used [0x00000004c4e00000, 0x00000004c4e00000, 0x00000004eb480000) from space 78592K, 57% used [0x00000004f0140000, 0x00000004f2da9b30, 0x00000004f4e00000) to space 78592K, 0% used [0x00000004eb480000, 0x00000004eb480000, 0x00000004f0140000) concurrent mark-sweep generation total 12681216K, used 6814889K [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 47232K, used 29092K [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) }
UPDATE
我将我的应用程序切换到多核机器以帮助减轻CMS收集的痛苦，现在，在稳定状态下，我没有看到任何暂停。 但是，在更新我的搜索索引期间，会很快生成大量大型内存结构，并且应用程序再次遭受长STW暂停。 我不确定如何避免这种情况，因为这些物体可能应该存在于终身代，我增加了幸存者空间的大小（-XX：SurvivorRatio = 8），但我仍然观察到长时间停顿。 请参阅下面的GC日志：
{Heap before GC invocations=103 (full 48): par new generation total 921600K, used 912322K [0x000000050ce00000, 0x000000054b600000, 0x000000054b600000) eden space 819200K, 99% used [0x000000050ce00000, 0x000000053e776380, 0x000000053ee00000) from space 102400K, 97% used [0x000000053ee00000, 0x0000000544f7a630, 0x0000000545200000) to space 102400K, 0% used [0x0000000545200000, 0x0000000545200000, 0x000000054b600000) concurrent mark-sweep generation total 11264000K, used 6486203K [0x000000054b600000, 0x00000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 48516K, used 29211K [0x00000007fae00000, 0x00000007 fdd61000, 0x0000000800000000) 2011-04-14T15:15:25.322+0000: 2358.684: [GC 2358.684: [ParNew Desired survivor size 52428800 bytes, new threshold 1 (max 15)- age 1: 102164088 bytes, 102164088 total : 912322K->99941K(921600K), 30.0146400 secs] 7398525K->6818473K(12185600K), 30.0147850 se cs] [Times: user=0.00 sys=0.00, real=30.02 secs] Heap after GC invocations=104 (full 48): par new generation total 921600K, used 99941K [0x000000050ce00000, 0x000000054b600000, 0x000000054b600000) eden space 819200K, 0% used [0x000000050ce00000, 0x000000050ce00000, 0x000000053ee00000) from space 102400K, 97% used [0x0000000545200000, 0x000000054b399710, 0x000000054b6000 00) to space 102400K, 0% used [0x000000053ee00000, 0x000000053ee00000, 0x00000005452000 00) concurrent mark-sweep generation total 11264000K, used 6718531K [0x000000054b600000, 0x0 0000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 48516K, used 29211K [0x00000007fae00000, 0x00000007 fdd61000, 0x0000000800000000)} Total time for which application threads were stopped: 30.0152850 seconds Application time: 0.9450500 seconds
添加评论更长的GC日志我认为你的幸存者空间太小，注意伊甸园充满了幸存者56％之前和伊甸园没有充满，但幸存者是100％。 这意味着它被强制进入一个完全非并发的终身collections，据报道它是一个年轻的gc，因为它不是由CMS触发的，因为它无处可放多余的垃圾而是终身。 只有终身collections家才能完成任务，因此会触发完整的GC。 补救措施是使伊甸园更大和/或使幸存者空间更大。 您可以使用SurvivorRatio来执行此操作，例如-XX:SurvivorRatio=8表示将每个幸存者空间设置为伊甸园的1/8。
停止时间实际上是“JVM在安全点上花费的时间”，您可以使用PrintSafepointStatistics来确定安全点期间发生了什么。 这篇文章有一个指向导致VM达到安全点的操作列表的链接，如果你仔细阅读它，将会显示有很多不同的方式可以在那里做“无所事事”。 不要排除OS时钟转换，因为时间是通过时间周期感知时间戳记录的。
btw pre hotspot17那些时间戳可能不准确。 该错误在Bug ID：6782663中描述，该错误在hs17中修复，其是6u21的一部分（根据发行说明 ）。 因为你在6u20，它（30s）甚至可能不是真正的价值。
在某些情况下，并发收集器将回退到完整的GC，暂停所有内容直到完成。 如果我没记错的话，如果应用程序创建了许多需要收集但无法跟上的对象，那么一个小的伊甸园可以触发它。 您可能想尝试指定较大的eden（或使用比率，以便它与内存正确缩放）。 如果您还没有这些配置选项，可以尝试添加这些配置选项以获取更多GC详细信息：
-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps
通过查看GC日志并迭代各种选项，我设法消除了我们在大型部署中看到的完整GC事件。 每个应用程序都是不同的，但是在这里他们也可以帮助你：
-Xms24g -Xmx24g -XX:MaxPermSize=256m -XX:NewRatio=4 -XX:SurvivorRatio=8 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+DisableExplicitGC -XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark -XX:CMSInitiatingOccupancyFraction=68
由于我们使用的是32GB以下，我们还使用-XX:+UseCompressedOops来减少64位寻址的开销。 此外，我们使用-XX:+UseLargePages以获得更好的性能，但您必须首先为您的操作系统启用大页面支持。