内存与垃圾回收——（十二）GC 日志分析

12_GC 日志分析

12.1_GC 常用参数

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

• -XX:+PrintGC 输出 GC 日志 （-Xlog: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.05 sys=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.00 sys=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 ]    

说明：带上了日期和时间

12.2_日志补充说明

• “[ GC"和”[ Full GC"说明了这次垃圾收集的停顿类型，如果有"Full"则说明 GC 发生了"StopThe World"

• 使用 Serial 收集器在新生代的名字是 Default 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

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

/**
 * 在jdk7 和 jdk8中分别执行
 * -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();
    }
}

JDK 7

新生代有 8 MB 的内存空间，当在存放了 3 个 2 MB后，只剩余 2 MB 空间。空间不足触发 YGC，from 区无法容纳存活的对象，直接晋升至老年代。

老年代存放了晋升过来的 3 个 2 MB，而新生代 YGC 后又拥有了 8 MB 空闲内存，可以存放 4 MB

JDK 8

jdk8 中，新生代无法存放的 4 MB 大对象直接存放至了老年代。

12.4_日志分析工具

将 GC 日志存到文件：

-Xloggc:/path/to/gc.log

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