尝试解决

由于这不是业务问题，所以无法直接定位。所以我尝试在测试环境复现，但很遗憾测试环境速度很快。

别无选择，只能继续进行。

我让运维人员检查了Nginx的响应时间，希望将问题归咎于网络。但是他们错了sketch.im 打不开了，Nginx的日志也显示响应时间确实有问题。

为了能够清楚的理解这个问题，我简单整理了一下调用流程。

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

日记

我们首先想到的就是记录那些可能比较慢的方法或接口的处理时间，以确定问题出在哪里。

但从刚才的调用链来看，这个请求流程不短，添加日志涉及很多改动，如果漏掉任何一个，都可能无法定位问题所在。

还有就是改完代码之后会涉及到网上发布版本。

刀具分析

所以最好的办法就是不改一行代码来分析这个问题。

这时候就需要一个代理工具了，我们选择用阿里巴巴之前开放的那个。

你只需要在启动参数中添加-:/xx/.jar，就可以监控你想监控的方法的耗时，它就能为你输出报告，非常方便。对代码无侵入，对性能影响很小。

工具使用

下面就来简单介绍一下该工具的使用方法。

第一步自然是要clone源码然后打包，大家可以clone我修改过的源码。

由于阿里巴巴已经多年没有维护此项目了，还残留着一些bug，所以我在原有基础上修复了影响使用的bug，并做了一些优化。

只需执行以下脚本。

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

这样之后在项目的/pkg//lib/-1.0.1.jar里就会生成我们要使用的jar包。

接下来只需要把这个jar包配置到启动参数中，并配置一个配置文件路径就可以了。

我把这个配置文件的官方解释复制过来。

#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

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

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

我多次访问接口：5688/-/？name=test&id=10，它将每个方法的详细响应写入.log。

从左到右，每列代表：

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

但是.log仍然为空；

这时候我们只需要执行该命令就可以将最新的方法采样信息刷新到.log文件中。

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

实际上，它访问一个暴露的服务，该服务读取、解析和写入.log。

端口就是配置文件里的端口。

再次打开.log：

它将记录方法信息。

实际上大多数的性能分析都是统计某个方法所消耗的平均时间。

因此还需要执行以下命令，通过.log.log生成各个方法消耗的平均时间。

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

打开.log显示所有方法所花费的平均时间。

和实际情况是相符的。

方法细节耗时

可能还有其他需求，比如我想查询某个方法的所有详细信息，需要多长时间，怎么办？

虽然没有正式推出，但是还是可以的，只是稍微麻烦一些。

例如我想查看()的时间详情：

首先需要知道这个方法的编号，可以在.log中找到。

2 top/crossoverjie/cicada/example/action/DemoAction:selectDB:84
复制代码

数量是2。

前面我们已经知道，.log会记录详细信息，因此我们可以通过以下命令查看。

grep 2 tprofiler.log
复制代码

使用第三列，方法编号 2，查看每次执行的详细信息。

但这种方式显然不够人性化，需要人为干预来滤除干扰，而且步骤繁多；所以我也打算增加这样的功能。

您只需输入方法名称，即可查询所有收集方法的耗时详情。

总结

回到刚才的问题，我们通过这个工具在线分析，得到了以下结果。

类似的工具确实有很多，只要找到适合自己的就行。

在使用这样的分布式跟踪工具之前，你可能会严重依赖这个工具sketch.im 打不开了，因此稍后你可能会进行一些定制，比如添加一些可视化界面，以提高故障排除效率。

如有侵权请联系删除！