背景
前兩天收到業務反饋有一個 topic 的分割槽訊息堆積了：
根據之前的經驗來看，要麼是業務消費邏輯出現問題導致消費過慢，當然也有小機率是訊息佇列的 Bug（我們使用的是 pulsar）。
排查
透過排查，發現確實是在一點多的時候訊息堆積了（後面是修復之後堆積開始下降）。
於是我在剛才堆積處檢視了一條堆積訊息的列表：
獲取到其中一條訊息的 messageId.
這裡本質上使用的是 pulsar-admin 的 API。
org.apache.pulsar.client.admin.Topics#peekMessages
再透過這條訊息的 id （為了演示，這裡的 messageId 可能不一樣）在我們的 pulsar 訊息鏈路系統中找到了訊息的傳送鏈路：
透過這個鏈路會發現訊息一直在推送，但就是沒有收到客戶端的 ACK 響應。
相關的訊息鏈路埋點可以參考這裡：如何編寫一個 Pulsar Broker Interceptor 外掛
簡單來說就是在以下幾個 broker 提供的攔截器介面加上埋點資料即可：
- messageProduced
- messageDispatched
- messageAcked
既然知道了是客戶端沒有響應 ACK，那就得知道客戶端此時在幹什麼。
首先排查了 JVM 記憶體、CPU 等監控情況，發現一切都挺正常的，這段時間沒有明顯的尖刺。
Arthas 排查
於是便準備使用 arthas 檢視下執行緒的執行情況。
我們進入到對應 Pod 的容器，執行：
java -jar arthas-boot.jar
因為 JVM 記憶體都沒有啥異常，所以先看看 thread 的執行堆疊，考慮到是 pulsar 消費執行緒卡住了，所以我們需要加上執行緒狀態已經過濾下執行緒的名稱：
thread --state WAITING | grep pulsar
此時就會列出當前 Java 程序中狀態為 WATING 並且執行緒名稱以 pulsar 開頭的執行緒。
我在之前的文章 從 Pulsar Client 的原理到它的監控皮膚 中分析過客戶端的原理。
可以知道 pulsar 客戶端在其中使用的是 pulsar-打頭的執行緒名稱，所以這樣就列出了我們需要重點關注的執行緒。
我們以圖中列出的執行緒 Id：320 為例：
thread 320
此時便會列印當前執行緒的堆疊。
從上述堆疊中會發現執行緒一直處於 IO 操作中，看起來是在運算元據庫。
我們再往下翻一翻，會發現上層呼叫的業務程式碼：
查閱程式碼得知這是一個資料庫的寫入操作，看起來是在這個環節資料庫響應過慢導致的 pulsar 執行緒被阻塞了；從而導致訊息沒有及時 ACK。
為了最終確認是否由資料庫引起的，於是繼續查詢了當前應用的慢 SQL 情況：
發現其中有一個查詢語句呼叫頻次和平均耗時都比較高，而且正好這個表也是剛才在堆疊裡操作的那張表。
經過業務排查發現這個慢 SQL 是由一個定時任務觸發的，而這個定時任務由於某些原因一直也沒有停止，所以為了快速解決這個問題，我們先嚐試將這個定時任務停掉。
果然停掉沒多久後訊息就開始快速消費了：
從這個時間線也可以看得出來了，在服務端推送了多次之後終於收到了 ACK。
修復之後業務再去排查最佳化這個慢 SQL，這樣這個問題就得到根本的解決了。
更多好用技巧
當然 arthas 好用的功能還遠不止此，我覺得還有以下功能比較好用：
火焰圖
profile：可以輸出火焰圖，在做效能分析的時候非常有用。
動態修改記憶體資料
還記得之前我們碰到過一個 pulsar 刪除 topic 的 Bug，雖然最終修復了問題，但是在釋出修復版本的時候為了避免再次觸發老版本的 bug，需要在記憶體中將某個關鍵欄位的值修改掉。
而且是不能重啟應用的情況下修改，此時使用 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 這個子命令來獲取物件，最終再使用 express 表示式將其中的值改為了 false。
當然這是一個高危操作，不到萬不得已不推薦這麼使用。
Arthas Tunnel & Web Console
這是一個方便開發者透過網頁就可以連線到 arthas 的功能，避免直接登入到伺服器進行操作。
我們在研效普通也內建了該功能，讓開發排查問題更加方便。
CPU 使用過多
cpu 異常使用排查也是一個非常有用的功能，雖然我們可以透過監控得知 JVM 的 cpu 使用情況，但是沒法知道具體是哪個執行緒以及哪行程式碼造成的 cpu 過高。
thread -n 3
使用以上命令就可以將 cpu 排名前三的執行緒列印出來，並且列出他的堆疊情況，這樣可以很直觀的得知 cpu 消耗了在哪些地方了。
當然還有一些 trace 查詢：
trace demo.MathGame run '#cost > 10'
比如這是將呼叫超過 10ms 的函式列印出來，不過如果我們接入了可觀測系統（OpenTelemetry、skywalking等）這個功能就用不太上了。
還可以在執行的時候不停機修改日誌級別，這種線上上排查一些疑難雜症的時候非常好用（通常情況下 debug 日誌是不列印的），我們可以將日誌級別調整為 debug 列印出更加詳細的資訊：
[arthas@2062]$ logger --name ROOT --level debug
update logger level success.
如果是在 kubernetes 環境中執行也有可能碰到 Java 程序啟動後沒有在磁碟中寫入 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.
導致直接執行的時候無法找到 Java 程序；此時就需要先 ps 拿到 PID 之後再傳入 PID 連入 arthas：
$ java -jar arthas-boot.jar 1
更多關於 arthas 的用法可以參考官網。
參考連結：
- https://pulsar.apache.org/docs/3.2.x/admin-api-topics/#peek-messages
- https://crossoverjie.top/2023/12/11/ob/Pulsar-Broker-Interceptor/
- https://arthas.aliyun.com/
- https://crossoverjie.top/2024/01/09/ob/Pulsar-Delete-Topic/