江苏龙网

  1. 首页 > 人文 > >

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

看第一次 CMS GC 日志 ， 有以下四个发现：

  1. 由日志 “CMS-initial-mark: 2935428K(3354624K)”可知 ， 第一次 CMS GC 是因为 2935428 / 3354624 = 87.5% > 80% ， 与此前监控图分析一致 。
  2. 由日志 “2019-03-28T20:05:22.211+0800: 3644474.678: [CMS-concurrent-reset: 0.007/0.007 secs]” 可知 ， 第一次 CMS GC 完成具体时间是 20:05:22.211 。
  3. 由日志 “[GC (Allocation Failure) 3644462.647: [ParNew: 1887488K->201195K(1887488K), 0.4228807 secs]” 和日志 “[GC (CMS Final Remark) 3644463.375: [ParNew (promotion failed): 434406K->315478K(1887488K), 5.8407801 secs]”可知 ， 第一次 CMS GC 日志中包含两次 Young GC ， 并且第一次 YoungGC 是由于 Allocation Failure ， 而第二次是因为什么呢 ， 其实是因为配置了-XX:+CMSScavengeBeforeRemark 参数 ， 因此在 CMS-remark 阶段前进行了一次 YoungGC 。
  4. 除了以上的信息 ， 还有个奇怪的现象是 ， Young GC 后 eden、from、to 三个 space 的使用量都不是 0 使用的情况 ， 正常情况 Young GC 后 eden 和 to space 的使用量应该是 0 。 这里其实不奇怪 ， 通过日志 “concurrent mark-sweep generation total 3354624K, used 3171231K” 可知 ， OldGen 所剩无几 ， 而且还可能存在碎片 ， 这会导致 Young GC 晋升的对象 ， 无处安放 ， 导致 Young GC 回收停止了 。
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 generationtotal 1887488K, used 315478K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)eden space 1677824K,13% used [0x0000000673400000, 0x00000006817bed10, 0x00000006d9a80000)from space 209664K,39% used [0x00000006e6740000, 0x00000006eb796e60, 0x00000006f3400000)tospace 209664K,95% used [0x00000006d9a80000, 0x00000006e5efae68, 0x00000006e6740000) concurrent mark-sweep generation total 3354624K, used 3171231K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000) Metaspaceused 90225K, capacity 91504K, committed 91776K, reserved 1130496Kclass spaceused 9517K, capacity 9806K, committed 9856K, reserved 1048576K}第二次 CMS GC 日志
2019-03-28T20:05:24.213+0800: 3644476.680: [GC (CMS Initial Mark) [1 CMS-initial-mark: 899032K(3354624K)] 1548664K(5242112K), 0.2663899 secs] [Times: user=0.82 sys=0.00, real=0.27 secs]2019-03-28T20:05:24.479+0800: 3644476.947: Total time for which application threads were stopped: 0.2691825 seconds, Stopping threads took: 0.0001300 seconds2019-03-28T20:05:24.480+0800: 3644476.947: [CMS-concurrent-mark-start]2019-03-28T20:05:25.453+0800: 3644477.921: [CMS-concurrent-mark: 0.973/0.973 secs] [Times: user=0.98 sys=0.00, real=0.97 secs]2019-03-28T20:05:25.453+0800: 3644477.921: [CMS-concurrent-preclean-start]2019-03-28T20:05:25.463+0800: 3644477.931: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]2019-03-28T20:05:25.463+0800: 3644477.931: [CMS-concurrent-abortable-preclean-start]2019-03-28T20:05:25.463+0800: 3644477.931: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]2019-03-28T20:05:25.464+0800: 3644477.931: Application time: 0.9841796 seconds2019-03-28T20:05:25.466+0800: 3644477.934: [GC (CMS Final Remark) [YG occupancy: 649871 K (1887488 K)]{Heap before GC invocations=18478 (full 732): par new generationtotal 1887488K, used 649871K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)eden space 1677824K,33% used [0x0000000673400000, 0x0000000695e4cfa0, 0x00000006d9a80000)from space 209664K,39% used [0x00000006e6740000, 0x00000006eb796e60, 0x00000006f3400000)tospace 209664K,95% used [0x00000006d9a80000, 0x00000006e5efae68, 0x00000006e6740000) concurrent mark-sweep generation total 3354624K, used 899032K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000) Metaspaceused 90199K, capacity 91456K, committed 91776K, reserved 1130496Kclass spaceused 9512K, capacity 9798K, committed 9856K, reserved 1048576K2019-03-28T20:05:25.466+0800: 3644477.934: [GC (CMS Final Remark) 3644477.934: [ParNew: 649871K->649871K(1887488K), 0.0000289 secs] 1548903K->1548903K(5242112K), 0.0001785 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]Heap after GC invocations=18479 (full 732): par new generationtotal 1887488K, used 649871K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)eden space 1677824K,33% used [0x0000000673400000, 0x0000000695e4cfa0, 0x00000006d9a80000)from space 209664K,39% used [0x00000006e6740000, 0x00000006eb796e60, 0x00000006f3400000)tospace 209664K,95% used [0x00000006d9a80000, 0x00000006e5efae68, 0x00000006e6740000) concurrent mark-sweep generation total 3354624K, used 899032K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000) Metaspaceused 90199K, capacity 91456K, committed 91776K, reserved 1130496Kclass spaceused 9512K, capacity 9798K, committed 9856K, reserved 1048576K}3644477.934: [Rescan (parallel) , 0.6932186 secs]3644478.627: [weak refs processing, 0.0000973 secs]3644478.628: [class unloading, 0.0527698 secs]3644478.680: [scrub symbol table, 0.0170169 secs]3644478.697: [scrub string table, 0.0019041 secs][1 CMS-remark: 899032K(3354624K)] 1548903K(5242112K), 0.7680979 secs] [Times: user=2.75 sys=0.00, real=0.76 secs]2019-03-28T20:05:26.234+0800: 3644478.702: Total time for which application threads were stopped: 0.7708180 seconds, Stopping threads took: 0.0001262 seconds2019-03-28T20:05:26.235+0800: 3644478.703: [CMS-concurrent-sweep-start]2019-03-28T20:05:27.235+0800: 3644479.702: Application time: 1.0001322 seconds2019-03-28T20:05:27.237+0800: 3644479.705: Total time for which application threads were stopped: 0.0026851 seconds, Stopping threads took: 0.0001390 seconds2019-03-28T20:05:27.441+0800: 3644479.908: Application time: 0.2034629 seconds2019-03-28T20:05:27.445+0800: 3644479.912: Total time for which application threads were stopped: 0.0038960 seconds, Stopping threads took: 0.0014157 seconds2019-03-28T20:05:28.445+0800: 3644480.912: Application time: 1.0001430 seconds2019-03-28T20:05:28.447+0800: 3644480.915: Total time for which application threads were stopped: 0.0026665 seconds, Stopping threads took: 0.0001339 seconds2019-03-28T20:05:31.156+0800: 3644483.624: Application time: 2.7089917 seconds2019-03-28T20:05:31.159+0800: 3644483.627: Total time for which application threads were stopped: 0.0025883 seconds, Stopping threads took: 0.0001411 seconds2019-03-28T20:05:32.468+0800: 3644484.936: [CMS-concurrent-sweep: 6.221/6.233 secs] [Times: user=6.35 sys=0.06, real=6.24 secs]2019-03-28T20:05:32.468+0800: 3644484.936: [CMS-concurrent-reset-start]2019-03-28T20:05:32.476+0800: 3644484.943: [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]2019-03-28T20:05:33.159+0800: 3644485.627: Application time: 2.0002143 seconds2019-03-28T20:05:33.162+0800: 3644485.630: Total time for which application threads were stopped: 0.0026832 seconds, Stopping threads took: 0.0001180 seconds2019-03-28T20:05:34.162+0800: 3644486.630: Application time: 1.0000781 seconds2019-03-28T20:05:34.164+0800: 3644486.632: Total time for which application threads were stopped: 0.0023807 seconds, Stopping threads took: 0.0001220 seconds2019-03-28T20:05:34.476+0800: 3644486.943: Application time: 0.3111430 seconds


推荐阅读


上一篇：专家介绍智能手机的使用年限

下一篇：系统小技巧：全面修复文件夹无权访问