问题标签 [concurrent-mark-sweep]

这是一段显示完整 CMS GC 事件的 GC 日志：

CMS 运行时似乎有一个次要 GC 事件：

那样行吗？次要 GC 是否会阻塞完整 GC？

这可以解释我们看到的非常高的系统时间吗？（系统=8.55 秒，系统=8.50 秒）

CMS-initial-mark 从 60%（预期值）开始并不断增长，尽管使用：-XX:+UseCMSInitiatingOccupancyOnly 和 -XX:CMSInitiatingOccupancyFraction=60

我可以寻求帮助，为什么它会增加？

标志：

-Xms28g -Xmx28g -XX:PermSize=512m -XX:MaxPermSize=512m -Xss512k -XX:NewSize=8g -XX:MaxNewSize=8g -XX:SurvivorRatio=6 -XX:+AlwaysPreTouch -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSConcurrentMTEnabled -XX:+CMSScavengeBeforeRemark -XX:CMSWaitDuration=3600000 -XX:+ExplicitGCInvokesConcurrent -XX:CMSScheduleRemarkEdenPenetration=10 -XX:CMSMaxAbortablePrecleanTime=5000 -XX :CMSInitiatingOccupancyFraction=60 -XX:+UseCMSInitiatingOccupancyOnly

GC日志：

08/25-18:00:48 [4] <48574> 145285.817: [CMS-concurrent-abortable-preclean-start]

08/25-18:00:51 [4] <48574> 145286.877：[ GC（分配失败） 145286.877：[ParNew（升级失败）：6332558K->6339431K（7340032K），1.7870705 秒]145288.664：[CMS1452 [CMS-concurrent-abortable-preclean: 1.138/2.932 secs] [Times: user=7.11 sys=0.04, real=2.93 secs]

08/25-18:02:14 [4] <48574> （并发模式失败）：20937785K->20947677K(20971520K), 82.4977633 秒] 27269752K->20947677K(28311552K), [元空间: 108471K4-8] ], 84.2851262 secs] [Times: user=84.51 sys=0.01, real=84.29 secs]

oldGen 历史：

08/25-18:00:34 [4] <48574> 145271.408: [GC (CMS Initial Mark) [1 CMS-initial-mark: 20933339K(20971520K)] 21000667K(28311552K), 0.0057867 secs] [Times: user= 0.04 系统=0.00，真实=0.01 秒]

08/25-18:02:31 [4] <48574> 145388.639: [GC (CMS Initial Mark) [1 CMS-initial-mark: 20947677K(20971520K)] 21005038K(28311552K), 0.0044022 secs] [Times: user= 0.03 系统=0.00，真实=0.01 秒]

问题是这样的。

我们正在使用 CMS 并遇到并发模式故障（大约需要 15 秒）。使用 JRE 8。

已经在使用 UseCMSInitiatingOccupancyOnly 和 CMSInitiatingOccupancyFraction (80%)。不使用 CMSScavengeBeforeRemark。

分配模式是这样的：

分配了许多短期对象。所以我们使用了一个大的年轻代，2GB。幸存者空间未调整。MaxTenuringThreshold 设置为 15。每隔几个小时 CMS 就会启动。

老一代是4GB。内存使用率很高。每次收集后，老年代大约有 30% 的空闲空间。不幸的是，没有更多的可用内存。我们正计划修改程序以使其使用更少的内存，但这需要时间。

通常程序没有太多工作要做，但每隔几个小时（我们无法预测何时）我们就会变得非常忙碌。15 秒的 STW 实在是太长了。

所以我的问题是：

我们如何为我们的程序调整 CMS？

我应该增加老一代（减少年轻一代）吗？

我应该调整幸存者吗？

我应该更改 CMSInitiatingOccupancyFraction 吗？

G1GC 会有帮助吗？

我有一个带有 4 个 JVM 的 linux 应用程序服务器。我对它们使用的 GC 算法是 CMS。我可以将其中两个 JVM 的 GC 算法更改为 G1GC 吗？这样做有什么负面影响吗？

