不改一行代码定位线上性能问题

背景

最近时运不佳，几乎每天被线上问题骚扰。前几天刚解决了一个 HashSet 的并发问题，周六又来了一个性能问题。

大体的现象是：

咱们提供出去的一个 OpenAPI 反应时快时慢，快的时候几十毫秒，慢的时候几秒钟才响应。

尝试解决

若是想学习Java工程化、高性能及分布式、深刻浅出。微服务、Spring，MyBatis，Netty源码分析的朋友能够加个人Java高级交流：854630135，群里有阿里大牛直播讲解技术，以及Java大型互联网技术的视频免费分享给你们。

因为这种也不是业务问题，不能直接定位。因此尝试在测试环境复现，但遗憾的测试环境贼快。

没办法只能硬着头皮上了。

中途有抱着侥幸内心让运维查看了 Nginx 里 OpenAPI 的响应时间，想把锅扔给网络。结果果真打脸了；Nginx 里的日志也代表确实响应时间确实有问题。

为了清晰的了解这个问题，我简单梳理了这个调用过程。

 

整个的流程算是比较常见的分层架构：

• 客户端请求到 Nginx。
• Nginx 负载了后端的 web 服务。
• web 服务经过 RPC 调用后端的 Service 服务。

日志大法

咱们首先想到的是打日志，在可能会慢的方法或接口处记录处理时间来判断哪里有问题。

但经过刚才的调用链来讲，这个请求流程不短。加日志涉及的改动较多并且万一加漏了还有可能定位不到问题。

再一个是改动代码以后还会涉及到发版上线。

工具分析

因此最好的方式就是不改动一行代码把这个问题分析出来。

这时就须要一个 agent 工具了。咱们选用了阿里之前开源的 Tprofile 来使用。

只须要在启动参数中加入 -javaagent:/xx/tprofiler.jar 便可监控你想要监控的方法耗时，而且能够给你输出报告，很是方便。对代码没有任何侵入性同时性能影响也较小。

工具使用

若是想学习Java工程化、高性能及分布式、深刻浅出。微服务、Spring，MyBatis，Netty源码分析的朋友能够加个人Java高级交流：854630135，群里有阿里大牛直播讲解技术，以及Java大型互联网技术的视频免费分享给你们。

下面来简单展现下如何使用这个工具。

首先第一步天然是 clone 源码而后打包，能够克隆我修改过的源码。

由于这个项目阿里多年没有维护了，还残留一些 bug,我在它原有的基础上修复了个影响使用的 bug，同时作了一些优化。

执行如下脚本便可。

git clone https://github.com/crossoverJie/TProfiler mvn assembly:assembly

到这里以后会在项目的 TProfiler/pkg/TProfiler/lib/tprofiler-1.0.1.jar 中生成好咱们要使用的 jar 包。

接下来只须要将这个 jar 包配置到启动参数中，同时再配置一个配置文件路径便可。

这个配置文件我 copy 官方的解释。

#log file name logFileName = tprofiler.log methodFileName = tmethod.log samplerFileName = tsampler.log #basic configuration items # 开始取样时间 startProfTime = 1:00:00 # 结束取样时间 endProfTime = 23:00:00 # 取样的时间长度 eachProfUseTime = 10 # 每次取样的时间间隔 eachProfIntervalTime = 1 samplerIntervalTime = 20 # 端口，主要不要冲突了 port = 50000 debugMode = false needNanoTime = false # 是否忽略 get set 方法 ignoreGetSetMethod = true #file paths 日志路径 logFilePath = /data/work/logs/tprofile/${logFileName} methodFilePath =/data/work/logs/tprofile/${methodFileName} samplerFilePath =/data/work/logs/tprofile/${samplerFileName} #include & excludes items excludeClassLoader = org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader # 须要监控的包 includePackageStartsWith = top.crossoverjie.cicada.example.action # 不须要监控的包 excludePackageStartsWith = com.taobao.sketch;org.apache.velocity;com.alibaba;com.taobao.forest.domain.dataobject

最终的启动参数以下：

-javaagent:/TProfiler/lib/tprofiler-1.0.1.jar -Dprofile.properties=/TProfiler/profile.properties

为了模拟排查接口响应慢的问题，我用 cicada 实现了一个 HTTP 接口。其中调用了两个耗时方法：

 

这样当我启动应用时，Tprofile 就会在我配置的目录记录它所收集的方法信息。

我访问接口 http://127.0.0.1:5688/cicada-example/demoAction?name=test&id=10 几回后它就会把每一个方法的明细响应写入 tprofile.log。

 

由左到右每列分别表明为：

线程ID、方法栈深度、方法编号、耗时（毫秒）。

但 tmethod.log 仍是空的；

这时咱们只须要执行这个命令便可把最新的方法采样信息刷到 tmethod.log 文件中。

java -cp /TProfiler/tprofiler.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 50000 flushmethod flushmethod success

其实就是访问了 Tprofile 暴露出的一个服务，他会读取、解析 tprofile.log 同时写入 tmethod.log.

其中的端口就是配置文件中的 port。

再打开 tmethod.log ：

 

其中会记录方法的信息。

• 第一行数字为方法的编号。能够经过这个编号去 tprofile.log(明细)中查询每次的耗时状况。
• 行末的数字则是这个方法在源码中最后一行的行号。

其实大部分的性能分析都是统计某个方法的平均耗时。

因此还须要执行下面的命令，经过 tmethod.log tprofile.log来生成每一个方法的平均耗时。

java -cp /TProfiler/tprofiler.jar com.taobao.profile.analysis.ProfilerLogAnalysis tprofiler.log tmethod.log topmethod.log topobject.log print result success

打开 topmethod.log 就是全部方法的平均耗时。

 

• 4 为请求次数。
• 205 为平均耗时。
• 818 则为总耗时。

和实际状况是相符的。

方法的明细耗时

这是可能还会有其余需求；好比说我想查询某个方法全部的明细耗时怎么办呢？

官方没有提供，但也是能够的，只是要麻烦一点。

好比我想查看 selectDB() 的耗时明细：

首先得知道这个方法的编号，在 tmethod.log 中能够看查到。

2 top/crossoverjie/cicada/example/action/DemoAction:selectDB:84

编号为 2.

以前咱们就知道 tprofile.log 记录的是明细，因此经过下面的命令便可查看。

grep 2 tprofiler.log

 

经过第三列方法编号为 2 的来查看每次执行的明细。

但这样的方式显然不够友好，须要人为来过滤干扰，步骤也多；因此我也准备加上这样一个功能。

只须要传入一个方法名称便可查询采集到的全部方法耗时明细。

总结

回到以前的问题；线上经过这个工具分析咱们获得了以下结果。

• 有些方法确实执行时快时慢，但都是和数据库相关的。因为目前数据库压力较大，准备在接下来进行冷热数据分离，以及分库分表。
• 在第一步操做还没实施以前将部分写数据库的操做改成异步，减少响应时间。
• 考虑接入 pinpoint 这样的 APM工具。

相似于 Tprofile 的工具确实挺多的，找到适合本身的就好。

在尚未使用相似于 pinpoint 这样的分布式跟踪工具以前应该会大量依赖于这个工具，因此后续说不定也会作一些定制，好比增长一些可视化界面等，能够提升排查效率。

若是想学习Java工程化、高性能及分布式、深刻浅出。微服务、Spring，MyBatis，Netty源码分析的朋友能够加个人Java高级交流：854630135，群里有阿里大牛直播讲解技术，以及Java大型互联网技术的视频免费分享给你们。