JVM 性能调优实战之:使用阿里开源工具 TProfiler 在海量业务代码中精确定位性能代码

原创 2016年09月21日 11:25:21
本文是《JVM 性能调优实战之:一次系统性能瓶颈的寻找过程》 的后续篇,该篇介绍了如何使用 JDK 自身提供的工具进行 JVM 调优将 TPS 由 2.5 提升到 20 (提升了 7 倍),并准确定位系统瓶颈:我们应用里静态对象不是太多、有大量的业务线程在频繁创建一些生命周期很长的临时对象,代码里有问题。那么问题来了,如何在海量业务代码里边准确定位这些性能代码?本文将介绍如何使用阿里开源工具 TProfiler 来定位这些性能代码,成功解决掉了 GC 过于频繁的性能瓶颈,并最终在上次优化的基础上将 TPS 再提升了4 倍,即提升到 100。

1. TProfiler 的下载安装

1.1. 下载

访问 TProfiler 的 GitHub 主页,点击 Clone or download 按钮的打开下载选项,点击该选项下的 Download ZIP 按钮将 TProfiler-master.zip 下载到本地。笔者上传了一份截至 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-1.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-1.0.1.jar -Dprofile.properties=/opt/tprofiler/profile.properties
之后重启 Weblogic。

3. TProfiler 的远程操作

使用启动 Weblogic 进程的用户 SSH 远程登录正在进行压测的机器。

3.1. 查看 TProfiler 当前状态

$ java -cp /opt/tprofiler/tprofiler-1.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 status
running
得到这个结果证明 TProfiler 正在进行采集工作。

3.2. 将 TProfiler 停止,以释放其占用的系统资源

随时关闭 TProfiler:
$ java -cp /opt/tprofiler/tprofiler-1.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 stop
$ java -cp /opt/tprofiler/tprofiler-1.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 status
stop
随时启动以继续采集:
$ java -cp /opt/tprofiler/tprofiler-1.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 start
$ java -cp /opt/tprofiler/tprofiler-1.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 status
running

3.3. 刷出数据

$ java -cp /opt/tprofiler/tprofiler-1.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 flushmethod
会将数据刷出到 ~/logs/ 目录下:
TProfiler的日志.png

4. TProfiler 对性能方法的采集

4.1. 普通方法、线程统计

$ java -cp /opt/tprofiler/tprofiler-1.0.1.jar com.taobao.profile.analysis.SamplerLogAnalysis ~/logs/tsampler.log ~/logs/method.log ~/logs/thread.log

4.2. top 统计

$ java -cp /opt/tprofiler/tprofiler-1.0.1.jar com.taobao.profile.analysis.ProfilerLogAnalysis ~/logs/tprofiler.log ~/logs/tmethod.log ~/logs/topmethod.log ~/logs/topobject.log
方法执行时间统计:这个非常非常重要,这个是 TProfiler 最最重要的 feature,是其能够傲视所有其他性能测试类(包括 jvm 性能测试类)软件的关键所在,我们将会不止一次地在关键的时候受益于 TProfiler 的这一非常有用的特性。
上述命令刷出的 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

格式说明:方法信息 执行次数 平均执行时间(单位:ms) 全部执行时间(单位:ms)

5. 性能方法的优化

根据 topmethod.log 统计结果,我们拿到了热点方法 top10:
热点方法 top10
方法名被调用次数平均执行时间(ms)采样内总执行时间(ms)
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:725421315799322
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>:76621926163741
com/fasterxml/jackson/databind/ser/impl/IndexedListSerializer:serializeContents:107518833145556
com/defonds/core/ppts/cache/biz/cims/impl/AccountPrdAndBankCacheImpl:selectBasicProductCfg:144161318137029
com/defonds/core/ppts/common/jms/retrieve/listener/DefaultMessageListener:handleMessage:64298146136180
com/fasterxml/jackson/databind/ser/BeanPropertyWriter:serializeAsField:573538922112553

这是压测时根据多次采样结果,拣选出的一次比较有代表性的一次。红色部分值得我们去重点关注并优化一下,因为极有可能就是应用瓶颈所在。这些代码要么是导致平均响应时间低下的一些点,要么是导致大量临时对象产生的一些点。
对于上篇博客中的结论,这些代码的调优原则是:临时对象能改成静态对象进行复用就改成公用对象否则要想方设法缩短其生命周期;高频访问代码提高响应速度。根据 jvm gc 日志发现很多 young gc 之后堆内存已用空间不仅下降反而上升至最大使用量导致 full gc,临时对象如果可以和其它线程复用的话改成静态对象以减少大量线程 local 对象的产生。
以排名第一的热点方法 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. 需要注意的一些问题

