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 第一组实验

GC线程数 最耗时的一次YGC日志信息
2 Parallel Time: 567.7 ms, GC Workers: 2
Object Copy (ms): Min: 560.2, Avg: 560.2, Max: 560.2, Diff: 0.0, Sum: 1120.3;
Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0\
3 Parallel Time: 524.8 ms, GC Workers: 3
Object Copy (ms): Min: 519.2, Avg: 519.2, Max: 519.2, Diff: 0.0, Sum: 1557.7
Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0
4 Parallel Time: 1313.9 ms, GC Workers: 4
Object Copy (ms): Min: 1037.0, Avg: 1162.0, Max: 1293.6, Diff: 256.6, Sum: 4648.1
Termination (ms): Min: 0.0, Avg: 131.6, Max: 256.6, Diff: 256.6, Sum: 526.5
6 Parallel Time: 1478.7 ms, GC Workers: 6
Object Copy (ms): Min: 415.9, Avg: 914.5, Max: 1453.3, Diff: 1037.4, Sum: 5486.8
Termination (ms): Min: 0.0, Avg: 535.6, Max: 1031.0, Diff: 1031.0, Sum: 3213.4
12 Parallel Time: 627.5 ms, GC Workers: 12
Object Copy (ms): Min: 307.2, Avg: 370.3, Max: 618.9, Diff: 311.7, Sum: 4443.7
Termination (ms): Min: 0.0, Avg: 248.5, Max: 311.5, Diff: 311.5, Sum: 2982.1
50 Parallel Time: 1757.2 ms, GC Workers: 50
Object Copy (ms): Min: 325.5, Avg: 434.7, Max: 1734.9, Diff: 1409.3, Sum: 21736.7
Termination (ms): Min: 0.0, Avg: 1297.9, Max: 1406.6, Diff: 1406.6, Sum: 64895.7

5.3.2 第二组实验

GC线程数 最耗时的一次YGC日志信息
2 Parallel Time: 586.5 ms, GC Workers: 2
Object Copy (ms): Min: 578.8, Avg: 578.9, Max: 578.9, Diff: 0.0, Sum: 1157.7
Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0
3 Parallel Time: 881.0 ms, GC Workers: 3
Object Copy (ms): Min: 872.7, Avg: 872.7, Max: 872.7, Diff: 0.0, Sum: 2618.2
Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0
4 Parallel Time: 1323.7 ms, GC Workers: 4
Object Copy (ms): Min: 1025.0, Avg: 1166.0, Max: 1310.8, Diff: 285.8, Sum: 4664.1
Termination (ms): Min: 0.0, Avg: 144.8, Max: 285.8, Diff: 285.8, Sum: 579.4
6 Parallel Time: 1337.3 ms, GC Workers: 6
Object Copy (ms): Min: 527.0, Avg: 820.2, Max: 1316.2, Diff: 789.3, Sum: 4921.3
Termination (ms): Min: 0.0, Avg: 492.3, Max: 777.4, Diff: 777.4, Sum: 2953.6
12 Parallel Time: 581.9 ms, GC Workers: 12
Object Copy (ms): Min: 469.8, Avg: 502.1, Max: 576.2, Diff: 106.4, Sum: 6025.2
Termination (ms): Min: 0.0, Avg: 74.0, Max: 106.3, Diff: 106.3, Sum: 888.0
50 Parallel Time: 592.3 ms, GC Workers: 60
Object Copy (ms): Min: 0.0, Avg: 25.6, Max: 564.1, Diff: 564.1, Sum: 1535.3
Termination (ms): Min: 0.0, Avg: 494.7, Max: 521.5, Diff: 521.5, Sum: 29682.0

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.后话

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