不改一行程式碼定位線上效能問題

crossoverJie發表於2019-03-03
行程

背景

最近時運不佳，幾乎天天被線上問題騷擾。前幾天剛解決了一個 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 這樣的分散式跟蹤工具之前應該會大量依賴於這個工具，所以後續說不定也會做一些定製，比如增加一些視覺化介面等，可以提高排查效率。

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

不改一行程式碼定位線上效能問題

相關文章