背景
近期线上遇到一个棘手问题:我们提供的 OpenAPI 响应时间极不稳定,快时几十毫秒,慢时则需数秒。由于这并非业务逻辑错误,直接在测试环境复现非常困难,测试环境往往运行飞快。
为了排除网络因素,我们让运维查看了 Nginx 的日志,确认响应时间确实存在波动,问题出在应用服务内部。

整个流程属于常见的分层架构:客户端请求经过 Nginx 负载到 Web 服务,Web 服务再通过 RPC 调用后端的 Service 服务。
排查思路
常规的排查方式是打日志,在关键方法处记录耗时。但考虑到调用链较长,手动加日志改动点多且容易遗漏,更重要的是涉及发版上线,风险较高。
既然不能改代码,最好的方式就是使用非侵入式的 Agent 工具。我们选用了阿里开源的 TProfiler,它通过 JVM Agent 监控方法耗时,对代码零侵入,性能影响也较小。
工具准备
TProfiler 项目多年未维护,存在一些 Bug。我们在其基础上修复了部分影响使用的缺陷并做了优化。
首先克隆源码并打包:
git clone https://github.com/crossoverJie/TProfiler
cd TProfiler
mvn assembly:assembly
构建完成后,会在 TProfiler/pkg/TProfiler/lib/tprofiler-1.0.1.jar 生成所需的 Jar 包。
接下来配置启动参数和配置文件路径。配置文件内容如下:
# 日志文件名
logFileName = tprofiler.log
methodFileName = tmethod.log
samplerFileName = tsampler.log
# 基础配置
startProfTime = 1:00:00
endProfTime = 23:00:00
eachProfUseTime = 10
eachProfIntervalTime = 1
samplerIntervalTime = 20
port = 50000
debugMode = false
needNanoTime = false
ignoreGetSetMethod = true
# 日志路径
logFilePath = /data/work/logs/tprofile/${logFileName}
methodFilePath = /data/work/logs/tprofile/${methodFileName}
samplerFilePath = /data/work/logs/tprofile/${samplerFileName}
# 包过滤
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 接口,其中调用了两个耗时方法。启动应用后,TProfiler 会在配置的目录记录收集的方法信息。
访问几次接口后,系统会将每个方法的明细响应写入 tprofiler.log。该文件每列分别代表线程 ID、方法栈深度、方法编号及耗时(毫秒)。
此时 tmethod.log 可能为空,需要执行以下命令将最新采样信息刷入:
java -cp /TProfiler/tprofiler.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 50000 flushmethod
执行成功后打开 ,可以看到方法编号及源码行号。大部分性能分析关注的是平均耗时,因此需要进一步生成报告:


