本文是《JVM 性能調優實戰之：一次系統性能瓶頸的尋找過程》 的後續篇，該篇介紹瞭如何使用 JDK 自身提供的工具進行 JVM 調優將 TPS 由 2.5 提高到 20 (提高了 7 倍)，並準肯定位系統瓶頸：咱們應用裏靜態對象不是太多、有大量的業務線程在頻繁建立一些生命週期很長的臨時對象，代碼裏有問題。那麼問題來了，如何在海量業務代碼裏邊準肯定位這些性能代碼？本文將介紹如何使用阿里開源工具 TProfiler 來定位這些性能代碼，成功解決掉了 GC 過於頻繁的性能瓶頸，並最終在上次優化的基礎上將 TPS 再提高了4 倍，即提高到 100。java
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。spring
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 進程的用戶及其所在用戶組。apache
2. TProfiler 的配置部署
2.1. TProfiler 配置
編輯服務器 /opt/tprofiler/profile.properties 文件內容以下：
#log file name
logFileName = tprofiler.log
methodFileName = tmethod.log
samplerFileName = tsampler.logjson
#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}mybatis
#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。app
3. TProfiler 的遠程操做
使用啓動 Weblogic 進程的用戶 SSH 遠程登陸正在進行壓測的機器。dom
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 正在進行採集工做。eclipse
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/ 目錄下：
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》的問題，截圖以下：
6.3. 採樣時間是否在配置的統計時間以內
在確認 6.2 裏注意的事情無誤的狀況下，獲得的 tprofiler.log 仍然爲空 (只有 = 號) 的話，請檢測你的採樣時間是否在 profile.properties 裏定義的 startProfTime 和 endProfTime 時間段以內。
6.4. 幾個命令配合使用
在壓測的時候，結合使用 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 方法的統計：
最後再次向具有開源精神的阿里技術團隊致敬~
參考資料TProfiler是一個能夠在生產環境長期使用的性能分析工具Low Overhead Method Profiling with Java Mission Control--------------------- 做者：Defonds 來源：CSDN 原文：https://blog.csdn.net/defonds/article/details/52605670