3

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

2016-12-29T22:44:34.741-0500: 27572.982: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2508212K(23068672K)] 2931097K(26843584K), 0.0213349 secs] [Times: user=0.22 sys=0.00, real=0.02 secs] 
2016-12-29T22:44:34.763-0500: 27573.004: [CMS-concurrent-mark-start]
2016-12-29T22:44:36.013-0500: 27574.254: [CMS-concurrent-mark: 0.208/1.250 secs] [Times: user=3.07 sys=0.10, real=1.25 secs] 
2016-12-29T22:44:36.014-0500: 27574.255: [CMS-concurrent-preclean-start]
2016-12-29T22:44:36.061-0500: 27574.303: [CMS-concurrent-preclean: 0.047/0.048 secs] [Times: user=0.12 sys=0.00, real=0.05 secs] 
2016-12-29T22:44:36.062-0500: 27574.303: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-12-29T22:44:41.339-0500: 27579.580: [CMS-concurrent-abortable-preclean: 4.084/5.277 secs] [Times: user=9.53 sys=0.46, real=5.27 secs] 
2016-12-29T22:44:41.356-0500: 27579.598: [GC (CMS Final Remark) [YG occupancy: 3509179 K (3774912 K)]2016-12-29T22:44:41.357-0500: 27579.598: [Rescan (parallel) , 0.0816014 secs]2016-12-29T22:44:41.438-0500: 27579.680: [weak refs processing, 0.0000347 secs]2016-12-29T22:44:41.438-0500: 27579.680: [class unloading, 0.0292451 secs]2016-12-29T22:44:41.468-0500: 27579.709: [scrub symbol table, 0.0069857 secs]2016-12-29T22:44:41.475-0500: 27579.716: [scrub string table, 0.0010933 secs][1 CMS-remark: 2508212K(23068672K)] 6017391K(26843584K), 0.1194737 secs] [Times: user=2.18 sys=0.00, real=0.12 secs] 
2016-12-29T22:44:41.477-0500: 27579.718: [CMS-concurrent-sweep-start]
2016-12-29T22:44:41.618-0500: 27579.860: [GC (Allocation Failure) 2016-12-29T22:44:41.619-0500: 27579.860: [ParNew: 3579431K->419392K(3774912K), 5.7752364 secs] 6080306K->3302237K(26843584K), 5.7769753 secs] [Times: user=4.70 sys=8.50, real=5.78 secs] 
2016-12-29T22:44:47.698-0500: 27585.940: [CMS-concurrent-sweep: 0.230/6.221 secs] [Times: user=5.76 sys=8.55, real=6.22 secs] 
2016-12-29T22:44:47.699-0500: 27585.940: [CMS-concurrent-reset-start]
2016-12-29T22:44:47.717-0500: 27585.958: [GC (System.gc()) 2016-12-29T22:44:47.718-0500: 27585.959: [ParNew: 527384K->155025K(3774912K), 0.7351766 secs] 3405551K->3441841K(26843584K), 0.7366514 secs] [Times: user=5.61 sys=1.44, real=0.74 secs] 
2016-12-29T22:44:48.503-0500: 27586.744: [CMS-concurrent-reset: 0.049/0.804 secs] [Times: user=5.81 sys=1.45, real=0.81 secs]

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

2016-12-29T22:44:41.618-0500: 27579.860: [GC (Allocation Failure) 2016-12-29T22:44:41.619-0500: 27579.860: [ParNew: 3579431K->419392K(3774912K), 5.7752364 secs] 6080306K->3302237K(26843584K), 5.7769753 secs] [Times: user=4.70 sys=8.50, real=5.78 secs]

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

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

4

3 回答 3

1

在您的情况下，使用的 GC 算法是：-

年轻代的并行新 + 老一代的并发标记和扫描 (CMS)

CMS 运行时似乎发生了次要 GC 事件，可以吗？
是的，ParNew 和 CMS 可以并行运行。

次要 GC 是否会阻塞完整 GC？
是的，ParNew 次要集合会“中断”并发 CMS 集合。在并发收集老年代期间，新生代的收集可以随时发生。在这种情况下，主要收集将与次要 GC 事件交错

这可以解释我们看到的非常高的系统时间吗？
您需要在 GC 中检查 Stop-the-world 事件的频率和持续时间。

  1. CMS 初始标记
  2. CMS 最后的话
  3. 帕尔新

通过查看您的日志，我可以看出您的 Minor GC (ParNew) 花费了太多时间来完成。
5.7752364 秒：垃圾收集器标记和复制年轻代中的活动对象所需的时间+与 ConcurrentMarkSweep 收集器的通信开销

Java GC的好参考，值得一读。

于 2016-12-30T20:30:58.237 回答
0

当然，年轻的收集可以发生在旧的收集期间。通常这不是一个大问题，但在 CMS 备注阶段直接在年轻集合之后（或其他方式，因此两者都是停止世界暂停）的情况下，它可能会损害性能。CMS 将通过计算下一次年轻收集发生的时间来尝试避免这种情况，但这只是理论。

于 2016-12-30T20:41:18.777 回答
0

如果 Young GC 在 CMS 阶段之间运行是绝对可以的。在 CMS 初始标记或 CMS 备注之前进行年轻收集甚至可以减少主要 GC 的 stop-the-world 暂停。

不正常的是在执行 GC 时系统时间（CPU 时间花费在内核中）很大。这通常不应该发生，因为垃圾收集主要是用户空间的工作。

检查top、perf等以找出导致系统时间过长的原因。这通常与内存问题有关：交换或透明大页面碎片整理。

于 2016-12-30T22:46:08.163 回答