摘要：背景最近時(shí)運(yùn)不佳，幾乎天天被線上問(wèn)題騷擾。工具分析所以最好的方式就是不改動(dòng)一行代碼把這個(gè)問(wèn)題分析出來(lái)。我們選用了阿里以前開(kāi)源的來(lái)使用。因?yàn)檫@個(gè)項(xiàng)目阿里多年沒(méi)有維護(hù)了，還殘留一些我在它原有的基礎(chǔ)上修復(fù)了個(gè)影響使用的，同時(shí)做了一些優(yōu)化。

最近時(shí)運(yùn)不佳，幾乎天天被線上問(wèn)題騷擾。前幾天剛解決了一個(gè) HashSet 的并發(fā)問(wèn)題，周六又來(lái)了一個(gè)性能問(wèn)題。

大致的現(xiàn)象是：

我們提供出去的一個(gè) OpenAPI 反應(yīng)時(shí)快時(shí)慢，快的時(shí)候幾十毫秒，慢的時(shí)候幾秒鐘才響應(yīng)。

由于這種也不是業(yè)務(wù)問(wèn)題，不能直接定位。所以嘗試在測(cè)試環(huán)境復(fù)現(xiàn)，但遺憾的測(cè)試環(huán)境賊快。

沒(méi)辦法只能硬著頭皮上了。

中途有抱著僥幸心里讓運(yùn)維查看了 Nginx 里 OpenAPI 的響應(yīng)時(shí)間，想把鍋扔給網(wǎng)絡(luò)。結(jié)果果然打臉了；Nginx 里的日志也表明確實(shí)響應(yīng)時(shí)間確實(shí)有問(wèn)題。

為了清晰的了解這個(gè)問(wèn)題，我簡(jiǎn)單梳理了這個(gè)調(diào)用過(guò)程。

整個(gè)的流程算是比較常見(jiàn)的分層架構(gòu)：

客戶端請(qǐng)求到 Nginx。

Nginx 負(fù)載了后端的 web 服務(wù)。

web 服務(wù)通過(guò) RPC 調(diào)用后端的 Service 服務(wù)。

我們首先想到的是打日志，在可能會(huì)慢的方法或接口處記錄處理時(shí)間來(lái)判斷哪里有問(wèn)題。

但通過(guò)剛才的調(diào)用鏈來(lái)說(shuō)，這個(gè)請(qǐng)求流程不短。加日志涉及的改動(dòng)較多而且萬(wàn)一加漏了還有可能定位不到問(wèn)題。

再一個(gè)是改動(dòng)代碼之后還會(huì)涉及到發(fā)版上線。

所以最好的方式就是不改動(dòng)一行代碼把這個(gè)問(wèn)題分析出來(lái)。

這時(shí)就需要一個(gè) agent 工具了。我們選用了阿里以前開(kāi)源的 Tprofile 來(lái)使用。

只需要在啟動(dòng)參數(shù)中加入 -javaagent:/xx/tprofiler.jar 即可監(jiān)控你想要監(jiān)控的方法耗時(shí)，并且可以給你輸出報(bào)告，非常方便。對(duì)代碼沒(méi)有任何侵入性同時(shí)性能影響也較小。

下面來(lái)簡(jiǎn)單展示下如何使用這個(gè)工具。

首先第一步自然是 clone 源碼然后打包，可以克隆我修改過(guò)的源碼。

因?yàn)檫@個(gè)項(xiàng)目阿里多年沒(méi)有維護(hù)了，還殘留一些 bug,我在它原有的基礎(chǔ)上修復(fù)了個(gè)影響使用的 bug，同時(shí)做了一些優(yōu)化。

執(zhí)行以下腳本即可。

git clone https://github.com/crossoverJie/TProfiler

mvn assembly:assembly

到這里之后會(huì)在項(xiàng)目的 TProfiler/pkg/TProfiler/lib/tprofiler-1.0.1.jar 中生成好我們要使用的 jar 包。

接下來(lái)只需要將這個(gè) jar 包配置到啟動(dòng)參數(shù)中，同時(shí)再配置一個(gè)配置文件路徑即可。

這個(gè)配置文件我 copy 官方的解釋。

#log file name
logFileName = tprofiler.log
methodFileName = tmethod.log
samplerFileName = tsampler.log

#basic configuration items
# 開(kāi)始取樣時(shí)間
startProfTime = 1:00:00

# 結(jié)束取樣時(shí)間
endProfTime = 23:00:00

# 取樣的時(shí)間長(zhǎng)度
eachProfUseTime = 10

# 每次取樣的時(shí)間間隔
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

# 需要監(jiān)控的包
includePackageStartsWith = top.crossoverjie.cicada.example.action

# 不需要監(jiān)控的包
excludePackageStartsWith = com.taobao.sketch;org.apache.velocity;com.alibaba;com.taobao.forest.domain.dataobject