6.1. TProfiler 端口号是否已被占用

为 TProfiler 选取端口号之前要先检测一下该端口号是否已被占用:
$ netstat -an | grep 30000

6.2. TProfiler 配置里 includePackageStartsWith 

一定要根据你自己的系统进行实际更改,不然就会遇到《TProfiler.log的内容为空 #33》的问题,截图如下:
TProfiler.log的内容为空.png

6.3. 几个命令配合使用

在压测的时候,结合使用 start、stop、flushmethod、ProfilerLogAnalysis topmethod 等几个命令,以拿到关键性的结果。如果能再结合 Weblogic、LoadRunner 的启动、停止,效果最佳。不然的话,如果 JVM 已经跑了很多天,拿到的数据可能不是你想要的,反而会误导你南辕北辙。

7. 后记

总体来讲,TProfiler 配置部署、远程操作、日志阅读都不太复杂,操作还是很简单的。但是其却是能够起到一针见血、立竿见影的效果,帮我们解决了 GC 过于频繁的性能瓶颈。
TProfiler 最重要的特性就是能够统计出你指定时间段内 JVM 的 topmethod,这些 topmethod 极有可能就是造成你 JVM 性能瓶颈的元凶。这是其他大多数 JVM 调优工具所不具备的,包括 JRockit Mission Control。JRokit 首席开发者 Marcus Hirt 在其私人博客《Low Overhead Method Profiling with Java Mission Control》下的评论中曾明确指出 JRMC 并不支持 TOP 方法的统计:
JRMC并不支持TOP方法的统计.png
最后再次向具备开源精神的阿里技术团队致敬~

参考资料

版权声明:本文为博主原创文章,未经博主允许不得转载。

相关文章推荐

JVM运行数据区和常用的JVM工具的使用

先说说JVM(Java虚拟机)吧。话说是一个运行平台。在编译器编译产生的class文件会在JVM中被加载和解释执行的。JVM有许多种,早期的是SUN classic VM之后出现hotspot和BEA...

JProfiler 监控Tomcat

介绍JProfiler是一个全功能的Java剖析工具(profiler),专用于分析J2SE和J2EE应用程序。JProfiler是一个商业授权的Java剖析工具,由EJ技术有限公司,针对Java E...
  • catoop
  • catoop
  • 2015年09月26日 22:21
  • 10604

【入门篇】TProfiler工具使用

1、TProfiler下载与安装 第一步先去Github https://github.com/taobao/TProfiler下载源文件,接着将下载好的TProfiler-master.zip解压...

淘宝Tprofiler工具实现分析

工具介绍 TProfiler是一个可以在生产环境长期使用的性能分析工具.它同时支持剖析和采样两种方式,记录方法执行的时间和次数,生成方法热点 对象创建热点 线程状态分析等数据,为查找系统性能瓶颈提供...

淘宝tprofiler使用说明

下载tporfiler https://codeload.github.com/alibaba/TProfiler/zip/master 下载完成,TProfiler-master.zip 。有...
  • wh0426
  • wh0426
  • 2016年07月22日 13:54
  • 2293

淘宝的TProfiler使用日记

因为最近做项目迁移,迁移之后发现有些地方竟然变慢了!需要一个好的Profiler工具,定位最为耗时的地方。在翻淘宝中间件团队博客http://rdc.taobao.com/team/jm/ 的时候发现...

TProfiler日志分析

原文地址:https://github.com/alibaba/TProfiler/wiki/TProfiler日志分析 tprofiler.log文件格式说明: 线程ID 线程栈深度 方法ID...

TProfiler配置部署

原文地址:https://github.com/alibaba/TProfiler/wiki/TProfiler配置部署 打包 下载源码,在根目录运行package.bat脚本或者执行mvn a...

JVM 性能调优实战之:一次系统性能瓶颈的寻找过程

玩过性能优化的朋友都清楚,性能优化的关键并不在于怎么进行优化,而在于怎么找到当前系统的性能瓶颈。性能优化分为好几个层次,比如系统层次、算法层次、代码层次...JVM 的性能优化被认为是底层优化,门槛较...
  • defonds
  • defonds
  • 2016年09月20日 17:39
  • 21692

JVM 优化实战

本文讲解了 JVM 的内存划分和分配策略,并以截图和脚本展示常用可视化和命令行工具的使用方法,完整演示了 JVM 优化、内存泄露排查、gc.log 分析方法等。...
内容举报
返回顶部
收藏助手
不良信息举报
您举报文章:JVM 性能调优实战之:使用阿里开源工具 TProfiler 在海量业务代码中精确定位性能代码
举报原因:
原因补充:

(最多只允许输入30个字)