GC 日志打印实践

1.1 -XX:+PrintGC与-verbose:gc

如果只设置-XX:+PrintGC那么打印的日志如下所示：

[GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

1、GC类型，GC:minor GC(young gc),Full GC：major GC

2、Allocation Failure 表示是失败的类型

3、68896K->5080K 表示年轻代从68896K降为5080K

4、256000K表示整个堆的大小

5、0.0041139 secs表示这次GC总计所用的时间

在JDK 8中，-verbose:gc是-XX:+PrintGC一个别称，日志格式等价与：-XX:+PrintGC，。

1.2 -XX:+PrintGCDetails

打印GC前/后堆内存大小 

[GC (Allocation Failure) [PSYoungGen: 53248K->2176K(59392K)] 58161K->7161K(256000K), 0.0039189 secs] [Times: user=0.02 sys=0.01, real=0.00 secs]

1、GC 表示是一次YGC（Young GC）

2、Allocation Failure 表示是失败的类型

3、PSYoungGen 表示年轻代大小

4、53248K->2176K 表示年轻代占用从53248K降为2176K

5、59392K表示年轻带的大小

6、58161K->7161K 表示整个堆占用从53248K降为2176K

7、256000K表示整个堆的大小

8、 0.0039189 secs 表示这次GC总计所用的时间

9、[Times: user=0.02 sys=0.01, real=0.00 secs] 分别表示，用户态占用时长，内核用时，真实用时。

1.3 -XX:+PrintHeapAtGC

 打印GC前后的各个区域（Eden，from、to、Old、Metaspace等区域）的容量、使用量、使用占比等

{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 57344K, used 49152K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
  eden space 49152K, 100% used [0x00000000fc000000,0x00000000ff000000,0x00000000ff000000)
  from space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
  to   space 8192K, 0% used [0x00000000ff000000,0x00000000ff000000,0x00000000ff800000)
 ParOldGen       total 196608K, used 0K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
  object space 196608K, 0% used [0x00000000f0000000,0x00000000f0000000,0x00000000fc000000)
 Metaspace       used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
  class space    used 888K, capacity 986K, committed 1024K, reserved 1048576K
[GC (Allocation Failure)  49152K->2416K(253952K), 0.0030218 secs]
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 57344K, used 2400K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
  eden space 49152K, 0% used [0x00000000fc000000,0x00000000fc000000,0x00000000ff000000)
  from space 8192K, 29% used [0x00000000ff000000,0x00000000ff258020,0x00000000ff800000)
  to   space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
 ParOldGen       total 196608K, used 16K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
  object space 196608K, 0% used [0x00000000f0000000,0x00000000f0004000,0x00000000fc000000)
 Metaspace       used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
  class space    used 888K, capacity 986K, committed 1024K, reserved 1048576K
}

由此可以看出在，打印如下日志前后

[GC (Allocation Failure)  49152K->2416K(253952K), 0.0030218 secs]

1.4 -XX:+PrintGCDateStamps

2019-03-05T16:56:15.108+0800: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

 表示打印GC的时刻的时间是2019-03-05T16:56:15.108+0800。+0800表示是东8区。

1.5 -XX:+PrintGCTimeStamps

1.963: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

表示从JVM启动到打印GC时刻用了1.963秒。

1.6 -XX:+PrintGCApplicationStoppedTime

Total time for which application threads were stopp 2.81 seconds，Stopping threads took ：2.6 seconds

第一个 2.81 seconds 是JVM启动后的秒数，第二个 2.6 seconds 是 JVM发起STW的开始到结束的时间

1.7 -XX:+PrintSafepointStatistics 打印安全点统计信息

      -XX:PrintSafepointStatisticsCount=n 打印安全点统计信息的次数 

        vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.371: ParallelGCFailedAllocation       [      10          0              0    ]      [     0     0     0     0     7    ]  0   
Execute full gc...dataList has been promoted to cms old space
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.379: ParallelGCSystemGC               [      10          0              0    ]      [     0     0     0     0    16    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.396: no vm operation                  [       9          1              1    ]      [     0     0     0     0   341    ]  0   

• vmop：引发STW的原因，以及触发时间，本例中是GC。该项常见的输出有：<u>RevokeBias、BulkRevokeBias、Deoptimize、G1IncCollectionPause</u>。数字306936.812是虚拟机启动后运行的秒数。GC log可以根据该项内容定位Total time for which application threads…引发的详细信息。
• total ：STW发生时，JVM存在的线程数目。
• initially_running ：STW发生时，仍在运行的线程数，这项是Spin阶段的 时间来源
• wait_to_block ： STW需要阻塞的线程数目，这项是block阶段的时间来源
• sync = spin + block + 其他。 

safepoint的执行分为四个阶段：

1. Spin阶段。因为jvm在决定进入全局safepoint的时候，有的线程在安全点上，而有的线程不在安全点上，这个阶段是等待未在安全点上的用户线程进入安全点。
2. Block阶段。即使进入safepoint，用户线程这时候仍然是running状态，保证用户不在继续执行，需要将用户线程阻塞。
3. Cleanup。这个阶段是JVM做的一些内部的清理工作。
4. VM Operation. JVM 执行的一些全局性工作，例如 GC, 代码反优化。

1.8 -XX:+PrintTenuringDistribution 

Desired survivor size 107347968 bytes, new threshold 11 (max 15)
- age   1:    4345400 bytes,    4345400 total
- age   2:    2436856 bytes,    6782256 total
- age   3:     676112 bytes,    7458368 total
- age   4:    2323952 bytes,    9782320 total
- age   5:     599616 bytes,   10381936 total
- age   6:     563656 bytes,   10945592 total
- age   7:     567656 bytes,   11513248 total
- age   8:     815480 bytes,   12328728 total
- age   9:     527672 bytes,   12856400 total
- age  10:    3956032 bytes,   16812432 total
- age  11:   16575184 bytes,   33387616 total

 新生代对象晋升到老年代经过几次GC，而最大允许的年龄阈值为几

1.9 -XX:+PrintReferenceGC 强引用/弱引用/软引用/虚引用/finalize 方法 

2021-02-19T12:41:30.462+0800: 5072726.605: [SoftReference, 0 refs, 0.0000521 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [WeakReference, 0 refs, 0.0000069 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [FinalReference, 0 refs, 0.0000056 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [PhantomReference, 0 refs, 0 refs, 0.0000059 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [JNI Weak Reference, 0.0000131 secs], 0.4635293 secs]

2.0

• -Xloggc:/path/to/gc-%t.log # GC日志输出的文件路径

• -XX:+UseGCLogFileRotation # 开启日志文件分割

• -XX:NumberOfGCLogFiles=14 # 最多分割几个文件，超过之后从头开始写

• -XX:GCLogFileSize=100M # 每个文件上限大小，超过就触发分割

注：日志打印全部包含上面所有的命令，生成文件通过分析工具分析 

最终得到的日志文件名会像这个样子：

gc-2021-03-29_20-41-47.log.0
gc-2021-03-29_20-41-47.log.1
gc-2021-03-29_20-41-47.log.2
gc-2021-03-29_20-41-47.log.3