我面临一个特殊的问题，即旧垃圾收集在上次收集后立即开始。

从初始标记可以看出，在上一次收集之后，老年代仅被占用 30%。有人可以解释一下吗？另外，由于这个，我的请求队列被填满了

提前致谢。

我有这样的代码，很简单：

这是我的 JVM 选项：

我可以在路径 dir /Users/roger 中获取 gc 日志文件，并且 gc.log 内容如下：

Java HotSpot(TM) 64-Bit Server VM (25.181-b13) for bsd-amd64 JRE (1.8.0_181-b13), built on Jul 7 2018 01:02:31 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00) Memory: 4k page, physical 8388608k(258072k free)

CommandLine flags: -XX:CMSInitiatingOccupancyFraction=75 -XX:+ExplicitGCInvokesConcurrent -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:MaxTenuringThreshold=6 -XX:NewRatio=1 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintPromotionFailure -XX:ThreadStackSize=512 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 2018-11-03T01:26:37.136-0800: 0.245: Total time for which application threads were stopped: 0.0000852 seconds, Stopping threads took: 0.0000282 seconds 2018-11-03T01:26:37.136-0800: 0.245: Total time for which application threads were stopped: 0.0000434 seconds, Stopping threads took: 0.0000213 seconds 2018-11-03T01:26:37.136-0800: 0.245: Total time for which application threads were stopped: 0.0000500 seconds, Stopping threads took: 0.0000072 seconds 2018-11-03T01:26:38.138-0800: 1.247: Total time for which application threads were stopped: 0.0000811 seconds, Stopping threads took: 0.0000215 seconds 2018-11-03T01:26:41.441-0800: 4.550: Total time for which application threads were stopped: 0.0000860 seconds, Stopping threads took: 0.0000173 seconds 2018-11-03T01:26:42.419-0800: 5.527: [GC (System.gc()) 2018-11-03T01:26:42.419-0800: 5.527: [ParNew: 33556K->536K(943744K), 0.0049418 secs] 33556K->536K(1992320K), 0.0051371 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 2018-11-03T01:26:42.424-0800: 5.533: Total time for which application threads were stopped: 0.0052935 seconds, Stopping threads took: 0.0000191 seconds 2018-11-03T01:26:42.424-0800: 5.533: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(1048576K)] 536K(1992320K), 0.0003129 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-11-03T01:26:42.424-0800: 5.533: Total time for which application threads were stopped: 0.0003991 seconds, Stopping threads took: 0.0000239 seconds 2018-11-03T01:26:42.424-0800: 5.533: [CMS-concurrent-mark-start] 2018-11-03T01:26:42.438-0800: 5.547: [CMS-concurrent-mark: 0.014/0.014 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2018-11-03T01:26:42.438-0800: 5.547: [CMS-concurrent-preclean-start] 2018-11-03T01:26:42.440-0800: 5.548: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 2018-11-03T01:26:42.440-0800: 5.548: [GC (CMS Final Remark) [YG occupancy: 536 K (943744 K)]2018-11-03T01:26:42.440-0800: 5.548: [Rescan (parallel) , 0.0010829 secs]2018-11-03T01:26:42.441-0800: 5.550: [weak refs processing, 0.0000814 secs]2018-11-03T01:26:42.441-0800: 5.550: [class unloading, 0.0002646 secs]2018-11-03T01:26:42.441-0800: 5.550: [scrub symbol table, 0.0003364 secs]2018-11-03T01:26:42.442-0800: 5.550: [scrub string table, 0.0001618 secs][1 CMS-remark: 0K(1048576K)] 536K(1992320K), 0.0020665 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2018-11-03T01:26:42.442-0800: 5.551: Total time for which application threads were stopped: 0.0021350 seconds, Stopping threads took: 0.0000122 seconds 2018-11-03T01:26:42.442-0800: 5.551: [CMS-concurrent-sweep-start] 2018-11-03T01:26:42.442-0800: 5.551: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-11-03T01:26:42.442-0800: 5.551: [CMS-concurrent-reset-start] Heap par new generation total 943744K, used 8926K [0x0000000740000000, 0x0000000780000000, 0x0000000780000000) eden space 838912K, 1% used [0x0000000740000000, 0x00000007408315f0, 0x0000000773340000) from space 104832K, 0% used [0x00000007799a0000, 0x0000000779a263b0, 0x0000000780000000) to space 104832K, 0% used [0x0000000773340000, 0x0000000773340000, 0x00000007799a0000) concurrent mark-sweep generation total 1048576K, used 0K [0x0000000780000000, 0x00000007c0000000, 0x00000007c0000000) Metaspace used 3157K, capacity 4568K, committed 4864K, reserved 1056768K class space used 338K, capacity 392K, committed 512K, reserved 1048576K

我们可以在 gc 日志文件中看到一个 CMS gc。CMS gc 是由调用方法 System.gc() 引起的吗？以及如何在 gc 日志中知道这一点？我们只能在 gc 日志中看到由 System.gc() 方法引起的 ParNew gc。

在大负载时，我们的应用程序注意到大的 GC 暂停（400 毫秒）。在调查期间，事实证明，与其他阶段（10x-100X）相比，该暂停发生在CMS Final Remark并且class unloading阶段花费了更多时间：

这种暂停总是发生在性能测试的第一秒，暂停的持续时间从 300ms 到 400+ms 不等。

不幸的是，我无法访问服务器（它正在维护中）并且只有几次测试运行的日志。但是当服务器可用时，我想为进一步调查做好准备，但我不知道是什么导致了这种行为。

我的第一个想法是关于 Linux Huge pages，但我们不使用它们。

在日志中经过更多时间后，我发现以下内容：

调查 GC 暂停发生在 GC 调用 7969 和 7970 之间。元空间中的已用空间量几乎相同（实际上增加了）

所以，看起来它实际上并不是一些不再使用的停顿类（因为没有空间被清除），并且它不是安全点到达问题 - 因为线程阻塞需要很短的时间（0.0014133）。

如何调查这种情况以及适当的准备需要哪些诊断信息。

技术细节

Centos5 + JDK8 + CMS GC 带参数：

我们有一个在 OpenJDK8 上运行的应用程序，它一整天的分配率都很高（大约 80 MB/秒）。

我们注意到整体young generation gc时间直接参考old generation的占用，并且越来越慢。这怎么可能？此外，在强制 FullGC 之后，平均 GC 时间再次变快，之后又缓慢增加

工作量没有太大变化，并且有大量的 OldGen 可用空间。是的，有对 OldGen 的推广，但这是有意的，无法优化。

这里有两张图作为证据： OldGen YoungGen

请忽略 OldGen 的尖峰，这只是一个测量错误。红线代表 GC。

我们使用这些启动参数：

提前致谢。

我使用 jmap 转储使用 CMS GC 的应用程序的实时堆：

我用 YourKit 打开了这个转储，发现 61% 的 8Gb 堆无法访问，特别是

我认为 using-dump:live意味着它只包含可到达的对象？

应用程序的 gc.log 文件可疑地缺少由我调用 jmap 引起的任何完整 GC，而是在我进行转储的两侧显示这些行：

在进行堆转储后第一次 CMS 重置后的第一个 ParNew 集合中，我看到堆大致是堆转储中的大小（大约 3-4Gb）：

那么也许在这种情况下 jmap 没有触发完整的 GC？那可能/可配置吗？

从plumbr 的食谱中，我看到了 init mark、concurrent mark、concurrent preclean 和 concurrent abortable preclean 的作用。

初始标记

并发标记

并发预清理

但我无法得到关于“最后评论”的真正工作。只是再次遍历老一代？如果是这样的话，我认为前面的步骤是没有必要的。</p>