一次使用火焰图排查性能问题的经验

最近正在给公司一个非常老的单体项目升级到微服务。

在测试过程中、发现迁移过来的接口慢的不正常。使用火焰图找到了这个性能内鬼。

1. 排查过程

迁移的原始接口响应时间为 300ms ，迁移过来以后测试结果为10s+ ，这显然不正常。

防火墙http包分析是内鬼吗？

由于原接口方法逻辑未做修改，并且由于存在先例，最先想到的是公司服务器入口防火墙是内鬼。

怀疑是防火墙做了http包分析过慢导致。

这里使用 tcpdump分别对防火墙的入栈和出栈两侧抓包分析，发现并不是防火墙的问题。

arthas trace

随后用 arthas trace 对相关方法追踪了一下，发现是数据交换的mapper层方法非常慢，消耗了绝大部分时间。

所以排查范围从网络链路缩小到 app内。

虽然缩小到app内，但还是很迷惑，原方法逻辑并没有修改，且响应时间也很稳定。

移植过来以后怎么会慢这么多，事已至此打一张火焰图看看，cpu到底消耗在哪里了。

分析火焰图

arthas 集成了async-profiler 直接使用 profiler start/stop 就可以生成火焰图：

通过火焰图发现85%的时间都消耗在了 com.fhs.trans.utils包下的方法。

随机查了一下，发现是一个名为 easy-trans的插件， 功能是给VO做字段翻译转换的。

然后简单的debug了一下这个方法，发现它在做转换的时候会递归遍历所有 vo的所有属性。如果属性是pojo那么还会遍历这个pojo的所有属性。

恰巧我这个接口返回的数据量很大、属性也是多级的、就导致明明是内存操作也慢到10s级别。

把这个插件按照接口忽略以后，响应时间恢复正常了。

还有内鬼？

本以为事情到此就告一段落了，再调试后续接口时又发现新的问题。

部分ms级接口会不稳定的下降到s级别 。

于是再次打了一张火焰图：

发现在cpu调用中，JIT编译器退优化竟然占总采样的62%。

幸运的是，迁移项目的jdk为17, 已经拥有JFR功能，并且问题还算容易复现。

于是用jfr监听了一段接口调用的过程， 看看到底是什么东西在退优化。

抓了一个内鬼但不是主因

在监听期间，一共有8个退优化事件，排除jdk本身的，只剩一个 jdbc 驱动的问题。

是Druid连接池在初始化数据源时调用的方法，退优化的原因是 unstable_if （分支预测失败）。

查了一下分支预测失败的原因有很多 （if过多等）。

随后准备查看项目的mysql驱动依赖，进方法看看到底是怎么回事。直接让我逮到了！

项目引入了一个比较新版本的mysql启动，不是常用的 8.0.33

随后将驱动降成常见版本，又打了一个jfr，退优化果然没了。

但接口缓慢问题依然存在。

没什么办法，接着看火焰图吧

因为火焰图采样是对所有cpu同时采样，并且退优化这个问题不一定直接作用在接口调用栈上。

因此这次我直接在业务方法调用栈上找，看看能否有一些收获。

逮到！

一般来说是不会怀疑驱动器的，但是你这个parser占用了这么久到底是解析什么？

还是同样的思路，正准备看看这个解析方法到底做了什么。

欸，这clickhouse的驱动依赖怎么这么陌生啊， 怎么还是apache开头的。

<!--        <dependency>-->
<!--            <groupId>org.apache.pulsar</groupId>-->
<!--            <artifactId>pulsar-io-jdbc-clickhouse</artifactId>-->
<!--        </dependency>-->

于是马上和原项目的驱动依赖对比了一下，发现这个依赖是同事无意间引入的。

将所有ck相关依赖替换与原项目一致，解决问题！