GC日志分析

这几天在做JVM调优，顺手总结一下gc日志的东西。

本次分析的gc日志是Jboss下的gc日志.

部分截图：

//这一行说的是JVM是OpenJDK，以及其他信息
OpenJDK 64-Bit Server VM (25.265-b01) for linux-amd64 JRE (1.8.0_265-b01), built on Jul 28 2020 13:27:15 by "mockbuild" with gcc 4.4.7 20120313 (Red Hat 4.4.7-23)
//内存对齐4K，物理内存，交换内存
Memory: 4k page, physical 32779948k(26626888k free), swap 16777212k(16777212k free)
//JVM启动参数
CommandLine flags: -XX:CompressedClassSpaceSize=528482304 -XX:GCLogFileSize=3145728 -XX:InitialHeapSize=1366294528 -XX:MaxHeapSize=2414870528 -XX:MaxMetaspaceSize=536870912 -XX:MaxNewSize=524288000 -XX:MetaspaceSize=536870912 -XX:NewSize=524288000 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:-TraceClassUnloading -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:+UseParallelGC
2021-07-14T10:42:23.462+0800: 1.799: [GC (Allocation Failure) [PSYoungGen: 384000K->20087K(448000K)] 384000K->20103K(1271296K), 0.0220683 secs] [Times: user=0.05 sys=0.01, real=0.02 secs]
2021-07-14T10:42:25.304+0800: 3.640: [GC (Allocation Failure) [PSYoungGen: 404087K->55290K(448000K)] 404103K->55322K(1271296K), 0.0377894 secs] [Times: user=0.11 sys=0.01, real=0.04 secs]
2021-07-14T10:42:26.547+0800: 4.884: [GC (Allocation Failure) [PSYoungGen: 439290K->63969K(448000K)] 439322K->92450K(1271296K), 0.0577366 secs] [Times: user=0.25 sys=0.04, real=0.05 secs]
2021-07-14T10:42:28.723+0800: 7.059: [GC (Allocation Failure) [PSYoungGen: 447969K->63992K(448000K)] 476450K->141165K(1271296K), 0.0569773 secs] [Times: user=0.21 sys=0.02, real=0.06 secs]
2021-07-14T10:42:31.189+0800: 9.526: [GC (Allocation Failure) [PSYoungGen: 447992K->63983K(448000K)] 525165K->316222K(1271296K), 0.1188205 secs] [Times: user=0.27 sys=0.02, real=0.12 secs]
2021-07-14T10:42:43.725+0800: 22.062: [GC (Allocation Failure) [PSYoungGen: 447983K->63974K(235008K)] 700222K->411549K(1058304K), 0.0787492 secs] [Times: user=0.24 sys=0.02, real=0.08 secs]

看看每次gc的日志含义：

2021-07-14T10:42:23.462+0800: 1.799: [GC (Allocation Failure) [PSYoungGen: 384000K->20087K(448000K)] 384000K->20103K(1271296K), 0.0220683 secs] [Times: user=0.05 sys=0.01, real=0.02 secs]

[GC (Allocation Failure)
发生GC的原因

[PSYoungGen: 384000K->20087K(448000K)] 
PS: Parallel Scavenge 并行扫描
YoungGen：年轻代
384000K->20087K(448000K)：gc前的Eden区大小->gc后eden区的大小(Eden区的总大小)

384000K->20103K(1271296K)：gc前堆空间大小->gc后的堆空间大小（堆空间的总大小）
0.0220683 secs：gc花费的时间

[Times: user=0.05 sys=0.01, real=0.02 secs]
时间：用户时间， 系统时间， 实际gc时间

注意到日志中时间分为了三块：user， sys，和 real，三者的区别和含义如下：

　　real：指的是在此次GC事件中所花费的总时间；
　　user：指的是CPU工作在用户态所花费的时间；
　　sys：指的是CPU工作在内核态所花费的时间。

　　user + sys 就是CPU花费的实际时间，注意这个值统计了所有CPU上的时间，如果进程工作在多线程的环境下，这个值是会超出 real 所记录的值的，即 user + sys >= real

　　对于GC事件来说，无论是 Minor GC 还是 Full GC 的过程，都存在并发的GC算法，如新生代的ParNew，老年代的ParallelOld，GC过程中工作负载是由多个线程共同完成的，这也就意味着使用这些GC算法时，GC日志中我们应该观察到：user + sys > real。
譬如说：配置了ParNew且并发数为5的GC活动（-XX:+UseParNewGC -XX:ParallelGCThreads=5）中，如果user + sys的值为 2 seconds，那么 real 的时间 就近似为 400ms(2 seconds / 5)。

正常情况下 user+sys > real

如果real 所显示的时间 远 大于 user + sys。一般来说，如果观察到GC日志里多次出现了real时间过大，这表明JVM的GC 过程存在某些问题（等待计算资源），原因可能是下面这两种：

• 频繁的IO操作
• 缺乏CPU资源

繁忙的I/O操作

　　当程序存在繁忙的I/O操作（网络IO或磁盘IO）时，会让 real 时间大幅上升。因为在记录GC日志的时候，你的程序进行了磁盘读写，如果同一时间其他IO操作较重，则此时GC事件会延迟，进而影响了最终的 real 的值。注意，如果程序本身不存在的频繁的IO操作，同一机器上其他进程的频繁IO也会影响 real 的最终结果。Linux环境下可以使用 sar 监视机器上的I/O，eg. sar -d -p 1，如果频繁的IO操作的确存在，可以通过下面两种方式改进：

• 优化程序本身的IO操作逻辑；
• 消除其他进程带来的IO影响。

缺乏CPU资源

　　当程序本身是CPU密集型应用，或机器上其他进程占用了大量的CPU计算资源，则有可能会出现分配不到 CPU cycles的情况，这会让程序挂起，GC所花费的实际时间也将远大于 user + sys 的值。

　　可以使用 top 命令观察一下 进程的CPU利用率，同时辅以Profiler工具统计一段时间内进程的状态分布。如果的确是CPU资源不足，解决方法无法下面几种：

• 优化程序内部的线程使用，确保无冗余的线程配置；
• 增加虚拟机或容器的CPU配置，提升机器总的计算能力。