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

标签: 技术架构 JVM调优 TProfile | 发表时间:2016-11-20 23:28 | 作者:liuchi1993
出处:http://www.importnew.com

本文是《 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: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

这是压测时根据多次采样结果,拣选出的一次比较有代表性的一次。红色部分值得我们去重点关注并优化一下,因为极有可能就是应用瓶颈所在。这些代码要么是导致平均响应时间低下的一些点,要么是导致大量临时对象产生的一些点。
对于上篇博客中的结论,这些代码的调优原则是:临时对象能改成静态对象进行复用就改成公用对象否则要想方设法缩短其生命周期;高频访问代码提高响应速度。根据 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 性能调优实战之:使用阿里开源工具 TProfiler 在海量业务代码中精确定位性能代码

- - ImportNew
本文是《 JVM 性能调优实战之:一次系统性能瓶颈的寻找过程》 的后续篇,该篇介绍了如何使用 JDK 自身提供的工具进行 JVM 调优将 TPS 由 2.5 提升到 20 (提升了 7 倍),并准确定位系统瓶颈:我们应用里静态对象不是太多、有大量的业务线程在频繁创建一些生命周期很长的临时对象,代码里有问题.

JVM性能调优监控工具专题二:VisualVM基本篇之监控JVM内存,CPU,线程

- - ITeye博客
        上一个专题中讲述了JVM中自带的各种性能测试的小工具:包括jps,jstatck,jmap,jhat,jsats,hprof.         这样会造成不必要的麻烦,难道就没有一个tool可以 包括如上所有的功能. 答案是有的,自从 JDK 6 Update 7以后,提供了一全新的性能检测工具:VisualVM,VisualVM对运行中的Java应用提供了可视化的信息展示, 它是很多工具的整合包,整合了JConsole,jstat,jinfo,jstack以及jmap.

JVM性能调优监控工具专题三:VisualVM基本篇之快照分析、监控GC、Eclipse集成

- - 行业应用 - ITeye博客
上一个专题专门举例说明了使用VisualVM进行远程监控以及对Tomcat的远程监控,如果有兴趣,可以查看:. 该专题将讲解如何使用VisualVM生成快照、以及如何对JVM的GC进行监控,最后举例说明如何将VisualVM和eclipse进行集成. 我们可以使用 VisualVM 的快照功能生成任意个性能分析快照并保存到本地来辅助我们进行性能分析.

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

- - ImportNew
玩过性能优化的朋友都清楚,性能优化的关键并不在于怎么进行优化,而在于怎么找到当前系统的性能瓶颈. 性能优化分为好几个层次,比如系统层次、算法层次、代码层次…JVM 的性能优化被认为是底层优化,门槛较高,精通这种技能的人比较少. 笔者呆过几家技术力量不算弱的公司,每个公司内部真正能够进行 JVM 性能调优的人寥寥无几、甚至没有.

HBase性能调优

- - 学着站在巨人的肩膀上
我们经常看到一些文章吹嘘某产品如何如何快,如何如何强,而自己测试时却不如描述的一些数据. 其实原因可能在于你还不是真正理解其内部结构,对于其性能调优方法不够了解. 本文转自TaoBao的Ken Wu同学的博客,是目前看到比较完整的HBase调优文章. 原文链接:HBase性能调优. 因官方Book Performance Tuning部分章节没有按配置项进行索引,不能达到快速查阅的效果.

hbase性能调优

- - 数据库 - ITeye博客
   1)、hbase.regionserver.handler.count:该设置决定了处理RPC的线程数量,默认值是10,通常可以调大,比如:150,当请求内容很大(上MB,比如大的put、使用缓存的scans)的时候,如果该值设置过大则会占用过多的内存,导致频繁的GC,或者出现OutOfMemory,因此该值不是越大越好.

Hadoop性能调优

- - 开源软件 - ITeye博客
是否对任务进行profiling,调用java内置的profile功能,打出相关性能信息. 对几个map或reduce进行profiling. 非常影响速度,建议在小数据量上尝试. 1表示不reuse,-1表示无限reuse,其他数值表示每个jvm reuse次数. reuse的时候,map结束时不会释放内存.

MapReduce - 性能调优

- - CSDN博客云计算推荐文章
        Hadoop为用户作业提供了多种可配置的参数,以允许用户根据作业特点调整这些参数值使作业运行效率达到最优.         对于一大批MapReduce程序,如果可以设置一个Combiner,那么对于提高作业性能是十分有帮助的. Combiner可减少Map Task中间输出的结果,从而减少各个Reduce Task的远程拷贝数据量,最终表现为Map Task和Reduce Task执行时间缩短.

Java 性能调优

- - 编程语言 - ITeye博客
1.用new关键词创建类的实例时,构造函数链中的所有构造函数都会被自动调用. 但如果一个对象实现了Cloneable接口,我们可以调用它的clone()方法. clone()方法不会调用任何类构造函数. 在使用设计模式(Design Pattern)的场合,如果用Factory模式创建对象,则改用clone()方法创建新的对象实例非常简单.

Spark性能调优

- - zzm
通常我们对一个系统进行性能优化无怪乎两个步骤——性能监控和参数调整,本文主要分享的也是这两方面内容. Spark提供了一些基本的Web监控页面,对于日常监控十分有用. http://master:4040(默认端口是4040,可以通过spark.ui.port修改)可获得这些信息:(1)stages和tasks调度情况;(2)RDD大小及内存使用;(3)系统环境信息;(4)正在执行的executor信息.