拓展阅读

JVM FULL GC 生产问题 I-多线程通用实现

JVM FULL GC 生产问题 II-如何定位内存泄露？ 线程通用实现

JVM FULL GC 生产问题 III-多线程执行队列的封装实现，进一步抽象

jvisualvm java 性能分析工具

jvm-44-jvm 内存性能分析工具 Eclipse Memory Analyzer Tool (MAT) / 内存分析器 (MAT)

jvm-45-jvm dump 文件内存介绍+获取方式+堆内存可视分析化工具

jvm-46-jvm Thread Dump 线程的堆栈跟踪信息+获取方式+可视分析化工具 FastThread

jvm-47-jvm GC 日志获取方式+可视分析化工具 GcViewer

jvm-48-java 变更导致压测应用性能下降，如何分析定位原因？

jvm-49-linux 服务器使用率升高应该如何排查分析？

前言

大家好，我是老马。

java 的性能下降，相信每一位小伙伴都遇到过。

测试在压测环境，发现因为了升级了一下日志包组件，导致性能下降厉害（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 切面/脱敏等功能全部关闭，排除新的因素影响。

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

小结

希望本文对你有所帮助，如果喜欢，欢迎点赞收藏转发一波。

我是老马，期待与你的下次相遇。