慢半拍的 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.jfrcpu使用率高的进程采样次数为
jdk.ExecutionSample 4261cpu 使用率低的进程采样次数为
jdk.ExecutionSample 3773jdk.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 GHzcpu 使用率低的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 处于非空闲状态的时间占比，无法表达程序处理的快慢。
相关链接