最終的啟動(dòng)參數(shù)如下：

-javaagent:/TProfiler/lib/tprofiler-1.0.1.jar
-Dprofile.properties=/TProfiler/profile.properties

為了模擬排查接口響應(yīng)慢的問(wèn)題，我用 cicada 實(shí)現(xiàn)了一個(gè) HTTP 接口。其中調(diào)用了兩個(gè)耗時(shí)方法：

這樣當(dāng)我啟動(dòng)應(yīng)用時(shí)，Tprofile 就會(huì)在我配置的目錄記錄它所收集的方法信息。

我訪問(wèn)接口 http://127.0.0.1:5688/cicada-example/demoAction?name=test&id=10 幾次后它就會(huì)把每個(gè)方法的明細(xì)響應(yīng)寫(xiě)入 tprofile.log。

由左到右每列分別代表為：

線程ID、方法棧深度、方法編號(hào)、耗時(shí)（毫秒）。

但 tmethod.log 還是空的；

這時(shí)我們只需要執(zhí)行這個(gè)命令即可把最新的方法采樣信息刷到 tmethod.log 文件中。

java -cp /TProfiler/tprofiler.jar com.taobao.profile.client.TProfilerClient 127.0.0.1 50000 flushmethod

flushmethod success

其實(shí)就是訪問(wèn)了 Tprofile 暴露出的一個(gè)服務(wù)，他會(huì)讀取、解析 tprofile.log 同時(shí)寫(xiě)入 tmethod.log.

其中的端口就是配置文件中的 port。

再打開(kāi) tmethod.log ：

其中會(huì)記錄方法的信息。

第一行數(shù)字為方法的編號(hào)?？梢酝ㄟ^(guò)這個(gè)編號(hào)去 tprofile.log(明細(xì))中查詢每次的耗時(shí)情況。

行末的數(shù)字則是這個(gè)方法在源碼中最后一行的行號(hào)。

其實(shí)大部分的性能分析都是統(tǒng)計(jì)某個(gè)方法的平均耗時(shí)。

所以還需要執(zhí)行下面的命令，通過(guò) tmethod.log tprofile.log 來(lái)生成每個(gè)方法的平均耗時(shí)。

java -cp /TProfiler/tprofiler.jar com.taobao.profile.analysis.ProfilerLogAnalysis tprofiler.log tmethod.log topmethod.log topobject.log
print result success

打開(kāi) topmethod.log 就是所有方法的平均耗時(shí)。

4 為請(qǐng)求次數(shù)。

205 為平均耗時(shí)。

818 則為總耗時(shí)。

和實(shí)際情況是相符的。

這是可能還會(huì)有其他需求；比如說(shuō)我想查詢某個(gè)方法所有的明細(xì)耗時(shí)怎么辦呢？

官方?jīng)]有提供，但也是可以的，只是要麻煩一點(diǎn)。

比如我想查看 selectDB() 的耗時(shí)明細(xì)：

首先得知道這個(gè)方法的編號(hào)，在 tmethod.log 中可以看查到。

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

編號(hào)為 2.

之前我們就知道 tprofile.log 記錄的是明細(xì)，所以通過(guò)下面的命令即可查看。

grep 2 tprofiler.log

通過(guò)第三列方法編號(hào)為 2 的來(lái)查看每次執(zhí)行的明細(xì)。

但這樣的方式顯然不夠友好，需要人為來(lái)過(guò)濾干擾，步驟也多；所以我也準(zhǔn)備加上這樣一個(gè)功能。

只需要傳入一個(gè)方法名稱(chēng)即可查詢采集到的所有方法耗時(shí)明細(xì)。

回到之前的問(wèn)題；線上通過(guò)這個(gè)工具分析我們得到了如下結(jié)果。

有些方法確實(shí)執(zhí)行時(shí)快時(shí)慢，但都是和數(shù)據(jù)庫(kù)相關(guān)的。由于目前數(shù)據(jù)庫(kù)壓力較大，準(zhǔn)備在接下來(lái)進(jìn)行冷熱數(shù)據(jù)分離，以及分庫(kù)分表。

在第一步操作還沒(méi)實(shí)施之前將部分寫(xiě)數(shù)據(jù)庫(kù)的操作改為異步，減小響應(yīng)時(shí)間。

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

類(lèi)似于 Tprofile 的工具確實(shí)挺多的，找到適合自己的就好。

在還沒(méi)有使用類(lèi)似于 pinpoint 這樣的分布式跟蹤工具之前應(yīng)該會(huì)大量依賴(lài)于這個(gè)工具，所以后續(xù)說(shuō)不定也會(huì)做一些定制，比如增加一些可視化界面等，可以提高排查效率。

你的點(diǎn)贊與分享是對(duì)我最大的支持