1. 介绍

最近kafka集群总是有偶发的YGC问题。今天上午花了点时间好好研究了下。

2. 现状

我们的kafka集群用的是kafka官方的推荐配置。server配置参考kafka官方文档第六章来配置。另外我们的硬件环境比Linkedin用的机器还好点，40核，60G内存。

3. YGC问题回顾

YGC出问题后可以查看下kafka服务器上的GC日志，在KAFKA_HOME/logs/kafkaServer-gc.log

可以看到GC日志：

主要信息是：

1. Object Copy耗时比较久： Max和Diff的值远大于Avg，说明部分GC线程在拷贝对象上耗时太久
2. Termination: Avg,Max,Difff都比较大。说明GC线程大部分都花了比较久的时间来结束。

4. 原因分析

根据如下参考资料：

1. Object Copy和Termination耗时与GC线程CPU调度存在关联
2. GCParallelThreads的建议值，一般是逻辑核数的8分之5

可以猜测可能是由于GC线程由于不能及时分配到CPU而在CPU调度上耗时浪费了时间。

不过生产集群上cpu利用率比较低，28个GC线程去使用40个核心出现CPU调度耗时感觉说服性不够强。因为生产集群上也只有kafka server一个服务，其他就是些系统进程和zabbix进程。

5. 进一步探究GC线程数与Object Copy值的关系

我们写一个会导致堆溢出的简单JAVA程序，每循环1000次sleep 1毫秒，避免对CPU造成太大压力，预留线程切换的机会。这样可以看看CPU负载较低时能否引发同样的问题。

5.1 实验方案

我们的实验环境是我的本地机器，4核心的CPU。 分别尝试使用2、3、4、6、12、50个GC线程来运行会导致堆溢出的JAVA程序，观察GC日志中Object Copy的变化。

为了确保实验结果准确，我们跑两组实验。

5.2 代码和JVM参数

实验代码

package jdk8;

import vo.Student;

import java.util.ArrayList;
import java.util.List;

/**
 * @author Wan Kaiming on 2016/12/15
 * @version 1.0
 */
public class G1Test {

    public static void main(String[] args) throws InterruptedException {

        List<Student> list = new ArrayList<>();

        while(true){
            Thread.currentThread().sleep(1);
            for(int i=0;i<1000;i++){
            //student类自己写下吧
                list.add(new Student());
            }
        }
    }
}

JVM参数：

-Xmx2g
-Xms2g
-XX:MetaspaceSize=20m
-XX:+UseG1GC
-XX:MaxGCPauseMillis=20
-XX:InitiatingHeapOccupancyPercent=35
-XX:G1HeapRegionSize=16M
-XX:MinMetaspaceFreeRatio=50
-XX:MaxMetaspaceFreeRatio=80
-XX:+UseG1GC
-XX:MaxGCPauseMillis=20
-XX:InitiatingHeapOccupancyPercent=35
-XX:+DisableExplicitGC
-Djava.awt.headless=true
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps
-XX:ParallelGCThreads=12
-Dcom.sun.management.jmxremote
-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.ssl=false
-Dcom.sun.management.jmxremote.port=8888

5.3 实验结果

GC日志比较长，我们每次都选择一次实验中最耗时的那次YGC作为观测目标。

5.3.1 第一组实验

5.3.2 第二组实验

5.4 实验结果分析

实验结果上可以做出以下总结：

1. 当GC线程数小于CPU核数(4)时，可以发现虽然也有耗时比较久的YGC，但是各个线程之间基本没有diff。此外也没有steal job的现象(这个可以去了解下termination的含义)
2. 当GC线程数等于CPU核数时，Object Copy中的diff值开始有了,也开始出现GC线程steal job
3. 当GC线程数大于CPU核数时，Object Copy中的diff值开始明显增大。部分GC程等待调度导致在对象拷贝上耗时比别的线程多很久。大量GC线程steal job出现。

基本上，我们有理由相信，当GC线程由于不能及时分配到CPU时间片而被调度执行，会导致GC日志上 Object copy里面的diff值增大。这个于我们kafka生产环境上面的情况一致。而生产环境虽然只有kafka这么个主要的程序在跑，但是其本身还是会存在很多的线程和GC线程去竞争CPU资源。所以还是有理由相信这些G1收集器偶发的YGC峰值问题是由于GC线程过多而不能及时分配到CPU时间片造成的。

5.5 解决办法

知道原因了解决就比较容易：

1. 可以尝试设置-XX:ParallelGCThreads=n为一个稍微小点的值。例如40核，按照官方文档建议设置成8分之5，也就是25个。
2. 通过设置参数，降低YGC回收的约束，也可以。

6.后话

暂时考虑这么去处理，到时候生产上改了看看是不是有效果。