性能文章>再次剖析 “一个 JVM 参数引发的频繁 CMS GC”>

再次剖析 “一个 JVM 参数引发的频繁 CMS GC”原创

1年前
7019210

前言

之前这篇《一个 JVM 参数引发的频繁 CMS GC》文章发出之后,反应比较激烈,因为这可能与同学们通常 GC 优化经验相悖,通常有很多业务都通过添加 -XX:+CMSScavengeBeforeRemark 参数,来降低 CMS-remark 的时间,进而提升业务的性能以及可用性。

背景

这里给出几位同学比较典型的的想法和建议:
“同学1”:“-XX:+CMSScavengeBeforeRemark 参数引发的频繁 CMS GC 有失偏颇,其实根本原因是第一次 CMS GC 过程中的 Young GC 发生了 ‘promotion failed’ 导致了 to space 不为空”。

“同学2”:“我们线上也用了这个参数,没有出现频繁 CMS GC 的现象,我猜测你那种是特殊场景导致的,并不是用了那个参数就一定会导致频繁 CMS GC,大部分情况下加上这个参数是有好处的”。

“同学3”:“是不是可以降低 -XX:CMSInitiatingOccupancyFraction 参数的值来,比如70,让 Young GC成功”。

针对这几位同学提到的想法和建议,我又重新思考这个案例,来解答下这些的问题。

主要内容

本文主要讲解:

  1. 纠正《一个 JVM 参数引发的频繁 CMS GC》文章中的一个分析错误

  2. -XX:+CMSScavengeBeforeRemark 参数到底是不是引起频繁 CMS GC 的原因

  3. 什么场景会出现这种问题

  4. 有哪些优化策略

内容

纠正《一个 JVM 参数引发的频繁 CMS GC》文章中的一个错误
这里纠正《一个 JVM 参数引发的频繁 CMS GC》文中提到的关于 “OldGen 的使用占比情况都没有达到 80%,什么原因导致的 CMS GC” 问题原因分析中的一个错误。

引用下《一个 JVM 参数引发的频繁 CMS GC》文章的相关内容:
“我们再看看 collectionattemptissafe() 函数的实现,会让你豁然开朗,if (!to()->isempty()) return false,刚好满足了每次 Young GC 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());
  • }
  •  

这里说的是 CMS GC 过程中由于配置了 -XX:+CMSScavengeBeforeRemark 参数引起了 Young GC,而 Young GC 过程中由于 to space 不为空,导致 incrementalcollectionfailed 被设置成 true,致使 CMS 的 background collector 每隔 2s 检查一次 GC 触发条件,发现 _incrementalcollection_failed 被设置成 true,所以触发了下一次的 CMS GC。

这段内容是错误的,因为 -XX:+CMSScavengeBeforeRemark 参数引起了 Young GC 发生在 Final Remark 阶段,而在 CMS 的 Sweep 阶段,是会将 incrementalcollection_failed 重置成 false 的,因此,这不是这个原因导致下一次的 CMS GC。

  • // Now that sweeping has been completed, we clear
  • // the incremental_collection_failed flag,
  • // thus inviting a younger gen collection to promote into
  • // this generation. If such a promotion may still fail,
  • // the flag will be set again when a young collection is
  • // attempted.
  • GenCollectedHeap* gch = GenCollectedHeap::heap();
  • gch->clear_incremental_collection_failed(); // Worth retrying as fresh space may have been freed up
  • gch->update_full_collections_completed(_collection_count_start);
  •  

