JVM下篇：性能监控与调优篇 - 第05章：分析GC日志 - 《Java 编程》

一、GC日志参数
二、GC分类
三、GC日志格式
四、GC日志分析工具

一、GC日志参数

-verbose:gc：输出gc日志信息，默认输出到标准输出
-XX:+PrintGC：输出GC日志。类似：-verbose:gc
-XX:+PrintGCDetails：在发生垃圾回收时打印内存回收相处的日志，并在进程退出时输出当前内存各区域分配情况
-XX:+PrintGCTimeStamps：输出GC发生时的时间戳
-XX:+PrintGCDateStamps：输出GC发生时的时间戳（以日期的形式，例如：2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC：每一次GC前和GC后，都打印堆信息
-Xloggc:：表示把GC日志写入到一个文件中去，而不是打印到标准输出中

二、GC分类
针对HotSpot VM的实现，它里面的GC按照回收区域又分为两大种类型：一种是部分收集（Partial GC），一种是整堆收集（Full GC）
部分收集（Partial GC）：不是完整收集整个Java堆的垃圾收集。其中又分为：
1. 新生代收集（Minor GC / Young GC）：只是新生代（Eden / S0, S1）的垃圾收集
2. 老年代收集（Major GC / Old GC）：只是老年代的垃圾收集
  1. 目前，只有CMS GC会有单独收集老年代的行为。
  2. 注意，很多时候Major GC会和Full GC混淆使用，需要具体分辨是老年代回收还是整堆回收。
混合收集（Mixed GC）：收集整个新生代以及部分老年代的垃圾收集。目前，只有G1 GC会有这种行为
整堆收集（Full GC）：收集整个java堆和方法区的垃圾收集。
新生代收集：当Eden区满的时候就会进行新生代收集，所以新生代收集和S0区域和S1区域无关
老年代收集和新生代收集的关系：进行老年代收集之前会先进行一次年轻代的垃圾收集，
1. 原因如下：一个比较大的对象无法放入新生代，那它自然会往老年代去放，如果老年代也放不下，那会先进行一次新生代的垃圾收集，之后尝试往新生代放，如果还是放不下，才会进行老年代的垃圾收集，之后在往老年代去放，这是一个过程，我来说明一下为什么需要往老年代放，但是放不下，而进行新生代垃圾收集的原因，这是因为新生代垃圾收集比老年代垃圾收集更加简单，这样做可以节省性能
进行垃圾收集的时候，堆包含新生代、老年代、元空间/永久代：可以看出Heap后面包含着新生代、老年代、元空间，但是我们设置堆空间大小的时候设置的只是新生代、老年代而已，元空间是分开设置的

哪些情况会触发Full GC：
1. 老年代空间不足
2. 方法区空间不足
3. 显式调用System.gc()
4. Minior GC进入老年代的数据的平均大小大于老年代的可用内存
5. 大对象直接进入老年代，而老年代的可用空间不足
  三、GC日志格式
  1、不同GC分类的GC细节
```java /**
- -XX:+PrintCommandLineFlags *
- -XX:+UseSerialGC:表明新生代使用Serial GC ，同时老年代使用Serial Old GC *
- -XX:+UseParNewGC：标明新生代使用ParNew GC *
- -XX:+UseParallelGC:表明新生代使用Parallel GC
- -XX:+UseParallelOldGC : 表明老年代使用 Parallel Old GC
- 说明：二者可以相互激活 *
- -XX:+UseConcMarkSweepGC：表明老年代使用CMS GC。同时，年轻代会触发对ParNew 的使用 */ public class GCUseTest { public static void main(String[] args) { ArrayList list = new ArrayList<>();
  
  while(true){
```
  byte[] arr = new byte[1024 * 10];//10kb
  list.add(arr);
