JVM 性能調(diào)優(yōu)實(shí)戰(zhàn)之：使用阿里開源工具 TProfiler 在海量業(yè)務(wù)代碼中精確定位性能代碼

本文是《JVM 性能調(diào)優(yōu)實(shí)戰(zhàn)之：1次系統(tǒng)性能瓶頸的尋覓進(jìn)程》 的后續(xù)篇，該篇介紹了如何使用 JDK 本身提供的工具進(jìn)行 JVM 調(diào)優(yōu)將 TPS 由 2.5 提升到 20 (提升了 7 倍)，并準(zhǔn)肯定位系統(tǒng)瓶頸：我們利用里靜態(tài)對象不是太多、有大量的業(yè)務(wù)線程在頻繁創(chuàng)建1些生命周期很長的臨時(shí)對象，代碼里有問題。那末問題來了，如何在海量業(yè)務(wù)代碼里邊準(zhǔn)肯定位這些性能代碼？本文將介紹如何使用阿里開源工具 TProfiler 來定位這些性能代碼，成功解決掉了 GC 過于頻繁的性能瓶頸，并終究在上次優(yōu)化的基礎(chǔ)上將 TPS 再提升了4 倍，即提升到 100。

1. TProfiler 的下載安裝

1.1. 下載

訪問 TProfiler 的 GitHub 主頁，點(diǎn)擊 Clone or download 按鈕的打開下載選項(xiàng)，點(diǎn)擊該選項(xiàng)下的 Download ZIP 按鈕將 TProfiler-master.zip 下載到本地。筆者上傳了1份截至 20160920 最新 TProfiler-master.zip 到 CSDN 資源，讀者朋友也能夠去這里下載：http://download.csdn.net/detail/defonds/9635731。

1.2. 安裝

SSH 登錄需要監(jiān)控的遠(yuǎn)程服務(wù)器主機(jī)，為 TProfiler 新建安裝路徑：
$ mkdir /opt/tprofiler
本地將下載后的 TProfiler-master.zip 解緊縮，將 dist 目錄下的 profile.properties 和 dist/lib 目錄下的 tprofiler⑴.0.1.jar ftp 上傳到遠(yuǎn)程服務(wù)器 /opt/tprofiler 目錄下。
最后將遠(yuǎn)程服務(wù)器 /opt/tprofiler 目錄及其下所有文件的所有者改成啟動 Weblogic 進(jìn)程的用戶及其所在用戶組。

2. TProfiler 的配置部署

2.1. TProfiler 配置

編輯服務(wù)器 /opt/tprofiler/profile.properties 文件內(nèi)容以下：
#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
紅色部份是我修改后的內(nèi)容，其它部份使用默許值。

2.2. Weblogic 啟動參數(shù)配置

在 Weblogic JVM 啟動參數(shù)里加入：
-javaagent:/opt/tprofiler/tprofiler⑴.0.1.jar -Dprofile.properties=/opt/tprofiler/profile.properties
以后重啟 Weblogic。

3. TProfiler 的遠(yuǎn)程操作

使用啟動 Weblogic 進(jìn)程的用戶 SSH 遠(yuǎn)程登錄正在進(jìn)行壓測的機(jī)器。

3.1. 查看 TProfiler 當(dāng)前狀態(tài)

$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 status
running
得到這個(gè)結(jié)果證明 TProfiler 正在進(jìn)行收集工作。

3.2. 將 TProfiler 停止，以釋放其占用的系統(tǒng)資源

隨時(shí)關(guān)閉 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
隨時(shí)啟動以繼續(xù)收集：
$ 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. 刷出數(shù)據(jù)

$ java -cp /opt/tprofiler/tprofiler⑴.0.1.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 30000 flushmethod
會將數(shù)據(jù)刷出到 ~/logs/ 目錄下：

4. TProfiler 對性能方法的收集

4.1. 普通方法、線程統(tǒng)計(jì)

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

4.2. top 統(tǒng)計(jì)

$ 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
方法履行時(shí)間統(tǒng)計(jì)：這個(gè)非常非常重要，這個(gè)是 TProfiler 最最重要的 feature，是其能夠傲視所有其他性能測試類(包括 jvm 性能測試類)軟件的關(guān)鍵所在，我們將會不止1次地在關(guān)鍵的時(shí)候受益于 TProfiler 的這1非常有用的特性。
上述命令刷出的 topmethod.log 部份結(jié)果以下：
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
格式說明：方法信息 履行次數(shù) 平均履行時(shí)間 全部履行時(shí)間

5. 性能方法的優(yōu)化

根據(jù) topmethod.log 統(tǒng)計(jì)結(jié)果，我們拿到了熱門方法 top10：

熱門方法 top10

方法名	被調(diào)用次數(shù)	平均履行時(shí)間	采樣內(nèi)總履行時(shí)間
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

