现象

测试在压测环境，发现因为了升级了一下日志包组件，导致性能下降厉害（30%）。

需要分析原因？

思路

代码是否真的存在问题

是否所有的性能都下降?

如果全部下降，则针对升级的部分做代码分析+本地结合 jvisual 分析慢在哪里即可。

发现不是，那么就针对这一个应用具体分析。

这里发现就是特定应用的一个压测变慢了。

QPS 下降初步判断

整体看是压测的 QPS 下降。

随便抽取几笔日志查看，大部分的耗时在 10ms 左右，但是整体压测的平均耗时却是 60ms 左右。

每一次都是相同的请求参数，除了订单号差异。

我们要看为什么慢，就去找比较慢的操作才行。

目前的很多 ELK 等日志体系，对于耗时的模糊匹配支持不友好。

找到慢日志

如果有比较好的工具，直接统计出来。

如果日志分析工具不够强大，比如我想找耗时 200-299ms 之间的日志。

可以使用如下的命令

grep "业务关键词" xxx.log | grep "日志关键词2" | egrep 'cost=[2][0-9][0-9]' | tail

主要是 egrep 'cost=[2][0-9][0-9]' 正则 grep 可以把耗时 200-299 的日志找出来，

然后结合日志，分析整个调用链路。

慢日志区间定位

找了几笔慢的操作，都发现在 log1 和 log2 间隔非常久。

查代码，找到 log1 和 log2 的位置，发现是一个 mq 调用。

是否是 GC？

发现 CAT 上这个时间存在 young GC，但是 gc 耗时只有 60ms 左右。

但是慢操作的耗时介于 60~400ms 的都有。

所以可以排除是 gc 的问题，而且每一次都是这个位置，gc 不可能每一次都这么巧。

就算是 gc，那么慢的时间长度应该一致，而不是波动这么大。

耗时操作的确认

所以怀疑就是 mq 的问题。

比如 database/cache/rpc/http 这些都值得怀疑。

不过在怀疑之前，我们可以做一些其他因素的排除，比如把本次新增的功能，比如日志 aop 切面/脱敏等功能全部关闭，排除新的因素影响。

发现关闭之后压测无变化，所以最后只剩下一个资源问题。

小结

性能的分析，主要是思路要明确。

参考资料