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

背景
最近時運不佳，幾乎每天被線上問題騷擾。前幾天剛解決了一個 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.00.1 50000 flushmethod  flushmethod success
 128.

其實就是訪問了 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.logprint result success

打開 topmethod.log 就是全部方法的平均耗時。

• 4 爲請求次數。

• 205 爲平均耗時。

• 818 則爲總耗時。

和實際狀況是相符的。

方法的明細耗時
這是可能還會有其餘需求；好比說我想查詢某個方法全部的明細耗時怎麼辦呢？

官方沒有提供，但也是能夠的，只是要麻煩一點。

好比我想查看 selectDB() 的耗時明細：

首先得知道這個方法的編號，在 tmethod.log 中能夠看查到。

2top/crossoverjie/cicada/example/action/DemoAction:selectDB:84

編號爲 2.

以前咱們就知道 tprofile.log 記錄的是明細，因此經過下面的命令便可查看。

grep 2 tprofiler.log

經過第三列方法編號爲 2 的來查看每次執行的明細。

但這樣的方式顯然不夠友好，須要人爲來過濾干擾，步驟也多；因此我也準備加上這樣一個功能。

只須要傳入一個方法名稱便可查詢採集到的全部方法耗時明細。

總結
回到以前的問題；線上經過這個工具分析咱們獲得了以下結果。

• 有些方法確實執行時快時慢，但都是和數據庫相關的。因爲目前數據庫壓力較大，準備在接下來進行冷熱數據分離，以及分庫分表。

• 在第一步操做還沒實施以前將部分寫數據庫的操做改成異步，減少響應時間。

• 考慮接入 pinpoint 這樣的 APM工具。

相似於 Tprofile 的工具確實挺多的，找到適合本身的就好。

在尚未使用相似於 pinpoint 這樣的分佈式跟蹤工具以前應該會大量依賴於這個工具，因此後續說不定也會作一些定製，好比增長一些可視化界面等，能夠提升排查效率。

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