那究竟是什么原因导致的下一次的 CMS GC 呢?
我们再看看 CMS background collector 中影响 incrementalcollectionwillfail 函数返回值的另一个条件 “consultyoung && !younggen->collectionattemptissafe()”,consultyoung 传参设置的是 true 因此我们只需看 younggen->collectionattemptissafe()。这其实就是上面提到的 Young GC 过程中调用的 collectionattemptissafe() 函数,因为 to space 一直不为空,所以这个方法的返回值一直是 false,而 “consultyoung && !younggen->collectionattemptissafe()” 的返回值就是true,导致下一次 CMS GC的触发。

  • // Returns true if an incremental collection is likely to fail.
  • // We optionally consult the young gen, if asked to do so;
  • // otherwise we base our answer on whether the previous incremental
  • // collection attempt failed with no corrective action as of yet.
  • bool incremental_collection_will_fail(bool consult_young) {
  • // The first disjunct remembers if an incremental collection failed, even
  • // when we thought (second disjunct) that it would not.
  • return incremental_collection_failed() ||
  • (consult_young && !_young_gen->collection_attempt_is_safe());
  • }
  • bool incremental_collection_failed() const {
  • return _incremental_collection_failed;
  • }
  •  

-XX:+CMSScavengeBeforeRemark 参数到底是不是引起频繁 CMS GC 的原因

从上面对于下一次 CMS GC 触发原因分析,其实主要原因是 YoungGen 的 to space 不为空,导致后续持续的 CMS GC,因为我们得定位下什么原因导致了 to space 不为空。
我们来看看第一次 CMS GC 的日志

