深入理解JVM（十八）GC日志分析

通过阅读GC日志，我们可以了解Java虛拟机内存分配与回收策略。

内存分配与垃圾回收的参数列表

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

/*
 * JVM参数：-Xms60m -Xmx60m
 */
public class GCLogTest {
    public static void main(String[] args) {
        ArrayList<byte[]> list = new ArrayList<>();
        for (int i = 0; i < 500; i++){
           byte[] arr = new byte[1024 * 100];
           list.add(arr);
        }
    }
}

打开GC日志：

-verbose:gc

这个只会显示总的GC堆的变化， 如下：

[GC (Allocation Failure)  15267K->13850K(58880K), 0.0030993 secs]
[GC (Allocation Failure)  29150K->29068K(58880K), 0.0042701 secs]
[Full GC (Ergonomics)  29068K->28870K(58880K), 0.0072675 secs]
[Full GC (Ergonomics)  44230K->44173K(58880K), 0.0083393 secs]

参数解析：

GC、Full GC： GC的类型，GC只在新生代上进行，Full GC包括永久代，新生代， 老年代。
Allocation Failure： GC发生的原因。
15267K->13850K：堆在GC前的大小和GC后的大小。
58880K：现在的堆大小。
0.0030993 secs： GC持续的时间。

但是如果想查看更详细的信息， 比如新生代在GC前后的变化或者老年代在GC前后的变化等， 
就需要使用这个参数：

 -XX:+PrintGCDetaiis

输出信息如下： 

[GC (Allocation Failure) [PSYoungGen: 15267K->2548K(17920K)] 15267K->13850K(58880K), 0.0028485 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 17848K->2556K(17920K)] 29150K->29068K(58880K), 0.0036911 secs] [Times: user=0.05 sys=0.08, real=0.00 secs] 
[Full GC (Ergonomics) [PSYoungGen: 2556K->0K(17920K)] [ParOldGen: 26512K->28870K(40960K)] 29068K->28870K(58880K), [Metaspace: 3491K->3491K(1056768K)], 0.0066634 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Ergonomics) [PSYoungGen: 15360K->3000K(17920K)] [ParOldGen: 28870K->40872K(40960K)] 44230K->43872K(58880K), [Metaspace: 3491K->3491K(1056768K)], 0.0056879 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 17920K, used 10054K [0x00000000fec00000, 0x0000000100000000, 0x0000000100000000)
  eden space 15360K, 65% used [0x00000000fec00000,0x00000000ff5d1938,0x00000000ffb00000)
  from space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000)
  to   space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000)
 ParOldGen       total 40960K, used 40872K [0x00000000fc400000, 0x00000000fec00000, 0x00000000fec00000)
  object space 40960K, 99% used [0x00000000fc400000,0x00000000febea1a0,0x00000000fec00000)
 Metaspace       used 3498K, capacity 4498K, committed 4864K, reserved 1056768K
  class space    used 387K, capacity 390K, committed 512K, reserved 1048576K

参数解析：

GC，Full FC：同样是GC的类型
Allocation Failure： GC原因
PSYoungGen：使用了Parallel Scavenge并行垃圾收集器的新生代GC前后大小的变化
ParOldGen：使用了Parallel Old并行垃圾收集器的老年代Gc前后大小的变化
Metaspace： 元数据区GC前后大小的变化，JDK1.8中引入了元数据区以替代永久代
xxx secs ： 指Gc花费的时间
Times： user： 指的是垃圾收集器花费的所有CPU时间，
sys： 花费在等待系统调用或系统事件的时间， 
real ：GC从开始到结束的时间，包括其他进程占用时间片的实际时间。 

加上GC时间：

-XX:+PrintGCTimeStamps

0.101: [GC (Allocation Failure) [PSYoungGen: 15267K->2552K(17920K)] 15267K->13802K(58880K), 0.0029209 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.106: [GC (Allocation Failure) [PSYoungGen: 17852K->2460K(17920K)] 29102K->29012K(58880K), 0.0035817 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.109: [Full GC (Ergonomics) [PSYoungGen: 2460K->0K(17920K)] [ParOldGen: 26552K->28870K(40960K)] 29012K->28870K(58880K), [Metaspace: 3491K->3491K(1056768K)], 0.0073870 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
0.118: [Full GC (Ergonomics) [PSYoungGen: 15360K->3000K(17920K)] [ParOldGen: 28870K->40872K(40960K)] 44230K->43872K(58880K), [Metaspace: 3491K->3491K(1056768K)], 0.0042181 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

-XX:+PrintGCDateStamps

2022-09-08T11:37:30.424+0800: [GC (Allocation Failure) [PSYoungGen: 15267K->2552K(17920K)] 15267K->13810K(58880K), 0.0027859 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-09-08T11:37:30.428+0800: [GC (Allocation Failure) [PSYoungGen: 17852K->2552K(17920K)] 29110K->29020K(58880K), 0.0034724 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-09-08T11:37:30.431+0800: [Full GC (Ergonomics) [PSYoungGen: 2552K->0K(17920K)] [ParOldGen: 26468K->28870K(40960K)] 29020K->28870K(58880K), [Metaspace: 3491K->3491K(1056768K)], 0.0072200 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2022-09-08T11:37:30.440+0800: [Full GC (Ergonomics) [PSYoungGen: 15360K->3000K(17920K)] [ParOldGen: 28870K->40872K(40960K)] 44230K->43872K(58880K), [Metaspace: 3491K->3491K(1056768K)], 0.0050960 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

如果想把GC日志存到文件的话， 是下面这个参数：

-Xloggc:gc.log

生成的文件在项目路径下

可以用一些工具去分析这些gc日志。

常用的日志分析工具有： GCViewer、GCEasy、GCHisto、GCLogViewer 、Hpjmeter、 garbagecat等。