不改一行程式碼定位線上效能問題
背景
最近時運不佳，幾乎天天被線上問題騷擾。前幾天剛解決了一個 JVM-concurrent-HashSet-problem/" rel="nofollow,noindex" target="_blank">HashSet 的併發 問題，週六又來了一個性能問題。
大致的現象是：
我們提供出去的一個 OpenAPI 反應時快時慢，快的時候幾十毫秒，慢的時候幾秒鐘才響應。
嘗試解決
由於這種也不是業務問題，不能直接定位。所以嘗試在測試環境復現，但遺憾的測試環境賊快。
沒辦法只能硬著頭皮上了。
中途有抱著僥倖心裡讓運維查看了 Nginx 裡 OpenAPI 的響應時間，想把鍋扔給網路。結果果然打臉了； Nginx 裡的日誌也表明確實響應時間確實有問題。
為了清晰的瞭解這個問題，我簡單梳理了這個呼叫過程。
整個的流程算是比較常見的分層架構：
- 客戶端請求到
Nginx。 -
Nginx負載了後端的web服務。 -
web服務通過RPC呼叫後端的Service服務。
日誌大法
我們首先想到的是打日誌，在可能會慢的方法或介面處記錄處理時間來判斷哪裡有問題。
但通過剛才的呼叫鏈來說，這個請求流程不短。加日誌涉及的改動較多而且萬一加漏了還有可能定位不到問題。
再一個是改動程式碼之後還會涉及到發版上線。
工具分析
所以最好的方式就是不改動一行程式碼把這個問題分析出來。
這時就需要一個 agent 工具了。我們選用了阿里以前開源的 Tprofile 來使用。
只需要在啟動引數中加入 -javaagent:/xx/tprofiler.jar 即可監控你想要監控的方法耗時，並且可以給你輸出報告，非常方便。對程式碼沒有任何侵入性同時效能影響也較小。
工具使用
下面來簡單展示下如何使用這個工具。
首先第一步自然是 clone 原始碼然後打包，可以克隆我修改過的原始碼。
因為這個專案阿里多年沒有維護了，還殘留一些 bug ,我在它原有的基礎上修復了個影響使用的 bug ，同時做了一些優化。
執行以下指令碼即可。
git clone https://github.com/crossoverJie/TProfiler mvn assembly:assembly
到這裡之後會在專案的 TProfiler/pkg/TProfiler/lib/tprofiler-1.0.1.jar 中生成好我們要使用的 jar 包。
接下來只需要將這個 jar 包配置到啟動引數中，同時再配置一個配置檔案路徑即可。
這個配置檔案我 copy 官方的解釋。
#log file name logFileName = tprofiler.log methodFileName = tmethod.log samplerFileName = tsampler.log #basic configuration items # 開始取樣時間 startProfTime = 1:00:00 # 結束取樣時間 endProfTime = 23:00:00 # 取樣的時間長度 eachProfUseTime = 10 # 每次取樣的時間間隔 eachProfIntervalTime = 1 samplerIntervalTime = 20 # 埠，主要不要衝突了 port = 50000 debugMode = false needNanoTime = false # 是否忽略 get set 方法 ignoreGetSetMethod = true #file paths 日誌路徑 logFilePath = /data/work/logs/tprofile/${logFileName} methodFilePath =/data/work/logs/tprofile/${methodFileName} samplerFilePath =/data/work/logs/tprofile/${samplerFileName} #include & excludes items excludeClassLoader = org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader # 需要監控的包 includePackageStartsWith = top.crossoverjie.cicada.example.action # 不需要監控的包 excludePackageStartsWith = com.taobao.sketch;org.apache.velocity;com.alibaba;com.taobao.forest.domain.dataobject
最終的啟動引數如下：
-javaagent:/TProfiler/lib/tprofiler-1.0.1.jar -Dprofile.properties=/TProfiler/profile.properties
為了模擬排查介面響應慢的問題，我用 cicada 實現了一個 HTTP 介面。其中呼叫了兩個耗時方法：
這樣當我啟動應用時， Tprofile 就會在我配置的目錄記錄它所收集的方法資訊。
我訪問介面 http://127.0.0.1:5688/cicada-example/demoAction?name=test&id=10 幾次後它就會把每個方法的明細響應寫入 tprofile.log 。
由左到右每列分別代表為：
執行緒ID、方法棧深度、方法編號、耗時（毫秒）。
但 tmethod.log 還是空的；
這時我們只需要執行這個命令即可把最新的方法取樣資訊刷到 tmethod.log 檔案中。
java -cp /TProfiler/tprofiler.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 50000 flushmethod flushmethod success
其實就是訪問了 Tprofile 暴露出的一個服務，他會讀取、解析 tprofile.log 同時寫入 tmethod.log .
其中的埠就是配置檔案中的 port。
再開啟 tmethod.log ：
其中會記錄方法的資訊。
tprofile.log
其實大部分的效能分析都是統計某個方法的平均耗時。
所以還需要執行下面的命令，通過 tmethod.log tprofile.log 來生成每個方法的平均耗時。
java -cp /TProfiler/tprofiler.jar com.taobao.profile.analysis.ProfilerLogAnalysis tprofiler.log tmethod.log topmethod.log topobject.log print result success
開啟 topmethod.log 就是所有方法的平均耗時。
- 4 為請求次數。
- 205 為平均耗時。
- 818 則為總耗時。
和實際情況是相符的。
方法的明細耗時
這是可能還會有其他需求；比如說我想查詢某個方法所有的明細耗時怎麼辦呢？
官方沒有提供，但也是可以的，只是要麻煩一點。
比如我想檢視 selectDB() 的耗時明細：
首先得知道這個方法的編號，在 tmethod.log 中可以看查到。
2 top/crossoverjie/cicada/example/action/DemoAction:selectDB:84
編號為 2.
之前我們就知道 tprofile.log 記錄的是明細，所以通過下面的命令即可檢視。
grep 2 tprofiler.log
通過第三列方法編號為 2 的來檢視每次執行的明細。
但這樣的方式顯然不夠友好，需要人為來過濾干擾，步驟也多；所以我也準備加上這樣一個功能。
只需要傳入一個方法名稱即可查詢採集到的所有方法耗時明細。
總結
回到之前的問題；線上通過這個工具分析我們得到瞭如下結果。
- 有些方法確實執行時快時慢，但都是和資料庫相關的。由於目前資料庫壓力較大，準備在接下來進行冷熱資料分離，以及分庫分表。
- 在第一步操作還沒實施之前將部分寫資料庫的操作改為非同步，減小響應時間。
- 考慮接入
pinpoint這樣的APM工具。
類似於 Tprofile 的工具確實挺多的，找到適合自己的就好。
在還沒有使用類似於 pinpoint 這樣的分散式跟蹤工具之前應該會大量依賴於這個工具，所以後續說不定也會做一些定製，比如增加一些視覺化介面等，可以提高排查效率。