第一次 CMS GC日志

  • 2019-03-28T20:05:06.906+0800: 3644459.373: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2935428K(3354624K)] 3160044K(5242112K), 0.0586708 secs] [Times: user=0.22 sys=0.00, real=0.06 secs]
  • 2019-03-28T20:05:06.965+0800: 3644459.432: Total time for which application threads were stopped: 0.0616049 seconds, Stopping threads took: 0.0001381 seconds
  • 2019-03-28T20:05:06.965+0800: 3644459.432: [CMS-concurrent-mark-start]
  • 2019-03-28T20:05:08.066+0800: 3644460.533: [CMS-concurrent-mark: 1.101/1.101 secs] [Times: user=1.57 sys=0.05, real=1.10 secs]
  • 2019-03-28T20:05:08.066+0800: 3644460.533: [CMS-concurrent-preclean-start]
  • 2019-03-28T20:05:08.076+0800: 3644460.543: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
  • 2019-03-28T20:05:08.076+0800: 3644460.543: [CMS-concurrent-abortable-preclean-start]
  • 2019-03-28T20:05:10.177+0800: 3644462.645: Application time: 3.2124140 seconds
  • {Heap before GC invocations=18476 (full 731):
  • par new generation total 1887488K, used 1887488K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)
  • eden space 1677824K, 100% used [0x0000000673400000, 0x00000006d9a80000, 0x00000006d9a80000)
  • from space 209664K, 100% used [0x00000006e6740000, 0x00000006f3400000, 0x00000006f3400000)
  • to space 209664K, 0% used [0x00000006d9a80000, 0x00000006d9a80000, 0x00000006e6740000)
  • concurrent mark-sweep generation total 3354624K, used 2935428K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000)
  • Metaspace used 90225K, capacity 91504K, committed 91776K, reserved 1130496K
  • class space used 9517K, capacity 9806K, committed 9856K, reserved 1048576K
  • 2019-03-28T20:05:10.179+0800: 3644462.647: [GC (Allocation Failure) 3644462.647: [ParNew: 1887488K->201195K(1887488K), 0.4228807 secs] 4822916K->3279195K(5242112K), 0.4231546 secs] [Times: user=1.54 sys=0.00, real=0.42 secs]
  • Heap after GC invocations=18477 (full 731):
  • par new generation total 1887488K, used 201195K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)
  • eden space 1677824K, 0% used [0x0000000673400000, 0x0000000673400000, 0x00000006d9a80000)
  • from space 209664K, 95% used [0x00000006d9a80000, 0x00000006e5efae68, 0x00000006e6740000)
  • to space 209664K, 0% used [0x00000006e6740000, 0x00000006e6740000, 0x00000006f3400000)
  • concurrent mark-sweep generation total 3354624K, used 3078000K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000)
  • Metaspace used 90225K, capacity 91504K, committed 91776K, reserved 1130496K
  • class space used 9517K, capacity 9806K, committed 9856K, reserved 1048576K
  • }
  • 2019-03-28T20:05:10.603+0800: 3644463.070: Total time for which application threads were stopped: 0.4258929 seconds, Stopping threads took: 0.0001722 seconds
  • 2019-03-28T20:05:10.904+0800: 3644463.372: [CMS-concurrent-abortable-preclean: 2.397/2.828 secs] [Times: user=6.22 sys=0.10, real=2.83 secs]
  • 2019-03-28T20:05:10.904+0800: 3644463.372: Application time: 0.3012271 seconds
  • 2019-03-28T20:05:10.907+0800: 3644463.374: [GC (CMS Final Remark) [YG occupancy: 434406 K (1887488 K)]{Heap before GC invocations=18477 (full 731):
  • par new generation total 1887488K, used 434406K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)
  • eden space 1677824K, 13% used [0x0000000673400000, 0x00000006817bed10, 0x00000006d9a80000)
  • from space 209664K, 95% used [0x00000006d9a80000, 0x00000006e5efae68, 0x00000006e6740000)
  • to space 209664K, 0% used [0x00000006e6740000, 0x00000006e6740000, 0x00000006f3400000)
  • concurrent mark-sweep generation total 3354624K, used 3078000K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000)
  • Metaspace used 90225K, capacity 91504K, committed 91776K, reserved 1130496K
  • class space used 9517K, capacity 9806K, committed 9856K, reserved 1048576K
  • 2019-03-28T20:05:10.907+0800: 3644463.375: [GC (CMS Final Remark) 3644463.375: [ParNew (promotion failed): 434406K->315478K(1887488K), 5.8407801 secs] 3512406K->3486710K(5242112K), 5.8410096 secs] [Times: user=6.84 sys=1.31, real=5.84 secs]
  • Heap after GC invocations=18478 (full 731):
  • par new generation total 1887488K, used 315478K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)
  • eden space 1677824K, 13% used [0x0000000673400000, 0x00000006817bed10, 0x00000006d9a80000)
  • from space 209664K, 39% used [0x00000006e6740000, 0x00000006eb796e60, 0x00000006f3400000)
  • to space 209664K, 95% used [0x00000006d9a80000, 0x00000006e5efae68, 0x00000006e6740000)
  • concurrent mark-sweep generation total 3354624K, used 3171231K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000)
  • Metaspace used 90225K, capacity 91504K, committed 91776K, reserved 1130496K
  • class space used 9517K, capacity 9806K, committed 9856K, reserved 1048576K
  • }
  • 3644469.216: [Rescan (parallel) , 0.3096135 secs]3644469.525: [weak refs processing, 0.0009228 secs]3644469.526: [class unloading, 0.0797710 secs]3644469.606: [scrub symbol table, 0.0229535 secs]3644469.629: [scrub string table, 0.0020416 secs][1 CMS-remark: 3171231K(3354624K)] 3486710K(5242112K), 6.2593934 secs] [Times: user=8.10 sys=1.36, real=6.26 secs]
  • 2019-03-28T20:05:17.166+0800: 3644469.634: Total time for which application threads were stopped: 6.2622888 seconds, Stopping threads took: 0.0002099 seconds
  • 2019-03-28T20:05:17.167+0800: 3644469.634: [CMS-concurrent-sweep-start]
  • 2019-03-28T20:05:17.176+0800: 3644469.644: Application time: 0.0100218 seconds
  • 2019-03-28T20:05:17.179+0800: 3644469.647: Total time for which application threads were stopped: 0.0025500 seconds, Stopping threads took: 0.0001934 seconds
  • 2019-03-28T20:05:18.179+0800: 3644470.647: Application time: 1.0001731 seconds
  • 2019-03-28T20:05:18.182+0800: 3644470.649: Total time for which application threads were stopped: 0.0026811 seconds, Stopping threads took: 0.0001358 seconds
  • 2019-03-28T20:05:21.000+0800: 3644473.468: Application time: 2.8185985 seconds
  • 2019-03-28T20:05:21.003+0800: 3644473.471: Total time for which application threads were stopped: 0.0029238 seconds, Stopping threads took: 0.0001172 seconds
  • 2019-03-28T20:05:21.013+0800: 3644473.481: Application time: 0.0097451 seconds
  • 2019-03-28T20:05:21.019+0800: 3644473.487: Total time for which application threads were stopped: 0.0060990 seconds, Stopping threads took: 0.0002775 seconds
  • 2019-03-28T20:05:21.734+0800: 3644474.201: Application time: 0.7144315 seconds
  • 2019-03-28T20:05:21.736+0800: 3644474.204: Total time for which application threads were stopped: 0.0026804 seconds, Stopping threads took: 0.0001238 seconds
  • 2019-03-28T20:05:22.203+0800: 3644474.671: [CMS-concurrent-sweep: 5.019/5.037 secs] [Times: user=5.28 sys=0.27, real=5.03 secs]
  • 2019-03-28T20:05:22.204+0800: 3644474.671: [CMS-concurrent-reset-start]
  • 2019-03-28T20:05:22.211+0800: 3644474.678: [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
  • 2019-03-28T20:05:22.238+0800: 3644474.706: Application time: 0.5016696 seconds
  • 2019-03-28T20:05:22.241+0800: 3644474.708: Total time for which application threads were stopped: 0.0026876 seconds, Stopping threads took: 0.0001305 seconds
  • 2019-03-28T20:05:22.438+0800: 3644474.905: Application time: 0.1970764 seconds
  • 2019-03-28T20:05:22.440+0800: 3644474.908: Total time for which application threads were stopped: 0.0027034 seconds, Stopping threads took: 0.0001344 seconds
  • 2019-03-28T20:05:23.441+0800: 3644475.908: Application time: 1.0001304 seconds
  • 2019-03-28T20:05:23.443+0800: 3644475.911: Total time for which application threads were stopped: 0.0024875 seconds, Stopping threads took: 0.0001316 seconds
  • 2019-03-28T20:05:24.210+0800: 3644476.678: Application time: 0.7671567 seconds
  •  

通过日志可知,由于配置 -XX:+CMSScavengeBeforeRemark 参数,CMS Final Remark 阶段触发了一次 Young GC,而这时 OldGen 所剩无几没有足够的空闲空间放置 Young GC 晋升的对象,导致 Young GC 回收停止,致使 to space 不为空。
因此 to space 不为空的直接导火索是 Young GC “promotion failed”,那跟 -XX:+CMSScavengeBeforeRemark 参数有没有关系呢?当然有关系,因为这次 Young GC 就是由于配置了 -XX:+CMSScavengeBeforeRemark 参数,而触发的。
但是有人要说 “如果没有配置 -XX:+CMSScavengeBeforeRemark 参数,CMS GC 过程中也可能会发生 Young GC 的,如果 Young GC 晋升失败,一样会导致 to space 不为空”。
这种说法乍一看是合理的,CMS GC 过程中有几个阶段是并发,确实会出现由于Allocation Failure 而导致 Young GC,但是 Allocation Failure 触发的 Young GC,如果出现晋升失败大部分情况下都是会直接触发 Full GC,来直接对整个堆进行回收,不会出现后续的频繁 CMS GC。
因此,-XX:+CMSScavengeBeforeRemark 参数是可能会触发频繁 CMS GC 的。

什么场景会出现这种问题

有些同学可能要问,我们线上很多业务都配置了 -XX:+CMSScavengeBeforeRemark 参数,为什么都没出现过频繁 CMS GC 的问题,该问题在什么场景下比较易触发呢?该问题的出现条件是什么?
要了解在什么场景下比较容易触发,我们先来看看什么条件下会触发这个问题。
主要有两个条件:

  • -XX:+CMSScavengeBeforeRemark 参数引起的 “promotion failed” 的 Young GC,致使 to space 不为空;

  • 长时间没有 Allocation Failure 引起的 Young GC。

了解了这两个条件,就能解释为什么一般业务配置了这个参数,但是没有出现过类似频繁 CMS GC 的情况。
大部分业务很少出现因为 -XX:+CMSScavengeBeforeRemark 参数引起的 “promotion failed” 的 Young GC。
另外,一般业务的 Allocation Failure 引起的 Young GC 比较频繁,即使发生第一个条件,也很快会出现 Allocation Failure 引起的 “promotion failed” 的 Young GC,进而触发 Full GC 恢复,因此,即使出现时间持续时间也很短。

文章中的案例,就是符合两个条件,进而导致频繁 CMS GC。

  • 晋升对象比较大,很容易导致 “-XX:+CMSScavengeBeforeRemark 参数引起的 “promotion failed” 的 Young GC” 这种情况;

  • 长时间才会出现一次 Young GC, 又满足了 “长时间没有 Allocation Failure 引起的 Young GC” 条件。

有哪些优化策略

  1. 去掉 -XX:+CMSScavengeBeforeRemark 参数
    CMS GC 过程中不强制触发 Young GC,自然降低了 “promotion failed” Young GC 的出现次数,也不会导致 to space 不为空,进而降低了导致频繁 CMS GC 的可能。

  2. 降低 promotion failed 发生的概率
    可以通过降低 -XX:CMSInitiatingOccupancyFraction 参数的阈值,来降低 CMS GC 过程中因为 -XX:+CMSScavengeBeforeRemark 参数导致的 Young GC 出现 “promotion failed” 的概率。

  3. 提高 Young GC 的频率
    可以通过减小 YoungGen 的大小,来加快因 Allocation Failure 而触发 Young GC,这样即使出现该问题,也能尽快触发 Full GC 恢复。

总结

针对上述分析可知,-XX:+CMSScavengeBeforeRemark 参数确实是与案例中频繁 CMS GC 是相关的,只是出现的该问题的条件比较苛刻,不太容易出现;另外,针对问题出现的条件,是有些办法可以避免该问题或者降低该问题的出现概率。

分类:
标签:
请先登录,再评论

连看了两篇优秀

1年前

够深入的啊👍

1年前

为你推荐

不起眼,但是足以让你有收获的JVM内存分析案例
分析 这个问题说白了,就是说有些int[]对象不知道是哪里来的,于是我拿他的例子跑了跑,好像还真有这么回事。点该 dump 文件详情,查看相关的 int[] 数组,点该对象的“被引用对象”,发现所
从一起GC血案谈到反射原理
前言 首先回答一下提问者的问题。这主要是由于存在大量反射而产生的临时类加载器和 ASM 临时生成的类,这些类会被保留在 Metaspace,一旦 Metaspace 即将满的时候,就会触发 Fu
关于内存溢出,咱再聊点有意思的?
概述 上篇文章讲了JVM在GC上的一个设计缺陷,揪出一个导致GC慢慢变长的JVM设计缺陷,可能有不少人还是没怎么看明白的,今天准备讲的大家应该都很容易看明白 本文其实很犹豫写不写,因为感觉没有
协助美团kafka团队定位到的一个JVM Crash问题
概述 有挺长一段时间没写技术文章了,正好这两天美团kafka团队有位小伙伴加了我微信,然后咨询了一个JVM crash的问题,大家对crash的问题都比较无奈,因为没有现场,信息量不多,碰到这类问题我
又发现一个导致JVM物理内存消耗大的Bug(已提交Patch)
概述 最近我们公司在帮一个客户查一个JVM的问题(JDK1.8.0_191-b12),发现一个系统老是被OS Kill掉,是内存泄露导致的。在查的过程中,阴差阳错地发现了JVM另外的一个Bug。这个B
JVM实战:优化我的IDEA GC
IDEA是个好东西,可以说是地球上最好的Java开发工具,但是偶尔也会卡顿,仔细想想IDEA也是Java开发的,会不会和GC有关,于是就有了接下来对IDEA的GC进行调优 IDEA默认JVM参数: -
不起眼,但是足以让你收获的JVM内存案例
今天的这个案例我觉得应该会让你涨姿势吧,不管你对JVM有多熟悉,看到这篇文章,应该还是会有点小惊讶的,不过我觉得这个案例我分享出来,是想表达不管多么奇怪的现象请一定要追究下去,会让你慢慢变得强大起来,
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得