现象
测试在压测环境,发现因为了升级了一下日志包组件,导致性能下降厉害(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 切面/脱敏等功能全部关闭,排除新的因素影响。
发现关闭之后压测无变化,所以最后只剩下一个资源问题。
小结
性能的分析,主要是思路要明确。