```
  // try { // Thread.sleep(5); // } catch (InterruptedException e) { // e.printStackTrace(); // } } } } ``` 1、老年代使用CMS GC
  老年代使用CMS GC，整体是并发垃圾收集，主打低延迟
  
  2、新生代使用Serial GC
  GC设置方法：参数中使用-XX:+UseSerialGC，说明新生代使用Serial GC，同时老年代也会触发对Serial Old GC的使用，因此添加该参数之后，新生代使用Serial GC，而老年代使用Serial Old GC，整体是串行垃圾收集
  
  DefNew代表新生代使用Serial GC，然后Tenured代表老年代使用Serial Old GC
  
  2、GC日志分类
  MinorGC
  MinorGC（或young GC或YGC）日志：

FullGC

3、GC日志结构剖析

3.1 透过日志看垃圾收集器

Serial收集器：新生代显示 “[DefNew”，即 Default New Generation
ParNew收集器：新生代显示 “[ParNew”，即 Parallel New Generation
Parallel Scavenge收集器：新生代显示”[PSYoungGen”，JDK1.7使用的即PSYoungGen
Parallel Old收集器：老年代显示”[ParoldGen”
G1收集器：显示”garbage-first heap“

透过日志看GC原因

Allocation Failure：表明本次引起GC的原因是因为新生代中没有足够的区域存放需要分配的数据
Metadata GCThreshold：Metaspace区不够用了
FErgonomics：JVM自适应调整导致的GC
System：调用了System.gc()方法

3.2 透过日志看GC前后情况
通过图示，我们可以发现GC日志格式的规律一般都是：GC前内存占用 —-＞ GC后内存占用（该区域内存总大小）
```
[PSYoungGen: 5986K->696K (8704K) ] 5986K->704K (9216K)
```
中括号内：GC回收前年轻代堆大小，回收后大小（年轻代堆总大小）
括号外：GC回收前年轻代和老年代大小，回收后大小（年轻代和老年代总大小）

注意：Minor GC堆内存总容量 = 9/10 年轻代 + 老年代。原因是Survivor区只计算from部分，而JVM默认年轻代中Eden区和Survivor区的比例关系，Eden:S0:S1=8:1:1。

3.3 透过日志看GC时间

GC日志中有三个时间：user，sys和real

user：进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的实际CPU 时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示GC线程执行所使用的 CPU 总时间。
sys：进程在内核态消耗的 CPU 时间，即在内核执行系统调用或等待系统事件所使用的CPU 时间
real：程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成）。对于并行gc，这个数字应该接近（用户时间＋系统时间）除以垃圾收集器使用的线程数。

由于多核的原因，一般的GC事件中，real time是小于sys time＋user time的，因为一般是多个线程并发的去做GC，所以real time是要小于sys＋user time的。如果real＞sys＋user的话，则你的应用可能存在下列问题：IO负载非常重或CPU不够用。

4、Minor GC 日志解析

2020-11-20T17:19:43.265-0800
1. 添加-XX:+PrintGCDateStamps参数
2. 日志打印时间，日期格式：如2013-05-04T21:53:59.234+0800
0.822:
1. 添加-XX:+PrintGCTimeStamps该参数
2. gc发生时，Java虚拟机启动以来经过的秒数
[GC(Allocation Failure)
1. 发生了一次垃圾回收，这是一次Minior GC。
2. 它不区分新生代还是老年代GC，括号里的内容是gc发生的原因，这里的Allocation Failure的原因是新生代中没有足够区域能够存放需要分配的数据而失败
[PSYoungGen:76800K->8433K(89600K)
1. PSYoungGen：表示GC发生的区域，区域名称与使用的GC收集器是密切相关的
  1. Serial收集器：Default New Generation 显示Defnew
  2. ParNew收集器：ParNew
  3. Parallel Scanvenge收集器：PSYoung
  4. 老年代和新生代同理，也是和收集器名称相关
2. 76800K->8433K(89600K)：GC前该内存区域已使用容量->GC后盖区域容量(该区域总容量)
  1. 如果是新生代，总容量则会显示整个新生代内存的9/10，即eden+from/to区
  2. 如果是老年代，总容量则是全身内存大小，无变化
76800K->8449K(294400K)
1. 虽然本次是Minor GC，只会进行新生代的垃圾收集，但是也肯定会打印堆中总容量相关信息
2. 在显示完区域容量GC的情况之后，会接着显示整个堆内存区域的GC情况：GC前堆内存已使用容量->GC后堆内存容量（堆内存总容量），并且堆内存总容量 = 9/10 新生代 + 老年代，然后堆内存总容量肯定小于初始化的内存大小
,0.0088371：整个GC所花费的时间，单位是秒
[Times：user=0.02 sys=0.01,real=0.01 secs]
1. user：指CPU工作在用户态所花费的时间
2. sys：指CPU工作在内核态所花费的时间
3. real：指在此次事件中所花费的总时间
  5、Full GC 日志解析
2020-11-20T17:19:43.794-0800
1. 添加-XX:+PrintGCDateStamps参数
2. 日志打印时间日期格式如2013-05-04T21:53:59.234+0800
1.351
1. 添加-XX:+PrintGCTimeStamps该参数
2. gc发生时，Java虚拟机启动以来经过的秒数
Full GC(Metadata GCThreshold)
1. 括号中是gc发生的原因，原因：Metaspace区不够用了。除此之外，还有另外两种情况会引起Full GC，如下：
  1. Full GC(FErgonomics)：原因：JVM自适应调整导致的GC
  2. Full GC（System）：原因：调用了System.gc()方法
[PSYoungGen: 100082K->0K(89600K)]
1. PSYoungGen：表示GC发生的区域，区域名称与使用的GC收集器是密切相关的
  1. Serial收集器：Default New Generation 显示DefNew
  2. ParNew收集器：ParNew
  3. Parallel Scanvenge收集器：PSYoungGen
  4. 老年代和新生代同理，也是和收集器名称相关
2. 10082K->0K(89600K)：GC前该内存区域已使用容量->GC该区域容量(该区域总容量)
  1. 如果是新生代，总容量会显示整个新生代内存的9/10，即eden+from/to区
  2. 如果是老年代，总容量则是全部内存大小，无变化
ParOldGen：32K->9638K(204800K)：老年代区域没有发生GC，因此本次GC是metaspace引起的
10114K->9638K(294400K),
1. 在显示完区域容量GC的情况之后，会接着显示整个堆内存区域的GC情况：GC前堆内存已使用容量->GC后堆内存容量（堆内存总容量），并且堆内存总容量 = 9/10 新生代 + 老年代，然后堆内存总容量肯定小于初始化的内存大小
[Meatspace:20158K->20156K(1067008K)],
1. metaspace GC 回收2K空间
  四、GC日志分析工具
  
  GCEasy
  GCEasy是一款在线的GC日志分析器，可以通过GC日志分析进行内存泄露检测、GC暂停原因分析、JVM配置建议优化等功能，大多数功能是免费的。
  官网地址：https://gceasy.io/

GCViewer
GCViewer是一款离线的GC日志分析器，用于可视化Java VM选项 -verbose:gc 和 .NET生成的数据 -Xloggc:。还可以计算与垃圾回收相关的性能指标（吞吐量、累积的暂停、最长的暂停等）。当通过更改世代大小或设置初始堆大小来调整特定应用程序的垃圾回收时，此功能非常有用。
源码下载：https://github.com/chewiebug/GCViewer
运行版本下载：https://github.com/chewiebug/GCViewer/wiki/Changelog

GChisto

官网上没有下载的地方，需要自己从SVN上拉下来编译
不过这个工具似乎没怎么维护了，存在不少bug

HPjmeter

工具很强大，但是只能打开由以下参数生成的GC log，-verbose:gc -Xloggc:gc.log。添加其他参数生成的gc.log无法打开
HPjmeter集成了以前的HPjtune功能，可以分析在HP机器上产生的垃圾回收日志文件

第05章：分析GC日志

一、GC日志参数

二、GC分类

三、GC日志格式

1、不同GC分类的GC细节

2、GC日志分类

3、GC日志结构剖析

3.1 透过日志看垃圾收集器

3.2 透过日志看GC前后情况

3.3 透过日志看GC时间

4、Minor GC 日志解析

5、Full GC 日志解析

四、GC日志分析工具