首先强调，本文说明的是jdk11 hotspot G1 GC的日志，不同版本的JDK、不同的垃圾回收器，GC Log格式差别甚远。因此本文仅基于快手线上使用最多的jdk11 G1进行分析，同学们如果想了解其它的Log应该如何分析，不如先看完本文，再寻其他资料学习。
如何配置GC Log参数？
Oracle文档描述的比较很清楚。我们在jdk11一般通过Xlog参数来配置，这是目前在快手我见过最多的配置-Xlog:gc*=info,safepoint=info::time,tags,tid
参数的意思是，打印tags包含gc且等级为info（gc*=info）的日志，和tags为safepoint并且等级为info（safepoint=info）日志；两冒号之间的路径为空，默认将日志输出到stdout；每条日志显示信息时间(time)、标签(tags)和线程id(tid)。参数被两个冒号分为三部分，分别表示输出哪些日志、日志输出到哪里以及日志额外信息显示。每个部分并列的条目用逗号隔开。
Log中一次普通的Young GC
从上往下一一分析：[gc,start ] GC(533239) Pause Young (Normal) (G1 Evacuation Pause)
表示这是自JVM创建以来的第533239次GC，是一次普通的Young GC，Pause代表的是STW，大家在分析STW情况的时候可以直接搜索Pause。Pause Young表示的是GC类型，相对的还会有Pause Full表示Full GC。第一个小括号表示Young GC是否有特殊意义，例如Concurrent Start表示这次Young GC后就会开始并发标记，Mixed表示这是一次会回收Old区的混合回收。第二个小括号表示触发原因，一般Eden区填满进入的Young GC会显示G1 Evacuation Pause，常见的还有Humongous Allocation（排查问题总见到他），表示在一次大对象分配后，因为存活对象到达阈值而触发一次Young GC。
[gc,task ] GC(533239) Using 8 workers of 8 for evacuation
这次GC用8个workers来进行Evacuation（可以理解为对象拷贝），参数-XX:ParallelGCThreads可以控制参与Evacuation的线程数，提高这个值可以提高GC效率，减少STW时长，但不要忘记考虑CPU资源是否足够
[gc,phases ] GC(533239) Pre Evacuate Collection Set: 0.3ms[gc,phases ] GC(533239) Evacuate Collection Set: 52.8ms[gc,phases ] GC(533239) Post Evacuate Collection Set: 14.7ms[gc,phases ] GC(533239) Other: 1.6ms
这次GC分别在各个阶段的时间，我么理解一般大部分时间都用在Evacuation上，但上述阶段的划分过于笼统，如果怀疑有异常，其实是没办法排查的。在这种情况下可以在Xlog里加上gc+phases=debug，会显示更细节的时间开销统计
[gc,heap ] GC(533239) Eden regions: 2160->0(2184)[gc,heap ] GC(533239) Survivor regions: 33->28(275)[gc,heap ] GC(533239) Old regions: 508->509[gc,heap ] GC(533239) Humongous regions: 88->56
这部分往往是GC分析的核心，显示了heap里面各代的内存变化情况，例如Eden区，GC前有2160个Regions有对象，GC后Eden区全空，并且JVM在GC后重新分配给Eden区2184个Regions。survivor区、Old、Humongous（大对象）的分析方法一致，不过大家可以发现，Old、humongous只显示了使用Region的变化，没有小括号来表示分配了多少，这是因为G1只给Young区做分配，其他内存可以理解为都给了Old区，也可以理解为Old区只需要考虑占用，未使用部分是Free Region。
[gc,metaspace ] GC(533239) Metaspace: 473360K->473360K(952320K)
显示Metaspace大小，括号内表示Metaspace容量为952320K，可以用于排查元数据oome
[gc ] GC(533239) Pause Young (Normal) (G1 Evacuation Pause) 5576M->1184M(7374M) 69.378ms
这次Young GC结束了，堆内存占用从 5576M变到1184M，堆内存大小（capacity）为7374M，这次GC用时69.378ms[gc,cpu ] GC(533239) User=0.30s Sys=0.20s Real=0.07s
User表示各GC线程工作时间，Sys表示进入内核态时间，Real是真实度过的时间，和上面的69.378ms对应
常见异常问题
结合过去一些排查经验，简单列举几个常见的gc异常现象与排查思路
1、gc次数陡增
最常见的gc问题就是，在查看GC指标时，发现GC Pause时间变长，每分钟GC次数增多。
因为有多种途径会触发GC，首先确定GC触发原因，一般可以归为以下几类：
- 不断的Concurrent Start和Mixed GC。
- 频繁触发Pause Young。
在Log里看每次GC的类型和原因的方法，上文已经提过，不在赘述。如果说，这段时间突然出现许多Concurrent Start和Mixed GC，说明这次gc异常是老年代的分配和占用导致，可以看一下（多次连续的）Mixed GC结束后，old区是否完成了有效回收？如果回收效果不佳，说明有大量对象一直存活，收不掉，借助heapdump可以分析；如果回收效果理想，但很快又会触发新的Concurrent Start，那么可以看看Concurrent Start的这次GC是否伴有G1 Humongous Allocation字样，进一步对比大对象的分配速率是否异常，最后仍可以借助heapdump定位。
如果出现了大量的Pause Young，但并没有异常Mixed GC情况，一般有两种原因：Eden 区过小，或者分配速率过大。普通的Young GC触发是因为Eden区被填满了，因此eden区过小和分配速率突然变大都可能导致Young GC频率增快。判断方法比较简单，只需要看下Eden regions数量是否和平常差不多即可。分配速率的问题需要从业务侧考虑，例如是不是有流量异常？Eden区过小的话，问题会比较复杂，暂时不和大家讨论了。
2、单次gc时间过长
之前有个小伙伴问了我一个问题，他在一个场景下，仅仅切换了一下线程池的实现，GC时间却增长了近十倍。根据日志观察，切换线程池实现后，每次gc的Survivor regions比较高，了解G1 GC基础的话应该清楚，对象如果在一次GC存活后，会从Eden区copy到Survivor区，存活对象多了，每次GC需要进行Evacuation的对象就多，STW时间自然会长。当我提到存活对象大幅增加时，小伙伴结合他的代码逻辑很快就定位了问题。这里提供了一个思路，当单次GC时间过长，我们可以看下时间是否用在Evacuate Collection Set，若是，再看下GC后的Survivor regions是否比较多，Old regions是否有增长。Evacuation往往是Young GC的主要开销。
Mixed GC时间略长于Young GC，这个是可以接受的，如果发现Mixed GC次数突然增多，导致GC时间变长，那问题就转化为之前提到的老年代对象分配问题了。
3、Full GC
G1期望控制每次GC STW时间在一定范围内，但如果出现了Full GC，那么总是不可避免的迎来秒级STW，这对很多线上应用都是难以接受的。
发生Full GC，日志里会出现Pause Full，首先我们可以看一下Full GC的回收效果，经过Full GC后内存是否得到了有效回收，如果大部分内存回收不掉，那么问题比较好定位，应该是哪里“漏”了，借助heapdump分析即可。
如果内存都能够正常回收，就需要多问几个问题了：Full GC触发原因是什么？会不会是metaspace满了？是不是业务代码主动调用了Full GC之前是否有To-space exhausted现象？根据触发原因的不同，排查的方向也应该跟着触发原因走。