一个 JVM 参数引发的频繁 CMS GC( 六 )

我们再看看 collectionattemptissafe() 函数的实现 , 会让你豁然开朗 , if (!to()->isempty()) return false , 刚好满足了每次 YoungGC to space 不为空 。 因此 , 是在这里 incrementalcollection_failed 被设置成 true , 导致每隔 2s 触发一次 CMS GC , 这就解释了为什么 OldGen 的使用占比情况都没有达到 80% , 也会触发 CMS GC 。
bool DefNewGeneration::collection_attempt_is_safe() {if (!to()->is_empty()) {log_trace(gc)(":: to is not empty ::");return false;}if (_old_gen == NULL) {GenCollectedHeap* gch = GenCollectedHeap::heap();_old_gen = gch->old_gen();}return _old_gen->promotion_attempt_is_safe(used());}Young GC 后 eden、from、to 三个 space 的使用量都不是 0 的情况看到这里 , 其实这个问题也很好解释了 , 我们看 ParNewGeneration::collect 函数中的这段代码就明白了 , YoungGC 遇到 to space 不为空的情况下 , 直接 setincrementalcollection_failed() 完就返回了 , 并没有进行真正的 Young GC 。
if (!collection_attempt_is_safe()) {gch->set_incremental_collection_failed();// slight lie, in that we did not even attempt onereturn;}罪魁祸首看到这里 , 你一定在想 , 那罪魁祸首到底是谁呢?表面上看是 to space 不为空导致触发了 Young GC , 然后设置了 incrementalcollectionfailed 参数 , 进而满足了 CMS GC 触发条件 。 实质上是因为配置了 -XX:CMSScavengeBeforeRemark 参数 , CMS GC 阶段强制进行了 Young GC , 导致 to space 不为空 , 因此这个锅得由 -XX:CMSScavengeBeforeRemark 参数来背 。
你可能要问即使不设置 -XX:CMSScavengeBeforeRemark 参数 CMS GC 阶段也是有可能会触发 Young GC , 凭什么要让 -XX:CMSScavengeBeforeRemark 参数来背锅 。
如果是 Allocation Failure 触发的 Young GC 也会有问题吗?答案是不会 , 这里可以借助最后一次 CMS GC 日志来分析 。
最后一次 CMS GC 日志
2019-03-28T20:14:15.470+0800: 3645007.937: Application time: 2.4315795 seconds2019-03-28T20:14:15.472+0800: 3645007.940: [GC (CMS Initial Mark) [1 CMS-initial-mark: 572987K(3354624K)] 2318654K(5242112K), 1.7733417 secs] [Times: user=1.94 sys=0.05, real=1.77 secs]2019-03-28T20:14:17.246+0800: 3645009.714: Total time for which application threads were stopped: 1.7762440 seconds, Stopping threads took: 0.0001283 seconds2019-03-28T20:14:17.246+0800: 3645009.714: [CMS-concurrent-mark-start]2019-03-28T20:14:17.257+0800: 3645009.725: Application time: 0.0112116 seconds2019-03-28T20:14:17.260+0800: 3645009.728: Total time for which application threads were stopped: 0.0027625 seconds, Stopping threads took: 0.0001346 seconds2019-03-28T20:14:17.260+0800: 3645009.728: Application time: 0.0001755 seconds2019-03-28T20:14:17.263+0800: 3645009.730: Total time for which application threads were stopped: 0.0027375 seconds, Stopping threads took: 0.0000825 seconds2019-03-28T20:14:17.263+0800: 3645009.731: Application time: 0.0000958 seconds2019-03-28T20:14:17.265+0800: 3645009.733: Total time for which application threads were stopped: 0.0025920 seconds, Stopping threads took: 0.0000832 seconds2019-03-28T20:14:17.274+0800: 3645009.741: Application time: 0.0081685 seconds2019-03-28T20:14:17.277+0800: 3645009.744: Total time for which application threads were stopped: 0.0028536 seconds, Stopping threads took: 0.0001305 seconds2019-03-28T20:14:17.845+0800: 3645010.312: Application time: 0.5681527 seconds{Heap before GC invocations=18561 (full 815): par new generationtotal 1887488K, used 1760091K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)eden space 1677824K, 100% used [0x0000000673400000, 0x00000006d9a80000, 0x00000006d9a80000)from space 209664K,39% used [0x00000006e6740000, 0x00000006eb796e60, 0x00000006f3400000)tospace 209664K,95% used [0x00000006d9a80000, 0x00000006e5efae68, 0x00000006e6740000) concurrent mark-sweep generation total 3354624K, used 572987K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000) Metaspaceused 90185K, capacity 91432K, committed 91776K, reserved 1130496Kclass spaceused 9510K, capacity 9794K, committed 9856K, reserved 1048576K2019-03-28T20:14:17.847+0800: 3645010.315: [GC (Allocation Failure) 3645010.315: [ParNew: 1760091K->1760091K(1887488K), 0.0000231 secs]3645010.315: [CMS2019-03-28T20:14:18.223+0800: 3645010.691: [CMS-concurrent-mark: 0.961/0.977 secs] [Times: user=1.04 sys=0.00, real=0.97 secs] (concurrent mode failure): 572987K->554147K(3354624K), 3.2531090 secs] 2333078K->554147K(5242112K), [Metaspace: 90185K->90185K(1130496K)], 3.2534483 secs] [Times: user=3.26 sys=0.00, real=3.25 secs]Heap after GC invocations=18562 (full 816): new generationtotal 1887488K, used 0K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)eden space 1677824K,0% used [0x0000000673400000, 0x0000000673400000, 0x00000006d9a80000)from space 209664K,0% used [0x00000006e6740000, 0x00000006e6740000, 0x00000006f3400000)tospace 209664K,0% used [0x00000006d9a80000, 0x00000006d9a80000, 0x00000006e6740000)concurrent mark-sweep generation total 3354624K, used 554147K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000) Metaspaceused 90165K, capacity 91402K, committed 91776K, reserved 1130496Kclass spaceused 9507K, capacity 9789K, committed 9856K, reserved 1048576K}2019-03-28T20:14:21.101+0800: 3645013.568: Total time for which application threads were stopped: 3.2561084 seconds, Stopping threads took: 0.0001151 seconds


推荐阅读