深入剖析：如何使用Pulsar和Arthas高效排查消息隊(duì)列延遲問題

作者：crossoverJie 2024-04-30 08:09:10

開發(fā) 前端

根據(jù)之前的經(jīng)驗(yàn)來看，要么是業(yè)務(wù)消費(fèi)邏輯出現(xiàn)問題導(dǎo)致消費(fèi)過慢，當(dāng)然也有小概率是消息隊(duì)列的 Bug（我們使用的是 pulsar）。

背景

前兩天收到業(yè)務(wù)反饋有一個(gè) topic 的分區(qū)消息堆積了：

圖片

排查

圖片

通過排查，發(fā)現(xiàn)確實(shí)是在一點(diǎn)多的時(shí)候消息堆積了（后面是修復(fù)之后堆積開始下降）。

于是我在剛才堆積處查看了一條堆積消息的列表：

圖片

獲取到其中一條消息的 messageId.

這里本質(zhì)上使用的是 pulsar-admin 的 API。org.apache.pulsar.client.admin.Topics#peekMessages

圖片

再通過這條消息的 id （為了演示，這里的 messageId 可能不一樣）在我們的 pulsar 消息鏈路系統(tǒng)中找到了消息的發(fā)送鏈路：

圖片

通過這個(gè)鏈路會(huì)發(fā)現(xiàn)消息一直在推送，但就是沒有收到客戶端的 ACK 響應(yīng)。

相關(guān)的消息鏈路埋點(diǎn)可以參考這里：如何編寫一個(gè) Pulsar Broker Interceptor 插件

簡(jiǎn)單來說就是在以下幾個(gè) broker 提供的攔截器接口加上埋點(diǎn)數(shù)據(jù)即可：

messageProduced
messageDispatched
messageAcked

既然知道了是客戶端沒有響應(yīng) ACK，那就得知道客戶端此時(shí)在干什么。

首先排查了 JVM 內(nèi)存、CPU 等監(jiān)控情況，發(fā)現(xiàn)一切都挺正常的，這段時(shí)間沒有明顯的尖刺。

Arthas 排查

于是便準(zhǔn)備使用 arthas 查看下線程的運(yùn)行情況。

我們進(jìn)入到對(duì)應(yīng) Pod 的容器，執(zhí)行：

java -jar arthas-boot.jar

因?yàn)?JVM 內(nèi)存都沒有啥異常，所以先看看 thread 的運(yùn)行堆棧，考慮到是 pulsar 消費(fèi)線程卡住了，所以我們需要加上線程狀態(tài)已經(jīng)過濾下線程的名稱：

圖片

thread --state WAITING | grep pulsar

此時(shí)就會(huì)列出當(dāng)前 Java 進(jìn)程中狀態(tài)為 WATING 并且線程名稱以 pulsar 開頭的線程。

我在之前的文章從 Pulsar Client 的原理到它的監(jiān)控面板中分析過客戶端的原理。

圖片

可以知道 pulsar 客戶端在其中使用的是 pulsar-打頭的線程名稱，所以這樣就列出了我們需要重點(diǎn)關(guān)注的線程。

我們以圖中列出的線程 Id：320 為例：

thread 320

圖片

此時(shí)便會(huì)打印當(dāng)前線程的堆棧。

從上述堆棧中會(huì)發(fā)現(xiàn)線程一直處于 IO 操作中，看起來是在操作數(shù)據(jù)庫。

我們?cè)偻路环?，?huì)發(fā)現(xiàn)上層調(diào)用的業(yè)務(wù)代碼：

圖片

查閱代碼得知這是一個(gè)數(shù)據(jù)庫的寫入操作，看起來是在這個(gè)環(huán)節(jié)數(shù)據(jù)庫響應(yīng)過慢導(dǎo)致的 pulsar 線程被阻塞了；從而導(dǎo)致消息沒有及時(shí) ACK。

為了最終確認(rèn)是否由數(shù)據(jù)庫引起的，于是繼續(xù)查詢了當(dāng)前應(yīng)用的慢 SQL 情況：

圖片

