- 机器 Appbl-pro-group2-25gcv
- 时间 2023-09-24 15:00 —— 2023-09-25 15:00
- 发生了3次 full GC
监控
分析最近一次 CMS GC，查看grafna 监控，可以看到如下数据:
- 老年代：8.45G——>216M
- eden：3.78G——>6.00G
- survivor：47.9M——>47.3M
- metaspace：128M——>128M
日志
2023-09-25T11:35:42.029+0800: 595502.668: [GC (CMS Initial Mark) [1 CMS-initial-mark: 8861188K(12656640K)] 8909230K(20140032K), 0.0025643 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
2023-09-25T11:35:42.031+0800: 595502.671: [CMS-concurrent-mark-start]
2023-09-25T11:35:42.091+0800: 595502.731: [CMS-concurrent-mark: 0.060/0.060 secs] [Times: user=0.31 sys=0.04, real=0.06 secs]
2023-09-25T11:35:42.091+0800: 595502.731: [CMS-concurrent-preclean-start]
2023-09-25T11:35:42.106+0800: 595502.746: [CMS-concurrent-preclean: 0.014/0.014 secs] [Times: user=0.05 sys=0.01, real=0.02 secs]
2023-09-25T11:35:42.106+0800: 595502.746: [CMS-concurrent-abortable-preclean-start]
2023-09-25T11:35:44.443+0800: 595505.083: [CMS-concurrent-abortable-preclean: 2.311/2.337 secs] [Times: user=5.93 sys=0.89, real=2.34 secs]
2023-09-25T11:35:44.447+0800: 595505.086: [GC (CMS Final Remark) [YG occupancy: 3497994 K (7483392 K)]2023-09-25T11:35:44.447+0800: 595505.086: [Rescan (parallel) , 0.0738369 secs]2023-09-25T11:35:44.520+0800: 595505.160: [weak refs processing, 0.0015907 secs]2023-09-25T11:35:44.522+0800: 595505.162: [class unloading, 0.0279791 secs]2023-09-25T11:35:44.550+0800: 595505.190: [scrub symbol table, 0.0147747 secs]2023-09-25T11:35:44.565+0800: 595505.205: [scrub string table, 0.0011507 secs][1 CMS-remark: 8861188K(12656640K)] 12359182K(20140032K), 0.1198031 secs] [Times: user=1.23 sys=0.00, real=0.12 secs]
2023-09-25T11:35:44.567+0800: 595505.207: [CMS-concurrent-sweep-start]
2023-09-25T11:35:46.647+0800: 595507.286: [GC (Allocation Failure) 2023-09-25T11:35:46.647+0800: 595507.287: [ParNew: 6699862K->48209K(7483392K), 0.0098278 secs] 8173995K->1523994K(20140032K), 0.0101199 secs] [Times: user=0.14 sys=0.00, real=0.01 secs]
2023-09-25T11:35:47.120+0800: 595507.760: [CMS-concurrent-sweep: 2.533/2.553 secs] [Times: user=7.67 sys=0.29, real=2.55 secs]
2023-09-25T11:35:47.120+0800: 595507.760: [CMS-concurrent-reset-start]
2023-09-25T11:35:47.139+0800: 595507.779: [CMS-concurrent-reset: 0.019/0.019 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
整个GC过程 耗时 5s, 四个阶段中只有初始标记和重新标记会STW， STW的时间只有大概 0.12s。
阶段1 : 初始标记 （CMS Initial Mark）
- 2023-09-25T11:35:42.029+0800: 595502.668 ——GC开始时间，和相对于JVM启动的时间，这里是6.9d
- GC (CMS Initial Mark) —— 初始标记阶段，收集所有GC root 和其直接引用的对象
- 8861188K(12656640K)—— 当前老年代使用的容量 8.45G，老年代可用的最大容量12.07G
- 8909230K(20140032K)——整个堆目前的使用容量 8.49G，堆可用的容量 19.2G
- 0.0025643 secs —— 这个阶段持续的时间
并发标记
重新标记
2023-09-25T11:35:44.447+0800: 595505.086: [GC (CMS Final Remark) [YG occupancy: 3497994 K (7483392 K)]
2023-09-25T11:35:44.447+0800: 595505.086: [Rescan (parallel) , 0.0738369 secs]2023-09-25T11:35:44.520+0800: 595505.160: [weak refs processing, 0.0015907 secs]
2023-09-25T11:35:44.522+0800: 595505.162: [class unloading, 0.0279791 secs]
2023-09-25T11:35:44.550+0800: 595505.190: [scrub symbol table, 0.0147747 secs]
2023-09-25T11:35:44.565+0800: 595505.205: [scrub string table, 0.0011507 secs][1 CMS-remark: 8861188K(12656640K)] 12359182K(20140032K), 0.1198031 secs] [Times: user=1.23 sys=0.00, real=0.12 secs]
-
CMS Final Remark —— 标记老年代中所有存活的对象，包括在并发标记阶段建立和改变的引用
-
YG occupancy: 3497994 K (7483392 K)—— 年轻当前的占用量 3.34 和容量 7.14G
-
CMS-remark
- 8861188K(12656640K）——老年代使用量与总量，和初始标记相同
- 12359182K(20140032K)——堆的使用量和总量，对比初始标记阶段，总量不变，堆的使用量增大3.29G，年轻代增大导致。
- 0.12s 左右
