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： +PrintGCDetaiis

输出信息如下：

[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 ]     

说明：带上了日期和时间

日志补充说明

• "[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说明

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

示例代码：

/**
 * 在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();
    }
}

 

 

日志分析工具

可以用一些工具去分析这些gc日志。
常用的日志分析.工具有： GCViewer、GCEasy、GCHisto、GCLogViewer 、Hpjmeter、garbagecat等