“这是我参与更文挑战的第8天，活动详情查看： 更文挑战”
上篇介绍了JVM运行时参数，接下来介绍Java GC日志。
一、GC日志参数
-verbose:gc
输出gc日志信息，默认输出到标准输出
-XX:+PrintGC
等同于-verbose:gc表示打开简化的GC日志
-XX:+PrintGCDetails
在发生垃圾回收时打印内存回收详细的日志，并在进程退出时输出当前内存各区域分配情况
-XX:+PrintGCTimeStamps
输出GC发生时的时间戳
-XX:+PrintGCDateStamps
输出GC发生时的时间戳（以日期的形式，如2021-06-15T14:23:59.234+0800）
-XX:+PrintHeapAtGC
每一次GC前和GC后，都打印堆信息
-Xloggc:<file>
把GC日志写入到一个文件中去，而不是打印到标准输出中
二、GC日志格式
GC分类
针对HotSpot VM的实现，它里面的GC按照回收区域又分为两大种类类型：一种是部分收集（Parial GC），一种是整堆收集（Full GC）。
部分收集：不是完整收集整个Java堆的垃圾收集。其中又分为：
- 新生代收集（Minor GC / Young GC）:只是新生代（Eden\S0,S1）的垃圾收集
- 老年代收集（Major GC / Old GC）:只是老年代的垃圾收集。
- 目前，只有CMS GC会单独收集老年代的行为。
- 注意，很多时候Major GC会和Full GC混淆使用，需要具体分辨是老年代回收还是整堆回收。
- 混合收集（Mixed GC）：收集整个新生代以及部分老年代的垃圾收集。
- 目前，只有G1 GC会有这种行为
整堆收集（Full GC）：收集整个Java堆和方法区的垃圾收集。
哪些情况会触发Full GC？
- 老年代空间不足
- 方法区空间不足
- 显式调用System.gc()
- Minor GC进入老年代的数据的平均大小大于老年代的可用内存
- 大对象直接进入老年代，而老年代的可用空间不足
GC日志分类
MinorGC
Allocation Failure
表明本次引起GC的原因是因为在年轻代中没有足够的空间能够存储新的数据了。
FullGC
GC日志结构剖析
垃圾收集器
- 使用Serial收集器在新生代的名字是Default New Generation，因此显示的是"[DefNew"
- 使用ParNew收集器在新生代的名字会变成"[ParNew",意思是"Parallel New Generation"
- 使用Parallel Scavenge收集器在新生代的名字是"[PSYoungGen",这里的JDK1.7使用的就是PSYoungGen
- 使用Parallel Old Generation收集器在老年代的名字是"[ParOldGen"
- 使用G1收集器的话，会显示为"garbage-first heap"
GC前后情况
通过图示，我们可以发现GC日志格式的规律一般都是：GC前内存占用->GC后内存占用(该区域内存总大小) [PSYoungGen: 5986k->696k(8704k)] 5986k->704k(9216k)
中括号内：GC回收前年轻代堆大小，回收后大小，（年轻代堆总大小）
括号外：GC回收前年轻代和老年代大小，回收后大小，（年轻代和老年代总大小）
GC时间
GC日志中有三个时间：user,sys和real
- user:进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的实际CPU时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示GC线程执行所使用的CPU总时间。
- sys:进程在内核态消耗的CPU时间，即在内核执行系统调动或等待系统事件所使用的CPU时间
- real:程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待I/O完成）。对于并行gc,这个数字应该接近（用户时间+系统时间）除以垃圾收集器使用的线程数。
由于多核的原因，一般的GC事件中，real time 是小于 sys + user time的，因为一般是多个线程并发的去做GC，所以real time是要小于 sys + user time的。如果real > sys + user的话，则你的应用可能存在下列问题：IO负载非常重或者是CPU不够用。
Minor GC 日志解析
2020-11-20T17:19:43.265-0800: 0.822: [GC (ALLOCATION FAILURE) [PSYOUNGGEN:76800K->8433K(89600K)] 76800K->8449K(294400K), 0.0088371 SECS] [TIMES:USER=0.02 SYS=0.01, REAL=0.01 SECS]
复制代码2020-11-20T17:19:43.265-0800
日志打印事件 日期格式 如2013-05-04T21:53:59.234+0800
0.822
gc发生时，Java虚拟机启动以来经过的秒数
[GC (Allocation Failure)
发生了一次垃圾回收，这是一次Minor GC。它不区分新生代GC还是老年代GC，括号里的内容是gc发生的原因，这里的Allocation Failure的原因是新生代中没有足够区域能存放需要分配的数据而失败。
[PSYoungGen:76800K->8433K(89600K)]
- PSYoungGen:表示GC发生的区域，区域名称与使用的GC收集器是密切相关的
- Serial收集器：Default New Generation显示DefNew
- ParNew收集器：ParNew
- Parallel Scanvenge收集器：PSYoung
- 老年代和新生代同理，也是和收集器名称相关
- 76800K->8433K(89600K)：GC前该内存区域已使用容量-> GC后该区域容量（该区域总容量）
- 如果是新生代，总容量则会显示整个新生代内存的9/10，即Eden + from/to区
- 如果是老年代总容量则是全部内存大小，无变化
76800K->8449K(294400K)
在显示完区域容量GC的情况之后，会接着显示整个堆内存区域的GC情况：GC前堆内存已使用容量 -> GC堆内存容量（堆内存总容量）堆内存总容量 = 9/10 新生代 + 老年代 < 初始化的内存大小
, 0.0088371 secs]
整个GC所花费的时间，单位是秒
[Times:user=0.02 sys=0.01, real=0.01 secs]
- user：指的是CPU工作在用户态所花费的时间
- sys：指的是CPU工作在内核态所花费的时间
- real：指的是在此次GC事件中所花费的总时间
Full GC 日志剖析
2020-11-20T17:19:43.794-0800: 1.351: [FULL GC (METADATA THRESHOLD) [PSYOUNGGEN: 10082k->0k(89600k)] [PAROLDGEN: 32k->9638k(204800k)] 10114k->9638k(294400k), [METASPACE: 20158k->20156k(1067008k)], 0.0285388 SECS] [TIMES: USER=0.11, SYS=0.00, REAL=0.03 SECS]
复制代码2020-11-20T17:19:43.794-0800
日志打印时间 日期格式 如2013-05-04T21:53:59.234+0800
1.351
gc发生时，Java虚拟机启动以来经过的秒数
Full GC (Metadata GC Threshold)
- 发生了一次垃圾回收，这是一次FULL GC。它不区分新生代GC还是老年代GC
- 括号里的内容是gc发生的原因，这里的Metadata GC Threshold的原因是Metaspace区不够用了。
- Full GC(Ergonomics):JVM自适应调整导致的GC
- Full GC(System):调用了System.gc()方法
[PSYoungGen: 10082k->0k(89600k)]
- PSYoungGen:表示GC发生的区域，区域名称与使用的GC收集器是密切相关的
- Serial收集器：Default New Generation显示DefNew
- ParNew收集器：ParNew
- Parallel Scanvenge收集器：PSYoung
- 老年代和新生代同理，也是和收集器名称相关
- 10082k->0k(89600k)：GC前该内存区域已使用容量 -> GC后该区域容量（该区域总容量）
- 如果是新生代，总容量则会显示整个新生代内存的9/10，即Eden + from/to区
- 如果是老年代总容量则是全部内存大小，无变化
[ParOldGen: 32k->9638k(204800k)]
老年代区域没有发生GC，因为本次GC是metaspace引起的
10114k->9638k(294400k)
在显示完区域容量GC的情况之后，会接着显示整个堆内存区域的GC情况：GC前堆内存已使用容量 -> GC堆内存容量（堆内存总容量）堆内存总容量 = 9/10新生代 + 老年代 < 初始化的内存大小
[Metaspace: 20158k->20156k(1067008k)]
metaspace GC 回收2k空间
0.0285388 secs
整个GC所花费的时间，单位是秒
[Times: user=0.11, sys=0.00, real=0.03 secs]
- user：指的是CPU工作在用户态所花费的时间
- sys：指的是CPU工作在内核态所花费的时间
- real：指的是在此次GC事件中所花费的总时间
三、GC日志分析工具
介绍完GC日志的打印及含义后，是不是GC日志看起来比较麻烦，接下来介绍一下GC日志可视化分析工具GCeasy和GCviewer等。通过GC日志可视化分析工具，我们可以很方便地看到JVM各个分代的内存使用情况、垃圾回收次数、垃圾回收原因、垃圾回收占用的时间、吞吐量等，这些指标在我们JVM调优的时候是很有用的。
如果想把GC日志存到文件的话，是下面这个参数： -Xloggc:/path/to/gc.log 然后就可以用一些工具去分析这些gc日志。
GCeasy
GCeasy 一款超好用的在线分析GC日志的网站
GCViewer
上面介绍了一款在线的GC日志分析器，下面介绍一个离线版的GCViewer。
GCViewer是一个免费的、开源的分析小工具，用于可视化查看由SUN/Oracle,IBM,HP和BEA Java虚拟机产生的垃圾收集器的日志。
GCViewer用于可视化Java VM选项-verbose:gc和.NET生成的数据-Xloggc:<file>。它还计算与垃圾回收相关的性能指标（吞吐量，累积的暂停，最常的暂停等）。
下载GCViewer工具
- 源码下载：github.com/chewiebug/G…
- 运行版本下载：github.com/chewiebug/G…
只需双击gcviewer-1.3x.jar或运行java jar gcviewer-1.3x.jar(它需要运行Java 1.8vm),即可启动GCViewer（gui）
四、总结
本节介绍了Java GC日志分析，GC日志参数、GC日志格式、GC日志分析工具，希望大家能有所收获~ 下一篇将介绍OOM常见各各种场景及解决方案。
欢迎大家关注公众号（MarkZoe）互相学习、互相交流。
