JVM 性能调优实战之：使用阿里开源工具 TProfiler 在海量业务代码中精确定位性能代码
栏目：框架设计时间：2016-12-06 10:57:32
本文是《JVM 性能调优实战之：1次系统性能瓶颈的寻觅进程》 的后续篇，该篇介绍了如何使用 JDK 本身提供的工具进行 JVM 调优将 TPS 由 2.5 提升到 20 (提升了 7 倍)，并准肯定位系统瓶颈：我们利用里静态对象不是太多、有大量的业务线程在频繁创建1些生命周期很长的临时对象，代码里有问题。那末问题来了，如何在海量业务代码里边准肯定位这些性能代码？本文将介绍如何使用阿里开源工具 TProfiler 来定位这些性能代码，成功解决掉了 GC 过于频繁的性能瓶颈，并终究在上次优化的基础上将 TPS 再提升了4 倍，即提升到 100。
$ mkdir /opt/tprofiler
本地将下载后的 TProfiler-master.zip 解紧缩，将 dist 目录下的 profile.properties 和 dist/lib 目录下的 tprofiler⑴.0.1.jar ftp 上传到远程服务器 /opt/tprofiler 目录下。
最后将远程服务器 /opt/tprofiler 目录及其下所有文件的所有者改成启动 Weblogic 进程的用户及其所在用户组。
#log file name
logFileName = tprofiler.log
methodFileName = tmethod.log
samplerFileName = tsampler.log
#basic configuration items
startProfTime = 9:00:00
endProfTime = 23:00:00
eachProfUseTime = 5
eachProfIntervalTime = 50
samplerIntervalTime = 20
port = 30000
debugMode = false
needNanoTime = false
ignoreGetSetMethod = true
#file paths
logFilePath = ${user.home}/logs/${logFileName}
methodFilePath = ${user.home}/logs/${methodFileName}
samplerFilePath = ${user.home}/logs/${samplerFileName}
#include & excludes items
excludeClassLoader = org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader
includePackageStartsWith = com.caucho;com.defonds;com.fasterxml;com.sun.jersey;com.sun.jmx;org.apache;org.codehaus;org.jdbcdslog;org.mybatis;org.quartz;org.springframework
excludePackageStartsWith = com.taobao.sketch;org.apache.velocity;com.alibaba;com.taobao.forest.domain.dataobject
红色部份是我修改后的内容，其它部份使用默许值。
-javaagent:/opt/tprofiler/tprofiler⑴.0.1.jar -Dprofile.properties=/opt/tprofiler/profile.properties
以后重启 Weblogic。
running
得到这个结果证明 TProfiler 正在进行收集工作。
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 stop
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 status
stop
随时启动以继续收集：
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 start
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 status
running
会将数据刷出到 ~/logs/ 目录下：
方法履行时间统计：这个非常非常重要，这个是 TProfiler 最最重要的 feature，是其能够傲视所有其他性能测试类(包括 jvm 性能测试类)软件的关键所在，我们将会不止1次地在关键的时候受益于 TProfiler 的这1非常有用的特性。
上述命令刷出的 topmethod.log 部份结果以下：
com/defonds/core/ppts/common/support/JsonUtils:object2jsonString:123 13519 154 2083584
com/caucho/hessian/client/HessianURLConnection:sendRequest:156 15894 130 2072565
com/defonds/rest/core/client/proxy/ResourceJsonInvocationHandler:invoke:39 8123 113 921340
com/defonds/core/ppts/cache/service/impl/MerBankCfgServiceImpl:selectMerBankCfgByParams:72 54213 15 799322
com/defonds/core/ppts/incomes/biz/sinopay/service/impl/SinoPayBankReturnServiceImpl4Json:updateOrderSuccess:792 2495 176 438542
com/defonds/core/ppts/common/support/framework/bean/Message:<init>:76 6219 26 163741
com/fasterxml/jackson/databind/ser/impl/IndexedListSerializer:serializeContents:107 51883 3 145556
com/defonds/core/ppts/cache/biz/cims/impl/AccountPrdAndBankCacheImpl:selectBasicProductCfg:144 16131 8 137029
格式说明：方法信息 履行次数 平均履行时间 全部履行时间
这是压测时根据屡次采样结果，拣选出的1次比较有代表性的1次。红色部份值得我们去重点关注并优化1下，由于极有可能就是利用瓶颈所在。这些代码要末是致使平均响应时间低下的1些点，要末是致使大量临时对象产生的1些点。
对上篇博客中的结论，这些代码的调优原则是：临时对象能改成静态对象进行复用就改成公用对象，高频访问代码提高响应速度。根据 jvm gc 日志发现很多 young gc 以后堆内存已用空间不但降落反而上升至最大使用量致使 full gc，临时对象如果可以和其它线程复用的话改成静态对象以减少大量线程 local 对象的产生。
以排名第1的热门方法 com/defonds/core/ppts/common/support/JsonUtils:object2jsonString:123 为例，看看如何来进行调优。
该热门方法的优化建议：
这个方法平均调用时间在 154ms，如果在低并发时可能比这要小很多。但是高并发时可能要等待 GC 的堆内存释放、GC 作业时对业务线程酿成的暂停时间等因素影响，这个时间会被无穷放大。
比如我们原来用过谷歌的 Gson 进行 json 处理，某个大对象的 json 解析使用 gson 是 100 多秒，而换成 fastjson 解析后是 900 多毫秒。上百倍的性能差距呀，这还是在单用户操作、不能存在 CPU 和内存等资源限制及竞争的情况下拿到的数据。在此向贡献出 fastjson 的阿里人致敬~
$ netstat -an | grep 30000
TProfiler 最重要的特性就是能够统计出你指定时间段内 JVM 的 topmethod，这些 topmethod 极有可能就是造成你 JVM 性能瓶颈的首恶。这是其他大多数 JVM 调优工具所不具有的，包括 JRockit Mission Control。JRokit 首席开发者 Marcus Hirt 在其私人博客《Low Overhead Method Profiling with Java Mission Control》下的评论中曾明确指出 JRMC 其实不支持 TOP 方法的统计：
最后再次向具有开源精神的阿里技术团队致敬~
1. TProfiler 的下载安装
1.1. 下载
访问 TProfiler 的 GitHub 主页，点击 Clone or download 按钮的打开下载选项，点击该选项下的 Download ZIP 按钮将 TProfiler-master.zip 下载到本地。笔者上传了1份截至 20160920 最新 TProfiler-master.zip 到 CSDN 资源，读者朋友也能够去这里下载：http://download.csdn.net/detail/defonds/9635731。1.2. 安装
SSH 登录需要监控的远程服务器主机，为 TProfiler 新建安装路径：$ mkdir /opt/tprofiler
本地将下载后的 TProfiler-master.zip 解紧缩，将 dist 目录下的 profile.properties 和 dist/lib 目录下的 tprofiler⑴.0.1.jar ftp 上传到远程服务器 /opt/tprofiler 目录下。
最后将远程服务器 /opt/tprofiler 目录及其下所有文件的所有者改成启动 Weblogic 进程的用户及其所在用户组。
2. TProfiler 的配置部署
2.1. TProfiler 配置
编辑服务器 /opt/tprofiler/profile.properties 文件内容以下：#log file name
logFileName = tprofiler.log
methodFileName = tmethod.log
samplerFileName = tsampler.log
#basic configuration items
startProfTime = 9:00:00
endProfTime = 23:00:00
eachProfUseTime = 5
eachProfIntervalTime = 50
samplerIntervalTime = 20
port = 30000
debugMode = false
needNanoTime = false
ignoreGetSetMethod = true
#file paths
logFilePath = ${user.home}/logs/${logFileName}
methodFilePath = ${user.home}/logs/${methodFileName}
samplerFilePath = ${user.home}/logs/${samplerFileName}
#include & excludes items
excludeClassLoader = org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader
includePackageStartsWith = com.caucho;com.defonds;com.fasterxml;com.sun.jersey;com.sun.jmx;org.apache;org.codehaus;org.jdbcdslog;org.mybatis;org.quartz;org.springframework
excludePackageStartsWith = com.taobao.sketch;org.apache.velocity;com.alibaba;com.taobao.forest.domain.dataobject
红色部份是我修改后的内容，其它部份使用默许值。
2.2. Weblogic 启动参数配置
在 Weblogic JVM 启动参数里加入：-javaagent:/opt/tprofiler/tprofiler⑴.0.1.jar -Dprofile.properties=/opt/tprofiler/profile.properties
以后重启 Weblogic。
3. TProfiler 的远程操作
使用启动 Weblogic 进程的用户 SSH 远程登录正在进行压测的机器。3.1. 查看 TProfiler 当前状态
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 statusrunning
得到这个结果证明 TProfiler 正在进行收集工作。
3.2. 将 TProfiler 停止，以释放其占用的系统资源
随时关闭 TProfiler：$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 stop
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 status
stop
随时启动以继续收集：
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 start
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 status
running
3.3. 刷出数据
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 flushmethod会将数据刷出到 ~/logs/ 目录下：
4. TProfiler 对性能方法的收集
4.1. 普通方法、线程统计
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.analysis.SamplerLogAnalysis ~/logs/tsampler.log ~/logs/method.log ~/logs/thread.log4.2. top 统计
$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.analysis.ProfilerLogAnalysis ~/logs/tprofiler.log ~/logs/tmethod.log ~/logs/topmethod.log ~/logs/topobject.log方法履行时间统计：这个非常非常重要，这个是 TProfiler 最最重要的 feature，是其能够傲视所有其他性能测试类(包括 jvm 性能测试类)软件的关键所在，我们将会不止1次地在关键的时候受益于 TProfiler 的这1非常有用的特性。
上述命令刷出的 topmethod.log 部份结果以下：
com/defonds/core/ppts/common/support/JsonUtils:object2jsonString:123 13519 154 2083584
com/caucho/hessian/client/HessianURLConnection:sendRequest:156 15894 130 2072565
com/defonds/rest/core/client/proxy/ResourceJsonInvocationHandler:invoke:39 8123 113 921340
com/defonds/core/ppts/cache/service/impl/MerBankCfgServiceImpl:selectMerBankCfgByParams:72 54213 15 799322
com/defonds/core/ppts/incomes/biz/sinopay/service/impl/SinoPayBankReturnServiceImpl4Json:updateOrderSuccess:792 2495 176 438542
com/defonds/core/ppts/common/support/framework/bean/Message:<init>:76 6219 26 163741
com/fasterxml/jackson/databind/ser/impl/IndexedListSerializer:serializeContents:107 51883 3 145556
com/defonds/core/ppts/cache/biz/cims/impl/AccountPrdAndBankCacheImpl:selectBasicProductCfg:144 16131 8 137029
格式说明：方法信息 履行次数 平均履行时间 全部履行时间
5. 性能方法的优化
根据 topmethod.log 统计结果，我们拿到了热门方法 top10：| 方法名 | 被调用次数 | 平均履行时间 | 采样内总履行时间 |
|---|---|---|---|
| com/defonds/core/ppts/common/support/JsonUtils:object2jsonString:123 | 13519 | 154 | 2083584 |
| com/caucho/hessian/client/HessianURLConnection:sendRequest:156 | 15894 | 130 | 2072565 |
| com/defonds/rest/core/client/proxy/ResourceJsonInvocationHandler:invoke:39 | 8123 | 113 | 921340 |
| com/defonds/core/ppts/cache/service/impl/MerBankCfgServiceImpl:selectMerBankCfgByParams:72 | 54213 | 15 | 799322 |
| com/defonds/core/ppts/incomes/biz/sinopay/service/impl/SinoPayBankReturnServiceImpl4Json:updateOrderSuccess:792 | 2495 | 176 | 438542 |
| com/defonds/core/ppts/common/support/framework/bean/Message:<init>:76 | 6219 | 26 | 163741 |
| com/fasterxml/jackson/databind/ser/impl/IndexedListSerializer:serializeContents:107 | 51883 | 3 | 145556 |
| com/defonds/core/ppts/cache/biz/cims/impl/AccountPrdAndBankCacheImpl:selectBasicProductCfg:144 | 16131 | 8 | 137029 |
| com/defonds/core/ppts/common/jms/retrieve/listener/DefaultMessageListener:handleMessage:64 | 2981 | 46 | 136180 |
| com/fasterxml/jackson/databind/ser/BeanPropertyWriter:serializeAsField:573 | 53892 | 2 | 112553 |
这是压测时根据屡次采样结果，拣选出的1次比较有代表性的1次。红色部份值得我们去重点关注并优化1下，由于极有可能就是利用瓶颈所在。这些代码要末是致使平均响应时间低下的1些点，要末是致使大量临时对象产生的1些点。
对上篇博客中的结论，这些代码的调优原则是：临时对象能改成静态对象进行复用就改成公用对象，高频访问代码提高响应速度。根据 jvm gc 日志发现很多 young gc 以后堆内存已用空间不但降落反而上升至最大使用量致使 full gc，临时对象如果可以和其它线程复用的话改成静态对象以减少大量线程 local 对象的产生。
以排名第1的热门方法 com/defonds/core/ppts/common/support/JsonUtils:object2jsonString:123 为例，看看如何来进行调优。
import org.codehaus.jackson.map.ObjectMapper;
public static <T> String object2jsonString(T t) {
try {
ObjectMapper objectMapper = instanceObjectMapper();
return objectMapper.writeValueAsString(t);
} catch (JsonParseException e) {
log.error(e.getMessage(), e);
throw new SysException(e);
} catch (JsonMappingException e) {
log.error(e.getMessage(), e);
throw new SysException(e);
} catch (IOException e) {
log.error(e.getMessage(), e);
throw new SysException(e);
}
}
public static ObjectMapper instanceObjectMapper() {
JsonFactory jf = new JsonFactory();
jf.configure(Feature.WRITE_NUMBERS_AS_STRINGS, true);
return new ObjectMapper(jf);
}
该热门方法的优化建议：
这个方法平均调用时间在 154ms，如果在低并发时可能比这要小很多。但是高并发时可能要等待 GC 的堆内存释放、GC 作业时对业务线程酿成的暂停时间等因素影响，这个时间会被无穷放大。
5.1. 临时对象改成静态对象
object2jsonString 方法的 objectMapper 对象，instanceObjectMapper 方法的 jf 对象；5.2. json 处理由 jackson 改成 fastjson
jackson 和 spring 整合的很好，提供的功能点很多很强大。但是其性能未必靠得住。比如我们原来用过谷歌的 Gson 进行 json 处理，某个大对象的 json 解析使用 gson 是 100 多秒，而换成 fastjson 解析后是 900 多毫秒。上百倍的性能差距呀，这还是在单用户操作、不能存在 CPU 和内存等资源限制及竞争的情况下拿到的数据。在此向贡献出 fastjson 的阿里人致敬~
5.3. 频繁 GC 的瓶颈已不复存在
针对 TProfiler 帮我们在海量业务代码中定位到的 top5 性能代码进行优化后，部署重新压测，50 个用户并发两个小时左右，我们拉了几次快照，上篇博客中定位的频繁 GC 的性能瓶颈已不复存在，TRT 也由上篇博客优化到的 2.5 降落到 0.5，TPS 基本能稳定在 100 个。问题美满解决。6. 需要注意的1些问题
6.1. TProfiler 端口号是不是已被占用
为 TProfiler 选取端口号之前要先检测1下该端口号是不是已被占用：$ netstat -an | grep 30000
6.2. TProfiler 配置里 includePackageStartsWith
1定要根据你自己的系统进行实际更改，不然就会遇到《TProfiler.log的内容为空 #33》的问题，截图以下：6.3. 几个命令配合使用
在压测的时候，结合使用 start、stop、flushmethod、ProfilerLogAnalysis topmethod 等几个命令，以拿到关键性的结果。如果能再结合 Weblogic、LoadRunner 的启动、停止，效果最好。不然的话，如果 JVM 已跑了很多天，拿到的数据可能不是你想要的，反而会误导你南辕北辙。7. 后记
整体来说，TProfiler 配置部署、远程操作、日志浏览都不太复杂，操作还是很简单的。但是其却是能够起到1针见血、吹糠见米的效果，帮我们解决了 GC 过于频繁的性能瓶颈。TProfiler 最重要的特性就是能够统计出你指定时间段内 JVM 的 topmethod，这些 topmethod 极有可能就是造成你 JVM 性能瓶颈的首恶。这是其他大多数 JVM 调优工具所不具有的，包括 JRockit Mission Control。JRokit 首席开发者 Marcus Hirt 在其私人博客《Low Overhead Method Profiling with Java Mission Control》下的评论中曾明确指出 JRMC 其实不支持 TOP 方法的统计：
最后再次向具有开源精神的阿里技术团队致敬~
参考资料
- TProfiler是1个可以在生产环境长时间使用的性能分析工具
- Low Overhead Method Profiling with Java Mission Control
------分隔线----------------------------
------分隔线----------------------------