不改一行代碼定位線上性能問題

背景

最近時運不佳，幾乎每天被線上問題騷擾。前幾天剛解決了一個 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 這樣的分佈式跟蹤工具以前應該會大量依賴於這個工具，因此後續說不定也會作一些定製，好比增長一些可視化界面等，能夠提升排查效率。

你的點贊與分享是對我最大的支持