慢半拍的 Flink TaskManager——问题不在代码中-育师

背景

用户发现自己的 flink程序出现多个TaskManager cpu使用率相差 10%的现象。
他们排除了数据差异，TaskManager基本都是相似结构的数据，程序处理起来不会有这么大的区别。
期待我找出原因，这样方便用户规划规模和扩量。

排查历程

60 秒快速扫描

用户做了基本的自查，但是并不能作为排查进行的证据，先把 flink 的运行指标汇聚到一起进行快速了解。可以看到如下的内容。

多个TaskManager cpu使用率出现恒定高低变化。高的一直高，低的一直低。
高 cpu使用率的heap 内存占用比低cpu 使用率的高。
高 cpu使用率的gc 次数比低cpu 使用率的多。
两者线程数相同。

这里看到内存和 gc 有差异，flink 本身没有心跳超时表现，直接忽略 gc 时延的影响。转换成gc吞吐，两者都是 90 左右，影响不大，不存在吞吐太低拉长运行时长的情况，说明这个现象是状态下的结果，不是原因。
gc 吞吐的公式如下：

GC吞吐量 = (总时间 - GC总耗时) / 总时间 × 100%

jmx 和 gc日志都可以计算出吞吐量，只是精度问题，日常用jmx 即可，并不是只有 gc日志才能计算。

profiling

经过快速扫描，排除了简单的问题场景。cpu 的使用率变化还可能是程序代码本身带来的，例如不同的分支处理逻辑不一样。用户代码也是多人开发，可能存在理解和实际运行不一致的情况。
我们用 jdk 自带的 jfr 进行 oncpu 采集分析，看看高cpu和低 cpu 使用率堆栈上的差异。

jcmd pid JFR.start duration=2m filename=/tmp/my.jfr

上面是一个采集 2min 的命令。拿到文件先快速统计一下事件差异。这里可以利用jdk 自带的 jfr命令统计。

jfr summary my.jfr

cpu使用率高的进程采样次数为

jdk.ExecutionSample 4261

cpu 使用率低的进程采样次数为

jdk.ExecutionSample 3773

jdk.ExecutionSample只会采集 java代码的堆栈，也就是说 cpu 使用率高的程序采样到的 oncpu 的java 代码多。我们需要分析代码上的差异。jfr 的可视化不好，可以使用我的火焰图转换工具。
# JFR转化火焰图工具

经过做火焰图的差分对比，发现没有代码路径上的差异，堆栈调用基本是等比率增长。

排查 jit

等比率增长的情况下说明问题已经不是编写出的 java 代码本身了。怀疑热点的代码是否是编译出了相同的机器码。可能是 jit 出来的代码效率不高，导致代码跑起来性能不好，相同的 cpu 使用率下执行的代码处理的数据少。
没有提前开启打印 jit 的参数，我们选择 jcmd 导出正在运行的编译情况。

jcmd pid Compiler.codelist

这里导出的数据很多，需要保存到一个文件中。我们可以看到如下内容

33566 3 2 org.jsoup.parser.HtmlTreeBuilderState$7.inBodyStartTag(Lorg/jsoup/parser/Token;Lorg/jsoup/parser/HtmlTreeBuilder;)Z [0x00007f55b3ba7190, 0x00007f55b3ba8d60 - 0x00007f55b3bb9e58]

这里需要重点看的是第二列，表示编译等级。

Level	编译器	特点
0	解释器	无编译，纯解释执行
1	C1	无 profiling，快速轻量编译
2	C1	轻量 profiling，收集基本调用信息
3	C1	完整 profiling，收集方法计数、类型统计等
4	C2	最高优化级别，基于 level 3 收集的 profiling 数据做激进优化
通过对比火焰图的热点方法，发现热点方法的编译等级基本是一样的。jdk 也是相同版本，及时编译出的代码区别不大。

排查cpu

虚拟机层已经排除完了，最大可能就是 2 个机器上 cpu 执行相同的代码本身有差异。我们使用 perf stat 快速统计。可以看到如下的结果：
cpu 使用率高的cycles如下，频率是2.545 GHz

1,809,708,584 cycles # 2.545 GHz

cpu 使用率低的cycles如下，频率是3.055 GHz

2,003,433,272 cycles # 3.055 GHz

可以发现两个机器的频率差异比较大。这里破案了，频率高的机器执行的速度快，从 cpu 使用率低角度看on cpu 的时间少，使用率低。
这里协调了运维把低频机器剔除，TaskManager的表现基本一致了。

总结

回头看这个排查过程，从 Flink 指标面板一路追到 CPU 频率。
堆内存和 GC 次数的差异是「高频低利用率」和「低频高利用率」的副产品，不是原因。很多人走到这里就会开始调 GC 参数，试图让两边的内存曲线对齐。但方向已经错了。
火焰图差分显示热点代码等比率增长，说明不是某条分支路径在拖后腿。JIT 编译等级一样，JDK 版本一样，应用层和 JVM 层已经排除。
最后两行perf stat的输出摆在面前——2.545 GHz vs 3.055 GHz，差距接近 20%。频率低的机器跑同样的指令，要花更多的 CPU 时间。我们看到的10% 的 CPU 使用率差异，根因就在这里。
CPU 使用率本质上是一段时间内 CPU 处于非空闲状态的时间占比，无法表达程序处理的快慢。