這是壓測時(shí)根據(jù)屢次采樣結(jié)果，揀選出的1次比較有代表性的1次。紅色部份值得我們?nèi)ブ攸c(diǎn)關(guān)注并優(yōu)化1下，由于極有可能就是利用瓶頸所在。這些代碼要末是致使平均響應(yīng)時(shí)間低下的1些點(diǎn)，要末是致使大量臨時(shí)對象產(chǎn)生的1些點(diǎn)。
對上篇博客中的結(jié)論，這些代碼的調(diào)優(yōu)原則是：臨時(shí)對象能改成靜態(tài)對象進(jìn)行復(fù)用就改成公用對象，高頻訪問代碼提高響應(yīng)速度。根據(jù) jvm gc 日志發(fā)現(xiàn)很多 young gc 以后堆內(nèi)存已用空間不但降落反而上升至最大使用量致使 full gc，臨時(shí)對象如果可以和其它線程復(fù)用的話改成靜態(tài)對象以減少大量線程 local 對象的產(chǎn)生。
以排名第1的熱門方法 com/defonds/core/ppts/common/support/JsonUtils:object2jsonString:123 為例，看看如何來進(jìn)行調(diào)優(yōu)。

該熱門方法的優(yōu)化建議：
這個(gè)方法平均調(diào)用時(shí)間在 154ms，如果在低并發(fā)時(shí)可能比這要小很多。但是高并發(fā)時(shí)可能要等待 GC 的堆內(nèi)存釋放、GC 作業(yè)時(shí)對業(yè)務(wù)線程釀成的暫停時(shí)間等因素影響，這個(gè)時(shí)間會被無窮放大。

5.1. 臨時(shí)對象改成靜態(tài)對象

object2jsonString 方法的 objectMapper 對象，instanceObjectMapper 方法的 jf 對象；

5.2. json 處理由 jackson 改成 fastjson

jackson 和 spring 整合的很好，提供的功能點(diǎn)很多很強(qiáng)大。但是其性能未必靠得住。
比如我們原來用過谷歌的 Gson 進(jìn)行 json 處理，某個(gè)大對象的 json 解析使用 gson 是 100 多秒，而換成 fastjson 解析后是 900 多毫秒。上百倍的性能差距呀，這還是在單用戶操作、不能存在 CPU 和內(nèi)存等資源限制及競爭的情況下拿到的數(shù)據(jù)。在此向貢獻(xiàn)出 fastjson 的阿里人致敬~

5.3. 頻繁 GC 的瓶頸已不復(fù)存在

針對 TProfiler 幫我們在海量業(yè)務(wù)代碼中定位到的 top5 性能代碼進(jìn)行優(yōu)化后，部署重新壓測，50 個(gè)用戶并發(fā)兩個(gè)小時(shí)左右，我們拉了幾次快照，上篇博客中定位的頻繁 GC 的性能瓶頸已不復(fù)存在，TRT 也由上篇博客優(yōu)化到的 2.5 降落到 0.5，TPS 基本能穩(wěn)定在 100 個(gè)。問題美滿解決。

6. 需要注意的1些問題

6.1. TProfiler 端口號是不是已被占用

為 TProfiler 選取端口號之前要先檢測1下該端口號是不是已被占用：
$ netstat -an | grep 30000

6.2. TProfiler 配置里 includePackageStartsWith 

1定要根據(jù)你自己的系統(tǒng)進(jìn)行實(shí)際更改，不然就會遇到《TProfiler.log的內(nèi)容為空 #33》的問題，截圖以下：

6.3. 幾個(gè)命令配合使用

在壓測的時(shí)候，結(jié)合使用 start、stop、flushmethod、ProfilerLogAnalysis topmethod 等幾個(gè)命令，以拿到關(guān)鍵性的結(jié)果。如果能再結(jié)合 Weblogic、LoadRunner 的啟動、停止，效果最好。不然的話，如果 JVM 已跑了很多天，拿到的數(shù)據(jù)可能不是你想要的，反而會誤導(dǎo)你南轅北轍。

7. 后記

整體來說，TProfiler 配置部署、遠(yuǎn)程操作、日志瀏覽都不太復(fù)雜，操作還是很簡單的。但是其卻是能夠起到1針見血、吹糠見米的效果，幫我們解決了 GC 過于頻繁的性能瓶頸。
TProfiler 最重要的特性就是能夠統(tǒng)計(jì)出你指定時(shí)間段內(nèi) JVM 的 topmethod，這些 topmethod 極有可能就是造成你 JVM 性能瓶頸的首惡。這是其他大多數(shù) JVM 調(diào)優(yōu)工具所不具有的，包括 JRockit Mission Control。JRokit 首席開發(fā)者 Marcus Hirt 在其私人博客《Low Overhead Method Profiling with Java Mission Control》下的評論中曾明確指出 JRMC 其實(shí)不支持 TOP 方法的統(tǒng)計(jì)：

最后再次向具有開源精神的阿里技術(shù)團(tuán)隊(duì)致敬~

參考資料

• TProfiler是1個(gè)可以在生產(chǎn)環(huán)境長時(shí)間使用的性能分析工具
• Low Overhead Method Profiling with Java Mission Control