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

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

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

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

jspincludeosgi不改一行代码定位线上机能问题 GraphQL

全体的流程算是比较常见的分层架构：

客户端要求到 Nginx。
Nginx 负载了后真个 web 做事。
web 做事通过 RPC 调用后真个 Service 做事。

日志大法

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

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

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

工具剖析

以是最好的办法便是不改动一行代码把这个问题剖析出来。

这时就须要一个 agent 工具了。
我们选用了阿里以前开源的 Tprofile 来利用。

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

工具利用

下面来大略展示下如何利用这个工具。

首先第一步自然是 clone 源码然后打包，可以克隆我修正过的源码。

由于这个项目阿里多年没有掩护了，还残留一些 bug,我在它原有的根本上修复了个影相应用的 bug，同时做了一些优化。

实行以下脚本即可。

git clone https://github.com/crossoverJie/TProfilermvn assembly:assembly

到这里之后会在项目的 TProfiler/pkg/TProfiler/lib/tprofiler-1.0.1.jar 中天生好我们要利用的 jar 包。

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

这个配置文件我 copy 官方的阐明。

#log file namelogFileName = tprofiler.logmethodFileName = tmethod.logsamplerFileName = tsampler.log#basic configuration items# 开始取样韶光startProfTime = 1:00:00# 结束取样韶光endProfTime = 23:00:00# 取样的韶光长度eachProfUseTime = 10# 每次取样的韶光间隔eachProfIntervalTime = 1samplerIntervalTime = 20# 端口，紧张不要冲突了port = 50000debugMode = falseneedNanoTime = 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 itemsexcludeClassLoader = 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 flushmethodflushmethod 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.logprint 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复制代码