1. 介绍
最近kafka集群总是有偶发的YGC问题。今天上午花了点时间好好研究了下。
2. 现状
我们的kafka集群用的是kafka官方的推荐配置。server配置参考kafka官方文档第六章来配置。另外我们的硬件环境比Linkedin用的机器还好点,40核,60G内存。
3. YGC问题回顾
YGC出问题后可以查看下kafka服务器上的GC日志,在KAFKA_HOME/logs/kafkaServer-gc.log
可以看到GC日志:
主要信息是:
- Object Copy耗时比较久: Max和Diff的值远大于Avg,说明部分GC线程在拷贝对象上耗时太久
- Termination: Avg,Max,Difff都比较大。说明GC线程大部分都花了比较久的时间来结束。
4. 原因分析
根据如下参考资料:
可以猜测可能是由于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 实验结果分析
实验结果上可以做出以下总结:
- 当GC线程数小于CPU核数(4)时,可以发现虽然也有耗时比较久的YGC,但是各个线程之间基本没有diff。此外也没有steal job的现象(这个可以去了解下termination的含义)
- 当GC线程数等于CPU核数时,Object Copy中的diff值开始有了,也开始出现GC线程steal job
- 当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 解决办法
知道原因了解决就比较容易:
- 可以尝试设置-XX:ParallelGCThreads=n为一个稍微小点的值。例如40核,按照官方文档建议设置成8分之5,也就是25个。
- 通过设置参数,降低YGC回收的约束,也可以。
6.后话
暂时考虑这么去处理,到时候生产上改了看看是不是有效果。