發(fā)現(xiàn)其中有一個(gè)查詢語句調(diào)用頻次和平均耗時(shí)都比較高，而且正好這個(gè)表也是剛才在堆棧里操作的那張表。

經(jīng)過業(yè)務(wù)排查發(fā)現(xiàn)這個(gè)慢 SQL 是由一個(gè)定時(shí)任務(wù)觸發(fā)的，而這個(gè)定時(shí)任務(wù)由于某些原因一直也沒有停止，所以為了快速解決這個(gè)問題，我們先嘗試將這個(gè)定時(shí)任務(wù)停掉。

果然停掉沒多久后消息就開始快速消費(fèi)了：

圖片

從這個(gè)時(shí)間線也可以看得出來了，在服務(wù)端推送了多次之后終于收到了 ACK。

修復(fù)之后業(yè)務(wù)再去排查優(yōu)化這個(gè)慢 SQL，這樣這個(gè)問題就得到根本的解決了。

火焰圖

profile：可以輸出火焰圖，在做性能分析的時(shí)候非常有用。

圖片

動(dòng)態(tài)修改內(nèi)存數(shù)據(jù)

還記得之前我們碰到過一個(gè) pulsar 刪除 topic 的 Bug，雖然最終修復(fù)了問題，但是在發(fā)布修復(fù)版本的時(shí)候?yàn)榱吮苊庠俅斡|發(fā)老版本的 bug，需要在內(nèi)存中將某個(gè)關(guān)鍵字段的值修改掉。

而且是不能重啟應(yīng)用的情況下修改，此時(shí)使用 arthas 就非常的方便：

curl -O https://arthas.aliyun.com/arthas-boot.jar && java -jar arthas-boot.jar 1 -c "vmtool -x 3 --action getInstances --className org.apache.pulsar.broker.ServiceConfiguration  --express 'instances[0].setTopicLevelPoliciesEnabled(false)'"

這里使用的是 vmtool 這個(gè)子命令來獲取對(duì)象，最終再使用 express 表達(dá)式將其中的值改為了 false。

當(dāng)然這是一個(gè)高危操作，不到萬不得已不推薦這么使用。

Arthas Tunnel & Web Console

這是一個(gè)方便開發(fā)者通過網(wǎng)頁就可以連接到 arthas 的功能，避免直接登錄到服務(wù)器進(jìn)行操作。

圖片

我們?cè)谘行胀ㄒ矁?nèi)置了該功能，讓開發(fā)排查問題更加方便。

CPU 使用過多

cpu 異常使用排查也是一個(gè)非常有用的功能，雖然我們可以通過監(jiān)控得知 JVM 的 cpu 使用情況，但是沒法知道具體是哪個(gè)線程以及哪行代碼造成的 cpu 過高。

thread -n 3

圖片

使用以上命令就可以將 cpu 排名前三的線程打印出來，并且列出他的堆棧情況，這樣可以很直觀的得知 cpu 消耗了在哪些地方了。

當(dāng)然還有一些 trace 查詢：

trace demo.MathGame run '#cost > 10'

比如這是將調(diào)用超過 10ms 的函數(shù)打印出來，不過如果我們接入了可觀測(cè)系統(tǒng)（OpenTelemetry、skywalking等）這個(gè)功能就用不太上了。

還可以在運(yùn)行的時(shí)候不停機(jī)修改日志級(jí)別，這種在線上排查一些疑難雜癥的時(shí)候非常好用（通常情況下 debug 日志是不打印的），我們可以將日志級(jí)別調(diào)整為 debug 打印出更加詳細(xì)的信息：

[arthas@2062]$ logger --name ROOT --level debug
update logger level success.

如果是在 kubernetes 環(huán)境中執(zhí)行也有可能碰到 Java 進(jìn)程啟動(dòng)后沒有在磁盤中寫入 PID 的情況：

$ java -jar arthas-boot.jar  
[INFO] arthas-boot version: 3.6.7  
[INFO] Can not find java process. Try to pass <pid> in command line.  
Please select an available pid.

導(dǎo)致直接運(yùn)行的時(shí)候無法找到 Java 進(jìn)程；此時(shí)就需要先 ps 拿到 PID 之后再傳入 PID 連入 arthas：