Java GC日志分析

1. 查看GC日志准备

-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

2. 年轻代GC日志

2019-09-17T23:12:05.334+0800: 6950.220: [GC2019-09-17T23:12:05.334+0800: 6950.220: [ParNew: 1713371K->30726K(1887488K), 0.0325240 secs] 1910235K->227695K(6081792K), 0.0329710 secs] [Times: user=0.12 sys=0.01, real=0.04 secs

3. CMS GC日志

2019-09-17T21:19:48.213+0800: 213.099: [GC [1 CMS-initial-mark: 2136781K(4194304K)] 2378922K(6081792K), 0.0269660 secs] [Times: user=0.02 sys=0.00, real=0.03 secs]
2019-09-17T21:19:48.240+0800: 213.126: [CMS-concurrent-mark-start]
2019-09-17T21:19:48.499+0800: 213.385: [CMS-concurrent-mark: 0.259/0.259 secs] [Times: user=0.98 sys=0.08, real=0.26 secs]
2019-09-17T21:19:48.499+0800: 213.385: [CMS-concurrent-preclean-start]
2019-09-17T21:19:48.508+0800: 213.394: [CMS-concurrent-preclean: 0.009/0.009 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
2019-09-17T21:19:48.509+0800: 213.395: [CMS-concurrent-abortable-preclean-start]
2019-09-17T21:19:50.125+0800: 215.011: [CMS-concurrent-abortable-preclean: 1.612/1.616 secs] [Times: user=3.28 sys=0.08, real=1.62 secs]
2019-09-17T21:19:50.125+0800: 215.011: [GC[YG occupancy: 1065145 K (1887488 K)]2019-09-17T21:19:50.125+0800: 215.011: [Rescan (parallel) , 0.1963400 secs]2019-09-17T21:19:50.321+0800: 215.207: [weak refs processing, 0.0003260 secs]2019-09-17T21:19:50.322+0800: 215.208: [class unloading, 0.0267880 secs]2019-09-17T21:19:50.349+0800: 215.235: [scrub symbol table, 0.0894820 secs]2019-09-17T21:19:50.438+0800: 215.324: [scrub string table, 0.0028500 secs] [1 CMS-remark: 2136781K(4194304K)] 3201926K(6081792K), 0.3199900 secs] [Times: user=0.87 sys=0.03, real=0.32 secs]
2019-09-17T21:19:50.445+0800: 215.331: [CMS-concurrent-sweep-start]
2019-09-17T21:19:51.334+0800: 216.220: [CMS-concurrent-sweep: 0.888/0.889 secs] [Times: user=1.81 sys=0.20, real=0.89 secs]
2019-09-17T21:19:51.334+0800: 216.220: [CMS-concurrent-reset-start]
2019-09-17T21:19:51.378+0800: 216.264: [CMS-concurrent-reset: 0.044/0.044 secs] [Times: user=0.09 sys=0.04, real=0.04 secs]

4. CMS GC 7阶段解析

1.初始标记

这个是 CMS 两次 stop-the-wolrd 事件的其中一次，这个阶段的目标是：标记那些直接被 GC root 引用或者被年轻代存活对象所引用的所有对象，标记后示例如下所示：

2. 并发标记

在这个阶段 Garbage Collector 会遍历老年代，然后标记所有存活的对象，它会根据上个阶段找到的 GC Roots 遍历查找。并发标记阶段，它会与用户的应用程序并发运行。并不是老年代所有的存活对象都会被标记，因为在标记期间用户的程序可能会改变一些引用，如下图所示：

3.并发预清理

Concurrent Preclean：这也是一个并发阶段，与应用的线程并发运行，并不会 stop 应用的线程。在并发运行的过程中，一些对象的引用可能会发生变化，但是这种情况发生时，JVM 会将包含这个对象的区域（Card）标记为 Dirty，这也就是 Card Marking。如下图所示： 在pre-clean阶段，那些能够从 Dirty 对象到达的对象也会被标记，这个标记做完之后，dirty card 标记就会被清除了，如下：

4.并发可终止预清理

这也是一个并发阶段，但是同样不会影响影响用户的应用线程，这个阶段是为了尽量承担 STW（stop-the-world）中最终标记阶段的工作。这个阶段持续时间依赖于很多的因素，由于这个阶段是在重复做很多相同的工作，直接满足一些条件（比如：重复迭代的次数、完成的工作量或者时钟时间等）

5.重新标记

这是第二个 STW 阶段，也是 CMS 中的最后一个，这个阶段的目标是标记所有老年代所有的存活对象，由于之前的阶段是并发执行的，gc 线程可能跟不上应用程序的变化，为了完成标记老年代所有存活对象的目标，STW 就非常有必要了。 通常 CMS 的 Final Remark 阶段会在年轻代尽可能干净的时候运行，目的是为了减少连续 STW 发生的可能性（年轻代存活对象过多的话，也会导致老年代涉及的存活对象会很多）。这个阶段会比前面的几个阶段更复杂一些

6.并发标记

这里不需要 STW，它是与用户的应用程序并发运行，这个阶段是：清除那些不再使用的对象，回收它们的占用空间为将来使用。如下图所示：

7.并发重置

这个阶段也是并发执行的，它会重设 CMS 内部的数据结构，为下次的 GC 做准备

本文由博客群发一文多发等运营工具平台 OpenWrite 发布