24、JVM实战：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日志文件的输出路径

+PrintGC

打开GC日志：一verbose：gc
这个只会显示总的GC堆的变化，如下：

[GC （Allocation Failure） 80832K一>19298K（227840K），0.0084018 secs]
[GC （Metadata GC Threshold） 109499K一>21465K （228352K），0.0184066 secs]
[Full GC （Metadata GC Threshold） 21 465K一>16716K （201728K），0.0619261 secs ]

参数解析：

GC、Full GC： GC的类型，GC只在新生代上进行，Full GC包括永生代，新生代，老年代。
Allocation Failure： GC发生的原因。
80832K一> 19298K：堆在GC前的大小和GC后的大小。
228840k：现在的堆大小。
0.0084018 secs： GC持续的时间。

PrintGCDetails

-打开GC日志：-verbose:gc -XX:+PrintGCDetails

输出信息如下：

[GC （Allocation Failure） [ PSYoungGen： 70640K一> 10116K（141312K） ] 80541K一>20017K （227328K），0.0172573 secs] [Times： user=0.03 sys=0.00， real=0.02 secs ]
[GC （Metadata GC Threshold） [PSYoungGen：98859K一>8154K（142336K） ] 108760K一>21261K （228352K），
0.0151573 secs] [Times： user=0.00 sys=0.01， real=0.02 secs]
[Full GC （Metadata GC Threshold） [PSYoungGen： 8154K一>0K（142336K） ] [ParOldGen： 13107K一>16809K（62464K） ] 21261K一>16809K （204800K），[Metaspace： 20599K一>20599K （1067008K） ]，0.0639732 secs]
[Times： user=0.14 sys=0.00， real=0.06 secs]

参数解析：

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从开始到结束的时间，包括其他进程占用时间片的实际时间。

PrintGCTimeStamps

打开GC日志： -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps

输出信息如下：

2019一09一24T22：15：24.518+0800：3.287： [GC（Allocation Failure） [ PSYoungGen： 1361 62K一>5113K（136192K） ] 141425K一>17632K （222208K） ，0.0248249 secs] [Times： user=0.05sys=0.00， real=0.03 secs ]
2019一09一24T22：15：25.559+0800：4.329： [ GC（Metadata GC Threshold）[PSYoungGen：97578K一>10068K（274944K） ] 110096K一>22658K （360960K），0.0094071 secs]
[Times： user=0. 00sys=0.00， real=0. 01 secs]
2019一09一24T22：15：25.569+0800：4.338： [Full GC （Metadata GC Threshold）[ PSYoungGen：10068K一>0K（274944K） ] [ ParoldGen： 12590K一>13564K （56320K） ] 22658K一>13564K （331264K） ，
[Metaspace： 20590K一>20590K（1067008K）]， 0. 0494875 secs]
[Times： user=0.17 sys=0. 02，real=0.05 secs ]

说明：带上了日期和时间

197

日志补充说明

“[GC"和”[Full GC"说明了这次垃圾收集的停顿类型，如果有"Full"则说明GC发生了"StopThe World"
使用Serial收集器在新生代的名字是De fault New Generation，因此显示的是" [DefNew"
使用ParNew收集器在新生代的名字会变成" 【ParNew"，意思是"Parallel New Generation"
使用Parallel Scavenge收集器在新生代的名字是" 【PSYoungGen"
老年代的收集和新生代道理一样，名字也是收集器决定的
使用G1收集器的话，会显示为"garbage一 first heap"
Allocation Failure 表明本次引起GC的原因是因为在年轻代中没有足够的空间能够存储新的数据了。
[PSYoungGen： 5986K一>696K（8704K）] 5986K一> 704K （9216K）中括号内： GC回收前年轻代大小，回收后大小，（年轻代总大小）括号外： GC回收前年轻代和老年代大小，回收后大小，（年轻代和老年代总大小）
user代表用户态回收耗时，sys 内核态回收耗时， rea实际耗时。由于多核的原因，时间总和可能会超过real时间

堆空间占用情况说明

Minor GC说明

Full GC说明

198

举例解读日志中堆空间数据

示例代码：

/**
 * 在jdk7 和 jdk8中分别执行
 * -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC
 */
public class GCLogTest1 {
   
     
    private static final int _1MB = 1024 * 1024;

    public static void testAllocation() {
   
     
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2 * _1MB];
        allocation2 = new byte[2 * _1MB];
        allocation3 = new byte[2 * _1MB];
        allocation4 = new byte[4 * _1MB];
    }

    public static void main(String[] agrs) {
   
     
        testAllocation();
    }
}

在JDK7中，对象数据的位置变化如下：

eden区由于有8m的空间，在创建前三个2m的对象时，会放在这个区域
当第四个4m的对象要进行创建时，eden区存放的空间不够，于是新生代进行垃圾回收，将前面三个2m的对象尝试移动到from区，但空间依旧不够，于是放到老年代中，如图二。
最终的结果如图二，4m对象放到eden区，三个2m对象被放到老年代中