戰(zhàn)：從CPU飆高到接口超時(shí))
在Java后端摸爬滾打久了你大概率經(jīng)歷過這樣的場(chǎng)景線上應(yīng)用突然CPU飆高、接口超時(shí)、用戶反饋某個(gè)功能時(shí)好時(shí)壞可日志里干干凈凈一點(diǎn)異常都沒打出來。重啟大法雖然能暫時(shí)緩解但根本問題還在而且重啟以后什么現(xiàn)場(chǎng)都沒了。這種時(shí)候我第一反應(yīng)就是開Arthas這個(gè)工具我第一次用就覺得“真香”甚至可以說它已經(jīng)成了我排查線上問題的默認(rèn)入口。所有要連著好幾臺(tái)機(jī)器、翻各種日志、反復(fù)猜測(cè)代碼邏輯的日子在Arthas面前基本可以畫上句號(hào)了。Arthas是Java生態(tài)里非常出名的在線診斷工具它最大的特點(diǎn)是不用改代碼、不用重啟應(yīng)用直接附著在運(yùn)行中的JVM上就能實(shí)時(shí)查看類加載信息、方法調(diào)用參數(shù)、返回值、異常甚至還能動(dòng)態(tài)修改內(nèi)存中已加載的類重新定義類邏輯。對(duì)于需要快速定位生產(chǎn)環(huán)境問題的開發(fā)、運(yùn)維和SRE同學(xué)來說這是一把不折不扣的瑞士軍刀。這篇內(nèi)容我會(huì)把日常用得最多、最順手的功能串起來講一遍從怎么快速附著到具體命令怎么用、遇到問題的排查思路是什么盡量按照實(shí)戰(zhàn)場(chǎng)景來寫方便你直接照葫蘆畫瓢。1. 為什么Arthas值得“真香”先搞清楚它解決的痛點(diǎn)1.1 傳統(tǒng)排查方式的困境我最早排查線上問題基本靠三板斧看日志、加臨時(shí)日志重新發(fā)版、重啟試試。日志如果沒有打印出關(guān)鍵堆棧就得靠猜加日志發(fā)版光是走流程就要很久而且改了代碼的行為可能就和問題現(xiàn)場(chǎng)不一致了有些偶發(fā)問題根本復(fù)現(xiàn)不出來重啟就更不用提了JVM里的現(xiàn)場(chǎng)被清得一干二凈線程狀態(tài)、堆內(nèi)存數(shù)據(jù)、正在執(zhí)行的調(diào)用鏈全都沒了。更難受的是定位性能問題。一個(gè)接口耗時(shí)忽高忽低你懷疑某個(gè)第三方調(diào)用超時(shí)但沒法確認(rèn)到底卡在哪一行。最原始的方案是到處打時(shí)間戳然后重新發(fā)版算下來一個(gè)下午就過去了。而且發(fā)版本身會(huì)引入變量問題可能就這次發(fā)完消失了下次出問題又不知道什么時(shí)候。Arthas這類工具的思路完全不同應(yīng)用不需要重啟它會(huì)在目標(biāo)JVM進(jìn)程上啟動(dòng)一個(gè)代理然后把診斷命令通過socket傳給這個(gè)代理代理用字節(jié)碼注入技術(shù)去攔截目標(biāo)類的方法把你想看的參數(shù)、返回值、異常、執(zhí)行耗時(shí)實(shí)時(shí)抓回來。相當(dāng)于給運(yùn)行中的應(yīng)用做了一次“無痛內(nèi)窺鏡”檢查隨時(shí)都能做做完拔掉恢復(fù)原樣。1.2 和BTrace、Greys等同類工具的取舍其實(shí)在Arthas之前已經(jīng)有BTrace這類早期工具我也試用過。BTrace有一個(gè)很大的問題是使用門檻比較高需要編寫專門的腳本而且對(duì)版本、對(duì)JVM參數(shù)比較敏感用得不好容易把自己搞掛。Arthas雖然也用了類似字節(jié)碼增強(qiáng)的原理但它在交互體驗(yàn)和命令設(shè)計(jì)上做了很多工程化的打磨像看板一樣實(shí)時(shí)刷新的dashboard、一鍵查看線程CPU占用的thread命令、跟蹤方法調(diào)用鏈的trace命令都是直接敲命令就能用非常符合后端開發(fā)的直覺。另外Arthas對(duì)Java版本和中間件環(huán)境的兼容性做得不錯(cuò)像Spring Boot這類框架的項(xiàng)目幾乎開箱即用不需要額外改啟動(dòng)參數(shù)。所以很多團(tuán)隊(duì)會(huì)把Arthas作為標(biāo)準(zhǔn)線上問題排查工具來推廣甚至要求每個(gè)服務(wù)鏡像里都預(yù)留Arthas的安裝路徑方便隨時(shí)附著排查。提示Arthas本身是一個(gè)診斷工具它不改變業(yè)務(wù)代碼的最終邏輯。但要注意在敏感環(huán)境使用時(shí)需要做好權(quán)限管理避免有人通過它執(zhí)行危險(xiǎn)操作比如動(dòng)態(tài)修改類邏輯。生產(chǎn)環(huán)境建議配合審計(jì)和權(quán)限體系來用。2. 五分鐘上手Arthas安裝、啟動(dòng)與附著2.1 用官方腳本快速安裝Arthas的安裝方式很靈活最省事的方法是直接下載官方提供的as.sh腳本然后執(zhí)行curl -L -O https://github.com/alibaba/arthas/releases/latest/download/arthas-boot.jar java -jar arthas-boot.jar這里我個(gè)人更推薦直接下載arthas-boot.jar來用因?yàn)楹罄m(xù)版本升級(jí)時(shí)用它來引導(dǎo)會(huì)更統(tǒng)一也方便自定義下載目錄。腳本方式適合快速體驗(yàn)它的本質(zhì)也是下載arthas-boot.jar再啟動(dòng)。啟動(dòng)之后命令行會(huì)列出當(dāng)前機(jī)器上所有的Java進(jìn)程就像這樣[INFO] arthas-boot version: 3.x.x [INFO] Found existing java process, please choose one and input the serial number: * [1] 12345 xxx-order-service [2] 23456 xxx-gateway輸入序號(hào)回車就能附著到對(duì)應(yīng)的進(jìn)程上。需要注意當(dāng)前登錄用戶必須和目標(biāo)進(jìn)程的啟動(dòng)用戶一致否則會(huì)附著失敗或者出現(xiàn)權(quán)限不足的問題。這個(gè)坑我踩過很多次后面會(huì)在排查章節(jié)單獨(dú)說。2.2 無交互式啟動(dòng)適合腳本和自動(dòng)化場(chǎng)景如果你需要在CI/CD流水線或者自動(dòng)化腳本里啟動(dòng)Arthas就不能用交互式選擇進(jìn)程的方式。這時(shí)候可以直接指定進(jìn)程ID啟動(dòng)java -jar arthas-boot.jar --attach-only --target-ip 127.0.0.1 -p 12345或者直接用as.sh帶參數(shù)./as.sh -p 12345還有一種場(chǎng)景是應(yīng)用本身就集成了Arthas的agent方式啟動(dòng)即在JVM參數(shù)里加上-javaagent:arthas-agent.jar這樣應(yīng)用一跑起來Arthas的attach通道就已經(jīng)準(zhǔn)備好了需要診斷的時(shí)候直接用客戶端連接即可。這種方式特別適合容器環(huán)境因?yàn)槿萜鞯腜ID 1進(jìn)程往往不是Java進(jìn)程動(dòng)態(tài)attach會(huì)受PID namespace影響提前掛agent反而更省心。2.3 理解Arthas的attach與Agent機(jī)制Arthas底層用的是Java的Attach API。它向目標(biāo)JVM發(fā)送attach請(qǐng)求并加載一個(gè)agent這個(gè)agent會(huì)和Arthas的服務(wù)端建立通信服務(wù)端再開一個(gè)telnet端口默認(rèn)8563以及一個(gè)HTTP端口默認(rèn)8562。你敲的每一條命令都會(huì)先經(jīng)過本地的Arthas客戶端再通過這個(gè)通道發(fā)送給目標(biāo)JVM里的agent去執(zhí)行。這條鏈路聽起來有點(diǎn)繞但只要理解了排錯(cuò)就快多了。比如你遇到attach成功但命令半天沒反應(yīng)那大概率是目標(biāo)進(jìn)程中agent初始化出了問題比如類加載器沖突、Arthas版本過舊等。再比如你發(fā)現(xiàn)本地能連上自己的測(cè)試環(huán)境但線上環(huán)境始終連接失敗就要檢查網(wǎng)絡(luò)策略是否開放了8563和8562這兩個(gè)端口。2.4 檢查Arthas是否工作正常附著成功后可以先執(zhí)行一個(gè)最簡單的命令試試[arthas12345]$ version如果返回版本號(hào)說明鏈路通暢。然后可以執(zhí)行[arthas12345]$ sysprop查看系統(tǒng)屬性。這些都正常了再進(jìn)入正式的診斷流程。3. 高頻命令實(shí)戰(zhàn)解析從看板到方法級(jí)追蹤3.1 dashboard實(shí)時(shí)全局看板dashboard是我每次進(jìn)入Arthas后幾乎必敲的第一條命令。它會(huì)以一個(gè)動(dòng)態(tài)面板的形式展示當(dāng)前JVM的概況包括線程、內(nèi)存、GC、類加載數(shù)量以及運(yùn)行時(shí)環(huán)境信息?？窗鍟?huì)自動(dòng)刷新默認(rèn)每3秒刷新一次當(dāng)然你可以用-i參數(shù)指定刷新間隔比如[arthas12345]$ dashboard -i 1000這樣每秒刷新一次。下面給你看一眼典型輸出長什么樣ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON 67 xx-rpc-thread-14 main 5 RUNNABLE 33 0:23 false true ... Memory used total max usage GC heap 1.2G 2.0G 4.0G 30.00% gc.ps_scavenge.count: 128 ...看板里最值得關(guān)注的是CPU占用排前幾的線程。如果某條業(yè)務(wù)線程長期處于RUNNABLE狀態(tài)而且CPU占比明顯偏高基本可以鎖定它就是CPU飆高問題的元兇。再用thread -n命令抓它的線程棧就能進(jìn)一步確認(rèn)卡點(diǎn)位置。3.2 thread線程排查利器thread命令有好幾個(gè)重要的用法按實(shí)用頻率排大概是這么個(gè)順序第一查看當(dāng)前最耗CPU的線程棧[arthas12345]$ thread -n 5這個(gè)命令會(huì)把CPU占用最高的5個(gè)線程的堆棧信息全部打印出來并且自動(dòng)帶上線程的ID、名稱、CPU使用率、狀態(tài)。有一次我遇到線上CPU突然打滿用這個(gè)命令一下就看到了某個(gè)線程卡在了一個(gè)JSON序列化工具的循環(huán)里棧頂清清楚楚寫著某行代碼的toString調(diào)用問題原因秒定位。第二查看指定線程的完整棧[arthas12345]$ thread 67其中67就是線程ID。這會(huì)打印該線程的完整堆棧適合排查線程阻塞在哪里、鎖等待在哪里。第三查找線程間是否有鎖等待和死鎖[arthas12345]$ thread --stateBLOCKED如果想要檢查死鎖Arthas沒有專門的一條命令但是可以結(jié)合thread --stateBLOCKED和線程棧中的“waiting for monitor”字樣來判斷。某次我處理過一個(gè)偶發(fā)死鎖問題兩個(gè)線程都在等對(duì)方的鎖通過這個(gè)命令一查堆棧里兩個(gè)線程互相等待的鎖對(duì)象非常直觀最后定位到是加鎖順序不一致導(dǎo)致的經(jīng)典死鎖。3.3 jad反編譯線上類確認(rèn)跑的是不是你以為的代碼線上最尷尬的情況之一就是代碼看著是新的實(shí)際發(fā)出去的包是舊的。與其問別人不如直接反編譯看字節(jié)碼。jad命令能反編譯任意已加載類打印出它的Java源碼結(jié)構(gòu)實(shí)際是反編譯結(jié)果可能和原始源碼有細(xì)微差別但邏輯基本可讀。用法非常簡單[arthas12345]$ jad com.example.OrderService輸出會(huì)帶類加載器信息、源碼位置、反編譯的Java代碼。這個(gè)命令在排查“為什么線上行為和本地不一致”時(shí)特別有用。有一次客戶端反饋某功能表現(xiàn)異常我用jad一查發(fā)現(xiàn)類里根本沒有最新加的判斷邏輯立刻確認(rèn)是發(fā)布流程出了問題省掉了無休止的討論。如果你的類被JIT優(yōu)化了反編譯出來可能有部分內(nèi)容顯示不出來但不影響判斷大致邏輯。可以用jad --source-only只輸出源碼方便復(fù)制到本地做diff比較。3.4 watch觀察方法調(diào)用入?yún)?、返回值和異常watch是Arthas里我最喜歡的命令沒有之一。它用來觀察指定方法的每一次調(diào)用抓取入?yún)?、返回?duì)象、拋出的異常、耗時(shí)等。寫法如下[arthas12345]$ watch com.example.OrderService createOrder {params, returnObj, exception, cost} -x 3拆解一下這個(gè)命令第一個(gè)參數(shù)是類全限定名。第二個(gè)參數(shù)是方法名。第三個(gè)參數(shù)是OGNL表達(dá)式?jīng)Q定要輸出什么。{params, returnObj, exception, cost}分別代表入?yún)⒘斜?、返回?duì)象、異常、耗時(shí)。這個(gè)大括號(hào)不是列表字面量而是輸出多個(gè)字段的組合。-x表示展開對(duì)象的層級(jí)數(shù)字越大展開細(xì)節(jié)越多。比如-x 3能看到入?yún)?duì)象的三層嵌套結(jié)構(gòu)。這個(gè)命令在排查“參數(shù)對(duì)了卻得到奇怪結(jié)果”、“某個(gè)方法偶爾拋異常但日志沒記錄”的場(chǎng)景下幾乎是精準(zhǔn)制導(dǎo)。比如有次同行遇到一個(gè)接口偶爾返回錯(cuò)誤碼但代碼里沒打日志我建議用watch帶異常參數(shù)去抓結(jié)果沒等多久就抓到了異常棧是一個(gè)特殊的非法參數(shù)組合導(dǎo)致的本地測(cè)試完全沒覆蓋到。注意點(diǎn)watch默認(rèn)只監(jiān)控方法進(jìn)入時(shí)的信息如果你想額外看方法退出時(shí)的結(jié)果要加上-b或-e參數(shù)來控制位置或者更常用的是保持默認(rèn)然后在OGNL表達(dá)式里同時(shí)取返回值和異常即可。Arthas的做法是默認(rèn)在方法結(jié)束以后統(tǒng)一輸出所以直接查returnObj和exception是能拿到的。3.5 trace定位方法內(nèi)部耗時(shí)分布有時(shí)候接口慢但你不知道熱點(diǎn)是在內(nèi)部哪個(gè)子調(diào)用上。trace命令可以追蹤一個(gè)方法內(nèi)部的所有子調(diào)用輸出每一層的耗時(shí)以及調(diào)用次數(shù)。[arthas12345]$ trace com.example.OrderService createOrder #cost 200這個(gè)命令的含義是當(dāng)createOrder整體耗時(shí)超過200毫秒時(shí)打印方法內(nèi)部的調(diào)用鏈耗時(shí)詳情。每一行會(huì)顯示類名、方法名、耗時(shí)、調(diào)用來源。trace是我處理性能問題時(shí)最依賴的工具。比如你懷疑數(shù)據(jù)庫查詢慢但數(shù)據(jù)庫監(jiān)控又沒查到慢SQL或者懷疑HTTP外部服務(wù)超時(shí)卻不知道具體在哪個(gè)階段。trace一跑整個(gè)方法內(nèi)部的每一步耗時(shí)一目了然是內(nèi)存計(jì)算慢還是RPC調(diào)用慢還是某個(gè)循環(huán)里做了太多無用計(jì)算全都能看到。和watch不同的是trace的成本相對(duì)高一些尤其是在高頻調(diào)用方法上開啟trace會(huì)有一定的性能開銷。所以在生產(chǎn)環(huán)境使用時(shí)要控制好追蹤的目標(biāo)方法不要掛在整個(gè)入口上大規(guī)模trace更推薦在定位到大致方法后細(xì)粒度去開trace。3.6 stack方法被誰調(diào)用、調(diào)用鏈長什么樣stack命令會(huì)輸出當(dāng)前方法被調(diào)用的調(diào)用路徑簡單理解就是“誰調(diào)用了我”。用法[arthas12345]$ stack com.example.OrderService createOrder這個(gè)命令適合回答“這個(gè)方法為什么被反復(fù)觸發(fā)”、“這個(gè)入口是被人調(diào)用還是內(nèi)部定時(shí)任務(wù)觸發(fā)的”。有一次排查一個(gè)數(shù)據(jù)錯(cuò)亂問題就是想弄清楚某條數(shù)據(jù)為什么會(huì)走到一個(gè)異常分支最后用stack發(fā)現(xiàn)原來是消息消費(fèi)邏輯里間接調(diào)用了同一個(gè)方法導(dǎo)致數(shù)據(jù)狀態(tài)被重復(fù)修改。stack還支持按條件輸出比如只輸出耗時(shí)超過閾值的調(diào)用[arthas12345]$ stack com.example.OrderService createOrder #cost1000這樣既能看到調(diào)用鏈也能篩選出慢調(diào)用用來排查偶發(fā)性慢請(qǐng)求特別好使。3.7 tt時(shí)間隧道記錄方法調(diào)用的歷史現(xiàn)場(chǎng)如果說watch是“實(shí)時(shí)看每一次調(diào)用”那tt就是“把調(diào)用的現(xiàn)場(chǎng)記下來回頭慢慢看”。tt命令能記錄一段時(shí)間內(nèi)某個(gè)方法的調(diào)用快照包含入?yún)?、返回、異常、調(diào)用時(shí)間等并且你能用tt的Play功能去重放某一次調(diào)用?；居梅╗arthas12345]$ tt -t com.example.OrderService createOrder -n 20意思是記錄最近20次createOrder調(diào)用的快照。輸出里每行有一個(gè)ID如果你想看第8次調(diào)用的具體參數(shù)和返回值[arthas12345]$ tt -i 8有一次線上偶發(fā)問題最讓人頭疼的就是無法復(fù)現(xiàn)當(dāng)時(shí)我用tt掛了半小時(shí)記錄到了那一次異常調(diào)用的完整入?yún)⑷缓笥眠@個(gè)參數(shù)在測(cè)試環(huán)境一跑就復(fù)現(xiàn)了整個(gè)排查從“玄學(xué)”變成了“確定性”。tt的代價(jià)比watch更大因?yàn)樗诜椒ǔ鋈肟诙疾迦霐r截邏輯并且保存快照。所以開啟時(shí)間不要過長記錄次數(shù)也要限制比如-n 20抓完立即關(guān)閉。3.8 monitor統(tǒng)計(jì)方法調(diào)用頻率、成功率和耗時(shí)趨勢(shì)如果你想看一個(gè)方法在一段時(shí)間內(nèi)的整體表現(xiàn)比如每分鐘被調(diào)多少次、成功率如何、平均耗時(shí)多少monitor就是干這個(gè)的[arthas12345]$ monitor com.example.OrderService createOrder -c 30表示每30秒統(tǒng)計(jì)一次createOrder的調(diào)用次數(shù)、失敗次數(shù)、失敗率、平均耗時(shí)等。這個(gè)命令適合不需要看單個(gè)調(diào)用細(xì)節(jié)而是想看宏觀趨勢(shì)的場(chǎng)景。比如壓測(cè)過程中觀察某個(gè)方法的TPS、RT變化或者線上某個(gè)接口失敗率突然升高時(shí)先確認(rèn)是不是這個(gè)原因。3.9 sc、getstatic與ognl查看類信息、讀取靜態(tài)變量、執(zhí)行任意表達(dá)式這三個(gè)命令放到一起講因?yàn)樗鼈兪茿rthas里“探查類結(jié)構(gòu)”的組合拳。sc用來搜索所有已加載的類[arthas12345]$ sc *OrderService*輸出會(huì)顯示類全限定名、類加載器、類狀態(tài)。如果想看類的詳細(xì)結(jié)構(gòu)加-d參數(shù)[arthas12345]$ sc -d com.example.OrderService這樣會(huì)輸出類的修飾符、注解、父類、接口、成員變量等。getstatic用來讀取類的靜態(tài)變量[arthas12345]$ getstatic com.example.OrderService CACHE_SIZE比如某個(gè)配置類的靜態(tài)字段是在啟動(dòng)時(shí)加載的又沒辦法動(dòng)態(tài)刷新用getstatic能直接看到當(dāng)前內(nèi)存里的值判斷配置是否真的生效了。ognl是最靈活的命令它能在目標(biāo)JVM里執(zhí)行任意表達(dá)式。比如調(diào)用某個(gè)靜態(tài)方法、獲取某個(gè)對(duì)象的字段、甚至修改某個(gè)字段的值[arthas12345]$ ognl com.example.GlobalConfiggetConfig()也可以帶上下文執(zhí)行比如獲取當(dāng)前線程上下文的某個(gè)Bean[arthas12345]$ ognl -x 2 #context org.springframework.web.context.ContextLoadergetCurrentWebApplicationContext(), #bean context.getBean(orderService), #bean.queryStatus()ognl的“任意執(zhí)行”能力非常強(qiáng)但也要格外小心它相當(dāng)于給了你在生產(chǎn)環(huán)境執(zhí)行代碼的權(quán)限。尤其是在寫修改類型表達(dá)式時(shí)一定要仔細(xì)確認(rèn)不要改錯(cuò)字段。3.10 mc與redefine動(dòng)態(tài)更新類邏輯redefine是我用得比較謹(jǐn)慎但關(guān)鍵時(shí)刻能救命的命令。它允許你修改已加載類的字節(jié)碼相當(dāng)于在運(yùn)行中“熱更新”類的邏輯。基本流程是先用jad把目標(biāo)類反編譯出來導(dǎo)出源碼到本地改完邏輯以后用mc命令編譯成.class文件再用redefine命令把它加載進(jìn)JVM。步驟如下[arthas12345]$ jad --source-only com.example.OrderService /tmp/OrderService.java # 然后在本機(jī)編輯 /tmp/OrderService.java改好邏輯 [arthas12345]$ mc /tmp/OrderService.java -d /tmp/output [arthas12345]$ redefine /tmp/output/com/example/OrderService.class注意事項(xiàng)redefine只改變后續(xù)新執(zhí)行的邏輯對(duì)已經(jīng)執(zhí)行到一半的調(diào)用是無效的而且redefine不會(huì)改變類的結(jié)構(gòu)你不能新增字段、不能新增方法簽名、不能增加銷毀原結(jié)構(gòu)。一般我拿它來做臨時(shí)補(bǔ)丁加一個(gè)日志輸出、調(diào)一個(gè)參數(shù)值等等等新的版本發(fā)上去以后就不要再依賴redefine的臨時(shí)邏輯了。警告redefine本質(zhì)上是修改運(yùn)行中的JVM內(nèi)存里的類定義風(fēng)險(xiǎn)等級(jí)很高只適合臨時(shí)應(yīng)急。不到萬不得已我建議你先嘗試用ognl修改配置值、用dashboard觀察趨勢(shì)最后才考慮redefine。而且redefine前一定要把原始類文件備份好保證能回滾。4. 實(shí)戰(zhàn)案例拆解從CPU飆高到接口超時(shí)的排查全流程4.1 案例一CPU突然飆到500%的線程定位事情大約是這樣的某跨平臺(tái)訂單服務(wù)的CPU在下午兩點(diǎn)左右突然飆高監(jiān)控報(bào)警直接打到群里。按照以前的處理方式第一件事是登錄機(jī)器看top找到CPU高進(jìn)程的PID然后jstack導(dǎo)出線程棧再手動(dòng)去找nid對(duì)應(yīng)的線程。這一套流程本身沒問題但jstack的線程棧里全是十六進(jìn)制線程ID要對(duì)應(yīng)到業(yè)務(wù)線程還得人工比對(duì)效率很低。有了Arthas之后流程變成了這樣先附著到目標(biāo)進(jìn)程執(zhí)行dashboard馬上就能看到哪個(gè)線程的CPU占用異常高通常那個(gè)線程的ID還會(huì)反復(fù)出現(xiàn)在刷新面板的最前面。然后執(zhí)行[arthas12345]$ thread -n 3Arthas會(huì)直接打印出CPU占用最高的三個(gè)線程的完整堆棧自動(dòng)把線程名稱、CPU時(shí)間、堆棧都組裝好了。那次我一眼就看到某個(gè)線程卡在一個(gè)XML解析方法內(nèi)部最底層是在JVM里做正則匹配數(shù)據(jù)量一大CPU直接被吃滿。順著棧里的業(yè)務(wù)類名很快就對(duì)應(yīng)到了代碼行發(fā)現(xiàn)是一個(gè)對(duì)超大字符串做了多次replaceAll的循環(huán)屬于典型的正則回溯問題。這個(gè)案例關(guān)鍵點(diǎn)在于thread -n非常省事省掉了jstack 人工匹配nid的過程。如果只靠jstack十幾分鐘能定位就算不錯(cuò)了用Arthas一兩分鐘就鎖定了根因。4.2 案例二接口偶發(fā)超時(shí)怎么抓到慢調(diào)用的具體位置另一個(gè)印象深刻的案例是某個(gè)查詢接口偶發(fā)超時(shí)時(shí)好時(shí)壞。我先打開trace守護(hù)在入口方法上[arthas12345]$ trace com.example.QueryService queryDetail #cost 1000跑了大約十分鐘抓到了一次耗時(shí)1200毫秒的調(diào)用快照。結(jié)果顯示大部分耗時(shí)花費(fèi)在調(diào)用下游的某個(gè)HTTP接口上時(shí)間約900毫秒而我對(duì)這個(gè)下游HTTP接口的容錯(cuò)判斷閾值是500毫秒所以導(dǎo)致上游超時(shí)。順著這個(gè)線索檢查了下游服務(wù)的響應(yīng)時(shí)間分布發(fā)現(xiàn)是對(duì)方服務(wù)在整點(diǎn)時(shí)刻做批量任務(wù)導(dǎo)致該時(shí)段RT拉長。后續(xù)調(diào)整了調(diào)用方的超時(shí)時(shí)間并且給這個(gè)下游調(diào)用增加了本地緩存問題徹底解決。如果不用trace靠加日志排查這種偶發(fā)問題可能要發(fā)好幾個(gè)版本才能抓到一個(gè)慢樣本而且很有可能會(huì)因?yàn)殡S機(jī)性導(dǎo)致錯(cuò)過現(xiàn)場(chǎng)。trace的價(jià)值在于它不需要任何提前埋點(diǎn)事后診斷能力很強(qiáng)。4.3 案例三方法返回值為什么和預(yù)期不一致還有過一次經(jīng)歷是同事在排查一個(gè)對(duì)賬系統(tǒng)的金額計(jì)算差異。日志里打了入?yún)⒁泊蛄俗罱K返回值但中間經(jīng)過了好幾個(gè)子方法的嵌套調(diào)用看不出是哪一步把金額改錯(cuò)了。這種情況watchstack組合拳非常管用。先watch最外層方法看看入?yún)⒑妥罱K返回值如果出入?yún)]問題就深入內(nèi)部方法分別watch找到第一個(gè)出現(xiàn)差異的那一層。當(dāng)時(shí)我們用watch單獨(dú)盯了一個(gè)金額調(diào)整的方法抓到的入?yún)⑹且粋€(gè)對(duì)象對(duì)象的某個(gè)金額字段是100.00但returnObj返回時(shí)變成了99.99。再往下一層看發(fā)現(xiàn)里面調(diào)用了一個(gè)舍入工具舍入模式默認(rèn)是向下取整而業(yè)務(wù)方預(yù)期是四舍五入。順著這個(gè)鏈路往下追又用stack查了舍入工具方法的調(diào)用來源確認(rèn)只有這一條業(yè)務(wù)路徑走錯(cuò)了舍入模式。整個(gè)過程沒有重啟、沒有改動(dòng)一行代碼一個(gè)下午就把根因挖干凈了。5. 常見問題與排查思路Arthas使用中踩過的坑5.1 attach失敗提示Unable to open socket file這個(gè)報(bào)錯(cuò)最常見的場(chǎng)景是你用的系統(tǒng)賬號(hào)和目標(biāo)Java進(jìn)程的啟動(dòng)賬號(hào)不一致。比如應(yīng)用是用service用戶啟動(dòng)的你sudo到root用戶執(zhí)行Arthas那么Arthas無法讀取目標(biāo)JVM的臨時(shí)目錄文件就會(huì)出現(xiàn)socket文件路徑相關(guān)報(bào)錯(cuò)。解決辦法很直接換成和啟動(dòng)進(jìn)程相同的用戶執(zhí)行。如果一定要root操作可以考慮安裝Arthas到目標(biāo)用戶目錄下并用su切換到該用戶后再啟動(dòng)。5.2 所有命令都能執(zhí)行但watch/trace沒有任何輸出這個(gè)有兩種可能。一種是方法已經(jīng)啟動(dòng)了很久沒有被調(diào)用你可以先用monitor確認(rèn)調(diào)用是否真的存在。另一種是方法是在其他類加載器里加載的而Arthas默認(rèn)匹配的類加載器集合不對(duì)。特別是用到自定義類加載器、OSGi環(huán)境時(shí)需要用sc -d確認(rèn)類的類加載器信息然后用classloader命令配合指定類加載器再觀察[arthas12345]$ classloader -l然后指定類加載器的索引再對(duì)目標(biāo)方法執(zhí)行watch。你也可以用watch時(shí)帶上-c參數(shù)指定類加載器的hash值。當(dāng)然現(xiàn)實(shí)中多數(shù)Spring Boot應(yīng)用是單一類加載器基本不會(huì)遇到這類問題。5.3 對(duì)象層級(jí)太深輸出被截?cái)嗄J(rèn)情況下Arthas為了避免把大量數(shù)據(jù)一股腦打印出來會(huì)限制OGNL表達(dá)式輸出對(duì)象的展開深度。如果你想看更多字段用-x參數(shù)調(diào)大即可。比如[arthas12345]$ watch com.example.OrderService createOrder {params, returnObj} -x 5如果-x調(diào)得太大導(dǎo)致輸出非常長影響閱讀可以同時(shí)用-n限制觀察次數(shù)比如-n 3只輸出三次結(jié)果。5.4 ognl表達(dá)式寫復(fù)雜了容易出錯(cuò)怎么調(diào)試ognl表達(dá)式在Arthas里雖然功能強(qiáng)大但一旦寫復(fù)雜了語法錯(cuò)誤可能比業(yè)務(wù)代碼本身還難排查。我的習(xí)慣是先在本地用一個(gè)簡單的Spring Boot應(yīng)用試表達(dá)式確認(rèn)無誤了再拿到生產(chǎn)環(huán)境執(zhí)行。還有一個(gè)技巧是拆分成小的表達(dá)式逐步驗(yàn)證先獲取對(duì)象引用再訪問字段不要一口氣寫超長的OGNL鏈條。比如你想拿到Spring容器里的某個(gè)Bean并調(diào)用方法可以先執(zhí)行[arthas12345]$ ognl #ctxorg.springframework.web.context.ContextLoadergetCurrentWebApplicationContext(), #ctx確認(rèn)這個(gè)對(duì)象能拿得到再去擴(kuò)展后面的字段訪問。5.5 Arthas本身對(duì)性能的影響很多人會(huì)擔(dān)心Arthas附著之后影響業(yè)務(wù)性能。實(shí)話實(shí)說開啟watch/trace/monitor這類命令會(huì)對(duì)目標(biāo)方法做字節(jié)碼增強(qiáng)有一定額外開銷。如果目標(biāo)是低頻方法影響幾乎可以忽略如果目標(biāo)是高QPS方法性能損耗會(huì)明顯一些。所以生產(chǎn)使用有幾個(gè)原則只在需要排查的時(shí)間窗口打開命令用-n限制記錄次數(shù)用完馬上關(guān)閉。不要同時(shí)開啟大量方法的trace/watch。優(yōu)先用dashboard和thread這類低開銷命令做初步排查鎖定目標(biāo)后再用watch/trace做精細(xì)分析。5.6 Arthas版本太舊導(dǎo)致命令行為不一致Arthas迭代速度比較快一些命令的參數(shù)和輸出格式在舊版本里可能不兼容。如果你發(fā)現(xiàn)某個(gè)命令行為和文檔不一致優(yōu)先檢查版本[arthas12345]$ version建議下載最新release版本并保持目標(biāo)環(huán)境和運(yùn)維腳本里使用的版本一致免得今天在這臺(tái)機(jī)器上可用、明天換臺(tái)機(jī)器就報(bào)錯(cuò)。5.7 容器環(huán)境里attach的特殊情況容器化部署越來越普遍在容器里用Arthas有時(shí)會(huì)遇到PID namespace限制導(dǎo)致attach失敗或者容器里沒有安裝完整JDK只有JRE。解決辦法是基礎(chǔ)鏡像里提前安裝JDK而不是只有JRE。使用Arthas的agent模式啟動(dòng)應(yīng)用避免動(dòng)態(tài)attach的限制。容器內(nèi)執(zhí)行Arthas時(shí)確認(rèn)/tmp目錄可寫并且PID對(duì)得上宿主機(jī)還是容器內(nèi)的Namespace。5.8 無法訪問8563端口如果Arthas在遠(yuǎn)程機(jī)器上運(yùn)行而你想從本地連上去操作需要確保8563端口默認(rèn)telnet端口和8562端口默認(rèn)HTTP端口被你當(dāng)前的網(wǎng)絡(luò)允許連接。一些公司內(nèi)部網(wǎng)絡(luò)策略較嚴(yán)格需要提網(wǎng)絡(luò)放行申請(qǐng)或者你可以用ssh隧道把遠(yuǎn)程端口映射到本地再訪問這樣就不用額外開防火墻端口了。整體來說Arthas確實(shí)是一個(gè)讓我“用過就回不去”的工具。它解決的不是某一個(gè)具體的問題而是把人從“盲人摸象”的排查模式里解放出來讓你能直接看到運(yùn)行中JVM的內(nèi)部。剛開始接觸時(shí)可能會(huì)被它的命令數(shù)量嚇到但只要把dashboard、thread、jad、watch、trace、tt這幾個(gè)核心命令用熟就已經(jīng)能覆蓋絕大部分日常排查場(chǎng)景了。我自己一次一次踩坑之后才慢慢意識(shí)到滿屏的命令并不可怕關(guān)鍵是把每一條的適用時(shí)機(jī)記清楚——先看全局再鎖線程然后用watch或trace深入方法內(nèi)部再用ognl處理疑難雜癥這套思路比硬記命令參數(shù)重要得多。希望這篇文章能幫你少走一些彎路也歡迎你把這些命令在測(cè)試環(huán)境多試幾遍熟能生巧之后線上問題再也不用靠“重啟大法”來解決了。 Java線上排查利器Arthas實(shí)戰(zhàn)：從CPU飆高到接口超時(shí)
在Java后端摸爬滾打久了你大概率經(jīng)歷過這樣的場(chǎng)景線上應(yīng)用突然CPU飆高、接口超時(shí)、用戶反饋某個(gè)功能時(shí)好時(shí)壞可日志里干干凈凈一點(diǎn)異常都沒打出來。重啟大法雖然能暫時(shí)緩解但根本問題還在而且重啟以后什么現(xiàn)場(chǎng)都沒了。這種時(shí)候我第一反應(yīng)就是開Arthas這個(gè)工具我第一次用就覺得“真香”甚至可以說它已經(jīng)成了我排查線上問題的默認(rèn)入口。所有要連著好幾臺(tái)機(jī)器、翻各種日志、反復(fù)猜測(cè)代碼邏輯的日子在Arthas面前基本可以畫上句號(hào)了。Arthas是Java生態(tài)里非常出名的在線診斷工具它最大的特點(diǎn)是不用改代碼、不用重啟應(yīng)用直接附著在運(yùn)行中的JVM上就能實(shí)時(shí)查看類加載信息、方法調(diào)用參數(shù)、返回值、異常甚至還能動(dòng)態(tài)修改內(nèi)存中已加載的類重新定義類邏輯。對(duì)于需要快速定位生產(chǎn)環(huán)境問題的開發(fā)、運(yùn)維和SRE同學(xué)來說這是一把不折不扣的瑞士軍刀。這篇內(nèi)容我會(huì)把日常用得最多、最順手的功能串起來講一遍從怎么快速附著到具體命令怎么用、遇到問題的排查思路是什么盡量按照實(shí)戰(zhàn)場(chǎng)景來寫方便你直接照葫蘆畫瓢。1. 為什么Arthas值得“真香”先搞清楚它解決的痛點(diǎn)1.1 傳統(tǒng)排查方式的困境我最早排查線上問題基本靠三板斧看日志、加臨時(shí)日志重新發(fā)版、重啟試試。日志如果沒有打印出關(guān)鍵堆棧就得靠猜加日志發(fā)版光是走流程就要很久而且改了代碼的行為可能就和問題現(xiàn)場(chǎng)不一致了有些偶發(fā)問題根本復(fù)現(xiàn)不出來重啟就更不用提了JVM里的現(xiàn)場(chǎng)被清得一干二凈線程狀態(tài)、堆內(nèi)存數(shù)據(jù)、正在執(zhí)行的調(diào)用鏈全都沒了。更難受的是定位性能問題。一個(gè)接口耗時(shí)忽高忽低你懷疑某個(gè)第三方調(diào)用超時(shí)但沒法確認(rèn)到底卡在哪一行。最原始的方案是到處打時(shí)間戳然后重新發(fā)版算下來一個(gè)下午就過去了。而且發(fā)版本身會(huì)引入變量問題可能就這次發(fā)完消失了下次出問題又不知道什么時(shí)候。Arthas這類工具的思路完全不同應(yīng)用不需要重啟它會(huì)在目標(biāo)JVM進(jìn)程上啟動(dòng)一個(gè)代理然后把診斷命令通過socket傳給這個(gè)代理代理用字節(jié)碼注入技術(shù)去攔截目標(biāo)類的方法把你想看的參數(shù)、返回值、異常、執(zhí)行耗時(shí)實(shí)時(shí)抓回來。相當(dāng)于給運(yùn)行中的應(yīng)用做了一次“無痛內(nèi)窺鏡”檢查隨時(shí)都能做做完拔掉恢復(fù)原樣。1.2 和BTrace、Greys等同類工具的取舍其實(shí)在Arthas之前已經(jīng)有BTrace這類早期工具我也試用過。BTrace有一個(gè)很大的問題是使用門檻比較高需要編寫專門的腳本而且對(duì)版本、對(duì)JVM參數(shù)比較敏感用得不好容易把自己搞掛。Arthas雖然也用了類似字節(jié)碼增強(qiáng)的原理但它在交互體驗(yàn)和命令設(shè)計(jì)上做了很多工程化的打磨像看板一樣實(shí)時(shí)刷新的dashboard、一鍵查看線程CPU占用的thread命令、跟蹤方法調(diào)用鏈的trace命令都是直接敲命令就能用非常符合后端開發(fā)的直覺。另外Arthas對(duì)Java版本和中間件環(huán)境的兼容性做得不錯(cuò)像Spring Boot這類框架的項(xiàng)目幾乎開箱即用不需要額外改啟動(dòng)參數(shù)。所以很多團(tuán)隊(duì)會(huì)把Arthas作為標(biāo)準(zhǔn)線上問題排查工具來推廣甚至要求每個(gè)服務(wù)鏡像里都預(yù)留Arthas的安裝路徑方便隨時(shí)附著排查。提示Arthas本身是一個(gè)診斷工具它不改變業(yè)務(wù)代碼的最終邏輯。但要注意在敏感環(huán)境使用時(shí)需要做好權(quán)限管理避免有人通過它執(zhí)行危險(xiǎn)操作比如動(dòng)態(tài)修改類邏輯。生產(chǎn)環(huán)境建議配合審計(jì)和權(quán)限體系來用。2. 五分鐘上手Arthas安裝、啟動(dòng)與附著2.1 用官方腳本快速安裝Arthas的安裝方式很靈活最省事的方法是直接下載官方提供的as.sh腳本然后執(zhí)行curl -L -O https://github.com/alibaba/arthas/releases/latest/download/arthas-boot.jar java -jar arthas-boot.jar這里我個(gè)人更推薦直接下載arthas-boot.jar來用因?yàn)楹罄m(xù)版本升級(jí)時(shí)用它來引導(dǎo)會(huì)更統(tǒng)一也方便自定義下載目錄。腳本方式適合快速體驗(yàn)它的本質(zhì)也是下載arthas-boot.jar再啟動(dòng)。啟動(dòng)之后命令行會(huì)列出當(dāng)前機(jī)器上所有的Java進(jìn)程就像這樣[INFO] arthas-boot version: 3.x.x [INFO] Found existing java process, please choose one and input the serial number: * [1] 12345 xxx-order-service [2] 23456 xxx-gateway輸入序號(hào)回車就能附著到對(duì)應(yīng)的進(jìn)程上。需要注意當(dāng)前登錄用戶必須和目標(biāo)進(jìn)程的啟動(dòng)用戶一致否則會(huì)附著失敗或者出現(xiàn)權(quán)限不足的問題。這個(gè)坑我踩過很多次后面會(huì)在排查章節(jié)單獨(dú)說。2.2 無交互式啟動(dòng)適合腳本和自動(dòng)化場(chǎng)景如果你需要在CI/CD流水線或者自動(dòng)化腳本里啟動(dòng)Arthas就不能用交互式選擇進(jìn)程的方式。這時(shí)候可以直接指定進(jìn)程ID啟動(dòng)java -jar arthas-boot.jar --attach-only --target-ip 127.0.0.1 -p 12345或者直接用as.sh帶參數(shù)./as.sh -p 12345還有一種場(chǎng)景是應(yīng)用本身就集成了Arthas的agent方式啟動(dòng)即在JVM參數(shù)里加上-javaagent:arthas-agent.jar這樣應(yīng)用一跑起來Arthas的attach通道就已經(jīng)準(zhǔn)備好了需要診斷的時(shí)候直接用客戶端連接即可。這種方式特別適合容器環(huán)境因?yàn)槿萜鞯腜ID 1進(jìn)程往往不是Java進(jìn)程動(dòng)態(tài)attach會(huì)受PID namespace影響提前掛agent反而更省心。2.3 理解Arthas的attach與Agent機(jī)制Arthas底層用的是Java的Attach API。它向目標(biāo)JVM發(fā)送attach請(qǐng)求并加載一個(gè)agent這個(gè)agent會(huì)和Arthas的服務(wù)端建立通信服務(wù)端再開一個(gè)telnet端口默認(rèn)8563以及一個(gè)HTTP端口默認(rèn)8562。你敲的每一條命令都會(huì)先經(jīng)過本地的Arthas客戶端再通過這個(gè)通道發(fā)送給目標(biāo)JVM里的agent去執(zhí)行。這條鏈路聽起來有點(diǎn)繞但只要理解了排錯(cuò)就快多了。比如你遇到attach成功但命令半天沒反應(yīng)那大概率是目標(biāo)進(jìn)程中agent初始化出了問題比如類加載器沖突、Arthas版本過舊等。再比如你發(fā)現(xiàn)本地能連上自己的測(cè)試環(huán)境但線上環(huán)境始終連接失敗就要檢查網(wǎng)絡(luò)策略是否開放了8563和8562這兩個(gè)端口。2.4 檢查Arthas是否工作正常附著成功后可以先執(zhí)行一個(gè)最簡單的命令試試[arthas12345]$ version如果返回版本號(hào)說明鏈路通暢。然后可以執(zhí)行[arthas12345]$ sysprop查看系統(tǒng)屬性。這些都正常了再進(jìn)入正式的診斷流程。3. 高頻命令實(shí)戰(zhàn)解析從看板到方法級(jí)追蹤3.1 dashboard實(shí)時(shí)全局看板dashboard是我每次進(jìn)入Arthas后幾乎必敲的第一條命令。它會(huì)以一個(gè)動(dòng)態(tài)面板的形式展示當(dāng)前JVM的概況包括線程、內(nèi)存、GC、類加載數(shù)量以及運(yùn)行時(shí)環(huán)境信息?？窗鍟?huì)自動(dòng)刷新默認(rèn)每3秒刷新一次當(dāng)然你可以用-i參數(shù)指定刷新間隔比如[arthas12345]$ dashboard -i 1000這樣每秒刷新一次。下面給你看一眼典型輸出長什么樣ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON 67 xx-rpc-thread-14 main 5 RUNNABLE 33 0:23 false true ... Memory used total max usage GC heap 1.2G 2.0G 4.0G 30.00% gc.ps_scavenge.count: 128 ...看板里最值得關(guān)注的是CPU占用排前幾的線程。如果某條業(yè)務(wù)線程長期處于RUNNABLE狀態(tài)而且CPU占比明顯偏高基本可以鎖定它就是CPU飆高問題的元兇。再用thread -n命令抓它的線程棧就能進(jìn)一步確認(rèn)卡點(diǎn)位置。3.2 thread線程排查利器thread命令有好幾個(gè)重要的用法按實(shí)用頻率排大概是這么個(gè)順序第一查看當(dāng)前最耗CPU的線程棧[arthas12345]$ thread -n 5這個(gè)命令會(huì)把CPU占用最高的5個(gè)線程的堆棧信息全部打印出來并且自動(dòng)帶上線程的ID、名稱、CPU使用率、狀態(tài)。有一次我遇到線上CPU突然打滿用這個(gè)命令一下就看到了某個(gè)線程卡在了一個(gè)JSON序列化工具的循環(huán)里棧頂清清楚楚寫著某行代碼的toString調(diào)用問題原因秒定位。第二查看指定線程的完整棧[arthas12345]$ thread 67其中67就是線程ID。這會(huì)打印該線程的完整堆棧適合排查線程阻塞在哪里、鎖等待在哪里。第三查找線程間是否有鎖等待和死鎖[arthas12345]$ thread --stateBLOCKED如果想要檢查死鎖Arthas沒有專門的一條命令但是可以結(jié)合thread --stateBLOCKED和線程棧中的“waiting for monitor”字樣來判斷。某次我處理過一個(gè)偶發(fā)死鎖問題兩個(gè)線程都在等對(duì)方的鎖通過這個(gè)命令一查堆棧里兩個(gè)線程互相等待的鎖對(duì)象非常直觀最后定位到是加鎖順序不一致導(dǎo)致的經(jīng)典死鎖。3.3 jad反編譯線上類確認(rèn)跑的是不是你以為的代碼線上最尷尬的情況之一就是代碼看著是新的實(shí)際發(fā)出去的包是舊的。與其問別人不如直接反編譯看字節(jié)碼。jad命令能反編譯任意已加載類打印出它的Java源碼結(jié)構(gòu)實(shí)際是反編譯結(jié)果可能和原始源碼有細(xì)微差別但邏輯基本可讀。用法非常簡單[arthas12345]$ jad com.example.OrderService輸出會(huì)帶類加載器信息、源碼位置、反編譯的Java代碼。這個(gè)命令在排查“為什么線上行為和本地不一致”時(shí)特別有用。有一次客戶端反饋某功能表現(xiàn)異常我用jad一查發(fā)現(xiàn)類里根本沒有最新加的判斷邏輯立刻確認(rèn)是發(fā)布流程出了問題省掉了無休止的討論。如果你的類被JIT優(yōu)化了反編譯出來可能有部分內(nèi)容顯示不出來但不影響判斷大致邏輯。可以用jad --source-only只輸出源碼方便復(fù)制到本地做diff比較。3.4 watch觀察方法調(diào)用入?yún)?、返回值和異常watch是Arthas里我最喜歡的命令沒有之一。它用來觀察指定方法的每一次調(diào)用抓取入?yún)?、返回?duì)象、拋出的異常、耗時(shí)等。寫法如下[arthas12345]$ watch com.example.OrderService createOrder {params, returnObj, exception, cost} -x 3拆解一下這個(gè)命令第一個(gè)參數(shù)是類全限定名。第二個(gè)參數(shù)是方法名。第三個(gè)參數(shù)是OGNL表達(dá)式?jīng)Q定要輸出什么。{params, returnObj, exception, cost}分別代表入?yún)⒘斜?、返回?duì)象、異常、耗時(shí)。這個(gè)大括號(hào)不是列表字面量而是輸出多個(gè)字段的組合。-x表示展開對(duì)象的層級(jí)數(shù)字越大展開細(xì)節(jié)越多。比如-x 3能看到入?yún)?duì)象的三層嵌套結(jié)構(gòu)。這個(gè)命令在排查“參數(shù)對(duì)了卻得到奇怪結(jié)果”、“某個(gè)方法偶爾拋異常但日志沒記錄”的場(chǎng)景下幾乎是精準(zhǔn)制導(dǎo)。比如有次同行遇到一個(gè)接口偶爾返回錯(cuò)誤碼但代碼里沒打日志我建議用watch帶異常參數(shù)去抓結(jié)果沒等多久就抓到了異常棧是一個(gè)特殊的非法參數(shù)組合導(dǎo)致的本地測(cè)試完全沒覆蓋到。注意點(diǎn)watch默認(rèn)只監(jiān)控方法進(jìn)入時(shí)的信息如果你想額外看方法退出時(shí)的結(jié)果要加上-b或-e參數(shù)來控制位置或者更常用的是保持默認(rèn)然后在OGNL表達(dá)式里同時(shí)取返回值和異常即可。Arthas的做法是默認(rèn)在方法結(jié)束以后統(tǒng)一輸出所以直接查returnObj和exception是能拿到的。3.5 trace定位方法內(nèi)部耗時(shí)分布有時(shí)候接口慢但你不知道熱點(diǎn)是在內(nèi)部哪個(gè)子調(diào)用上。trace命令可以追蹤一個(gè)方法內(nèi)部的所有子調(diào)用輸出每一層的耗時(shí)以及調(diào)用次數(shù)。[arthas12345]$ trace com.example.OrderService createOrder #cost 200這個(gè)命令的含義是當(dāng)createOrder整體耗時(shí)超過200毫秒時(shí)打印方法內(nèi)部的調(diào)用鏈耗時(shí)詳情。每一行會(huì)顯示類名、方法名、耗時(shí)、調(diào)用來源。trace是我處理性能問題時(shí)最依賴的工具。比如你懷疑數(shù)據(jù)庫查詢慢但數(shù)據(jù)庫監(jiān)控又沒查到慢SQL或者懷疑HTTP外部服務(wù)超時(shí)卻不知道具體在哪個(gè)階段。trace一跑整個(gè)方法內(nèi)部的每一步耗時(shí)一目了然是內(nèi)存計(jì)算慢還是RPC調(diào)用慢還是某個(gè)循環(huán)里做了太多無用計(jì)算全都能看到。和watch不同的是trace的成本相對(duì)高一些尤其是在高頻調(diào)用方法上開啟trace會(huì)有一定的性能開銷。所以在生產(chǎn)環(huán)境使用時(shí)要控制好追蹤的目標(biāo)方法不要掛在整個(gè)入口上大規(guī)模trace更推薦在定位到大致方法后細(xì)粒度去開trace。3.6 stack方法被誰調(diào)用、調(diào)用鏈長什么樣stack命令會(huì)輸出當(dāng)前方法被調(diào)用的調(diào)用路徑簡單理解就是“誰調(diào)用了我”。用法[arthas12345]$ stack com.example.OrderService createOrder這個(gè)命令適合回答“這個(gè)方法為什么被反復(fù)觸發(fā)”、“這個(gè)入口是被人調(diào)用還是內(nèi)部定時(shí)任務(wù)觸發(fā)的”。有一次排查一個(gè)數(shù)據(jù)錯(cuò)亂問題就是想弄清楚某條數(shù)據(jù)為什么會(huì)走到一個(gè)異常分支最后用stack發(fā)現(xiàn)原來是消息消費(fèi)邏輯里間接調(diào)用了同一個(gè)方法導(dǎo)致數(shù)據(jù)狀態(tài)被重復(fù)修改。stack還支持按條件輸出比如只輸出耗時(shí)超過閾值的調(diào)用[arthas12345]$ stack com.example.OrderService createOrder #cost1000這樣既能看到調(diào)用鏈也能篩選出慢調(diào)用用來排查偶發(fā)性慢請(qǐng)求特別好使。3.7 tt時(shí)間隧道記錄方法調(diào)用的歷史現(xiàn)場(chǎng)如果說watch是“實(shí)時(shí)看每一次調(diào)用”那tt就是“把調(diào)用的現(xiàn)場(chǎng)記下來回頭慢慢看”。tt命令能記錄一段時(shí)間內(nèi)某個(gè)方法的調(diào)用快照包含入?yún)?、返回、異常、調(diào)用時(shí)間等并且你能用tt的Play功能去重放某一次調(diào)用?；居梅╗arthas12345]$ tt -t com.example.OrderService createOrder -n 20意思是記錄最近20次createOrder調(diào)用的快照。輸出里每行有一個(gè)ID如果你想看第8次調(diào)用的具體參數(shù)和返回值[arthas12345]$ tt -i 8有一次線上偶發(fā)問題最讓人頭疼的就是無法復(fù)現(xiàn)當(dāng)時(shí)我用tt掛了半小時(shí)記錄到了那一次異常調(diào)用的完整入?yún)⑷缓笥眠@個(gè)參數(shù)在測(cè)試環(huán)境一跑就復(fù)現(xiàn)了整個(gè)排查從“玄學(xué)”變成了“確定性”。tt的代價(jià)比watch更大因?yàn)樗诜椒ǔ鋈肟诙疾迦霐r截邏輯并且保存快照。所以開啟時(shí)間不要過長記錄次數(shù)也要限制比如-n 20抓完立即關(guān)閉。3.8 monitor統(tǒng)計(jì)方法調(diào)用頻率、成功率和耗時(shí)趨勢(shì)如果你想看一個(gè)方法在一段時(shí)間內(nèi)的整體表現(xiàn)比如每分鐘被調(diào)多少次、成功率如何、平均耗時(shí)多少monitor就是干這個(gè)的[arthas12345]$ monitor com.example.OrderService createOrder -c 30表示每30秒統(tǒng)計(jì)一次createOrder的調(diào)用次數(shù)、失敗次數(shù)、失敗率、平均耗時(shí)等。這個(gè)命令適合不需要看單個(gè)調(diào)用細(xì)節(jié)而是想看宏觀趨勢(shì)的場(chǎng)景。比如壓測(cè)過程中觀察某個(gè)方法的TPS、RT變化或者線上某個(gè)接口失敗率突然升高時(shí)先確認(rèn)是不是這個(gè)原因。3.9 sc、getstatic與ognl查看類信息、讀取靜態(tài)變量、執(zhí)行任意表達(dá)式這三個(gè)命令放到一起講因?yàn)樗鼈兪茿rthas里“探查類結(jié)構(gòu)”的組合拳。sc用來搜索所有已加載的類[arthas12345]$ sc *OrderService*輸出會(huì)顯示類全限定名、類加載器、類狀態(tài)。如果想看類的詳細(xì)結(jié)構(gòu)加-d參數(shù)[arthas12345]$ sc -d com.example.OrderService這樣會(huì)輸出類的修飾符、注解、父類、接口、成員變量等。getstatic用來讀取類的靜態(tài)變量[arthas12345]$ getstatic com.example.OrderService CACHE_SIZE比如某個(gè)配置類的靜態(tài)字段是在啟動(dòng)時(shí)加載的又沒辦法動(dòng)態(tài)刷新用getstatic能直接看到當(dāng)前內(nèi)存里的值判斷配置是否真的生效了。ognl是最靈活的命令它能在目標(biāo)JVM里執(zhí)行任意表達(dá)式。比如調(diào)用某個(gè)靜態(tài)方法、獲取某個(gè)對(duì)象的字段、甚至修改某個(gè)字段的值[arthas12345]$ ognl com.example.GlobalConfiggetConfig()也可以帶上下文執(zhí)行比如獲取當(dāng)前線程上下文的某個(gè)Bean[arthas12345]$ ognl -x 2 #context org.springframework.web.context.ContextLoadergetCurrentWebApplicationContext(), #bean context.getBean(orderService), #bean.queryStatus()ognl的“任意執(zhí)行”能力非常強(qiáng)但也要格外小心它相當(dāng)于給了你在生產(chǎn)環(huán)境執(zhí)行代碼的權(quán)限。尤其是在寫修改類型表達(dá)式時(shí)一定要仔細(xì)確認(rèn)不要改錯(cuò)字段。3.10 mc與redefine動(dòng)態(tài)更新類邏輯redefine是我用得比較謹(jǐn)慎但關(guān)鍵時(shí)刻能救命的命令。它允許你修改已加載類的字節(jié)碼相當(dāng)于在運(yùn)行中“熱更新”類的邏輯。基本流程是先用jad把目標(biāo)類反編譯出來導(dǎo)出源碼到本地改完邏輯以后用mc命令編譯成.class文件再用redefine命令把它加載進(jìn)JVM。步驟如下[arthas12345]$ jad --source-only com.example.OrderService /tmp/OrderService.java # 然后在本機(jī)編輯 /tmp/OrderService.java改好邏輯 [arthas12345]$ mc /tmp/OrderService.java -d /tmp/output [arthas12345]$ redefine /tmp/output/com/example/OrderService.class注意事項(xiàng)redefine只改變后續(xù)新執(zhí)行的邏輯對(duì)已經(jīng)執(zhí)行到一半的調(diào)用是無效的而且redefine不會(huì)改變類的結(jié)構(gòu)你不能新增字段、不能新增方法簽名、不能增加銷毀原結(jié)構(gòu)。一般我拿它來做臨時(shí)補(bǔ)丁加一個(gè)日志輸出、調(diào)一個(gè)參數(shù)值等等等新的版本發(fā)上去以后就不要再依賴redefine的臨時(shí)邏輯了。警告redefine本質(zhì)上是修改運(yùn)行中的JVM內(nèi)存里的類定義風(fēng)險(xiǎn)等級(jí)很高只適合臨時(shí)應(yīng)急。不到萬不得已我建議你先嘗試用ognl修改配置值、用dashboard觀察趨勢(shì)最后才考慮redefine。而且redefine前一定要把原始類文件備份好保證能回滾。4. 實(shí)戰(zhàn)案例拆解從CPU飆高到接口超時(shí)的排查全流程4.1 案例一CPU突然飆到500%的線程定位事情大約是這樣的某跨平臺(tái)訂單服務(wù)的CPU在下午兩點(diǎn)左右突然飆高監(jiān)控報(bào)警直接打到群里。按照以前的處理方式第一件事是登錄機(jī)器看top找到CPU高進(jìn)程的PID然后jstack導(dǎo)出線程棧再手動(dòng)去找nid對(duì)應(yīng)的線程。這一套流程本身沒問題但jstack的線程棧里全是十六進(jìn)制線程ID要對(duì)應(yīng)到業(yè)務(wù)線程還得人工比對(duì)效率很低。有了Arthas之后流程變成了這樣先附著到目標(biāo)進(jìn)程執(zhí)行dashboard馬上就能看到哪個(gè)線程的CPU占用異常高通常那個(gè)線程的ID還會(huì)反復(fù)出現(xiàn)在刷新面板的最前面。然后執(zhí)行[arthas12345]$ thread -n 3Arthas會(huì)直接打印出CPU占用最高的三個(gè)線程的完整堆棧自動(dòng)把線程名稱、CPU時(shí)間、堆棧都組裝好了。那次我一眼就看到某個(gè)線程卡在一個(gè)XML解析方法內(nèi)部最底層是在JVM里做正則匹配數(shù)據(jù)量一大CPU直接被吃滿。順著棧里的業(yè)務(wù)類名很快就對(duì)應(yīng)到了代碼行發(fā)現(xiàn)是一個(gè)對(duì)超大字符串做了多次replaceAll的循環(huán)屬于典型的正則回溯問題。這個(gè)案例關(guān)鍵點(diǎn)在于thread -n非常省事省掉了jstack 人工匹配nid的過程。如果只靠jstack十幾分鐘能定位就算不錯(cuò)了用Arthas一兩分鐘就鎖定了根因。4.2 案例二接口偶發(fā)超時(shí)怎么抓到慢調(diào)用的具體位置另一個(gè)印象深刻的案例是某個(gè)查詢接口偶發(fā)超時(shí)時(shí)好時(shí)壞。我先打開trace守護(hù)在入口方法上[arthas12345]$ trace com.example.QueryService queryDetail #cost 1000跑了大約十分鐘抓到了一次耗時(shí)1200毫秒的調(diào)用快照。結(jié)果顯示大部分耗時(shí)花費(fèi)在調(diào)用下游的某個(gè)HTTP接口上時(shí)間約900毫秒而我對(duì)這個(gè)下游HTTP接口的容錯(cuò)判斷閾值是500毫秒所以導(dǎo)致上游超時(shí)。順著這個(gè)線索檢查了下游服務(wù)的響應(yīng)時(shí)間分布發(fā)現(xiàn)是對(duì)方服務(wù)在整點(diǎn)時(shí)刻做批量任務(wù)導(dǎo)致該時(shí)段RT拉長。后續(xù)調(diào)整了調(diào)用方的超時(shí)時(shí)間并且給這個(gè)下游調(diào)用增加了本地緩存問題徹底解決。如果不用trace靠加日志排查這種偶發(fā)問題可能要發(fā)好幾個(gè)版本才能抓到一個(gè)慢樣本而且很有可能會(huì)因?yàn)殡S機(jī)性導(dǎo)致錯(cuò)過現(xiàn)場(chǎng)。trace的價(jià)值在于它不需要任何提前埋點(diǎn)事后診斷能力很強(qiáng)。4.3 案例三方法返回值為什么和預(yù)期不一致還有過一次經(jīng)歷是同事在排查一個(gè)對(duì)賬系統(tǒng)的金額計(jì)算差異。日志里打了入?yún)⒁泊蛄俗罱K返回值但中間經(jīng)過了好幾個(gè)子方法的嵌套調(diào)用看不出是哪一步把金額改錯(cuò)了。這種情況watchstack組合拳非常管用。先watch最外層方法看看入?yún)⒑妥罱K返回值如果出入?yún)]問題就深入內(nèi)部方法分別watch找到第一個(gè)出現(xiàn)差異的那一層。當(dāng)時(shí)我們用watch單獨(dú)盯了一個(gè)金額調(diào)整的方法抓到的入?yún)⑹且粋€(gè)對(duì)象對(duì)象的某個(gè)金額字段是100.00但returnObj返回時(shí)變成了99.99。再往下一層看發(fā)現(xiàn)里面調(diào)用了一個(gè)舍入工具舍入模式默認(rèn)是向下取整而業(yè)務(wù)方預(yù)期是四舍五入。順著這個(gè)鏈路往下追又用stack查了舍入工具方法的調(diào)用來源確認(rèn)只有這一條業(yè)務(wù)路徑走錯(cuò)了舍入模式。整個(gè)過程沒有重啟、沒有改動(dòng)一行代碼一個(gè)下午就把根因挖干凈了。5. 常見問題與排查思路Arthas使用中踩過的坑5.1 attach失敗提示Unable to open socket file這個(gè)報(bào)錯(cuò)最常見的場(chǎng)景是你用的系統(tǒng)賬號(hào)和目標(biāo)Java進(jìn)程的啟動(dòng)賬號(hào)不一致。比如應(yīng)用是用service用戶啟動(dòng)的你sudo到root用戶執(zhí)行Arthas那么Arthas無法讀取目標(biāo)JVM的臨時(shí)目錄文件就會(huì)出現(xiàn)socket文件路徑相關(guān)報(bào)錯(cuò)。解決辦法很直接換成和啟動(dòng)進(jìn)程相同的用戶執(zhí)行。如果一定要root操作可以考慮安裝Arthas到目標(biāo)用戶目錄下并用su切換到該用戶后再啟動(dòng)。5.2 所有命令都能執(zhí)行但watch/trace沒有任何輸出這個(gè)有兩種可能。一種是方法已經(jīng)啟動(dòng)了很久沒有被調(diào)用你可以先用monitor確認(rèn)調(diào)用是否真的存在。另一種是方法是在其他類加載器里加載的而Arthas默認(rèn)匹配的類加載器集合不對(duì)。特別是用到自定義類加載器、OSGi環(huán)境時(shí)需要用sc -d確認(rèn)類的類加載器信息然后用classloader命令配合指定類加載器再觀察[arthas12345]$ classloader -l然后指定類加載器的索引再對(duì)目標(biāo)方法執(zhí)行watch。你也可以用watch時(shí)帶上-c參數(shù)指定類加載器的hash值。當(dāng)然現(xiàn)實(shí)中多數(shù)Spring Boot應(yīng)用是單一類加載器基本不會(huì)遇到這類問題。5.3 對(duì)象層級(jí)太深輸出被截?cái)嗄J(rèn)情況下Arthas為了避免把大量數(shù)據(jù)一股腦打印出來會(huì)限制OGNL表達(dá)式輸出對(duì)象的展開深度。如果你想看更多字段用-x參數(shù)調(diào)大即可。比如[arthas12345]$ watch com.example.OrderService createOrder {params, returnObj} -x 5如果-x調(diào)得太大導(dǎo)致輸出非常長影響閱讀可以同時(shí)用-n限制觀察次數(shù)比如-n 3只輸出三次結(jié)果。5.4 ognl表達(dá)式寫復(fù)雜了容易出錯(cuò)怎么調(diào)試ognl表達(dá)式在Arthas里雖然功能強(qiáng)大但一旦寫復(fù)雜了語法錯(cuò)誤可能比業(yè)務(wù)代碼本身還難排查。我的習(xí)慣是先在本地用一個(gè)簡單的Spring Boot應(yīng)用試表達(dá)式確認(rèn)無誤了再拿到生產(chǎn)環(huán)境執(zhí)行。還有一個(gè)技巧是拆分成小的表達(dá)式逐步驗(yàn)證先獲取對(duì)象引用再訪問字段不要一口氣寫超長的OGNL鏈條。比如你想拿到Spring容器里的某個(gè)Bean并調(diào)用方法可以先執(zhí)行[arthas12345]$ ognl #ctxorg.springframework.web.context.ContextLoadergetCurrentWebApplicationContext(), #ctx確認(rèn)這個(gè)對(duì)象能拿得到再去擴(kuò)展后面的字段訪問。5.5 Arthas本身對(duì)性能的影響很多人會(huì)擔(dān)心Arthas附著之后影響業(yè)務(wù)性能。實(shí)話實(shí)說開啟watch/trace/monitor這類命令會(huì)對(duì)目標(biāo)方法做字節(jié)碼增強(qiáng)有一定額外開銷。如果目標(biāo)是低頻方法影響幾乎可以忽略如果目標(biāo)是高QPS方法性能損耗會(huì)明顯一些。所以生產(chǎn)使用有幾個(gè)原則只在需要排查的時(shí)間窗口打開命令用-n限制記錄次數(shù)用完馬上關(guān)閉。不要同時(shí)開啟大量方法的trace/watch。優(yōu)先用dashboard和thread這類低開銷命令做初步排查鎖定目標(biāo)后再用watch/trace做精細(xì)分析。5.6 Arthas版本太舊導(dǎo)致命令行為不一致Arthas迭代速度比較快一些命令的參數(shù)和輸出格式在舊版本里可能不兼容。如果你發(fā)現(xiàn)某個(gè)命令行為和文檔不一致優(yōu)先檢查版本[arthas12345]$ version建議下載最新release版本并保持目標(biāo)環(huán)境和運(yùn)維腳本里使用的版本一致免得今天在這臺(tái)機(jī)器上可用、明天換臺(tái)機(jī)器就報(bào)錯(cuò)。5.7 容器環(huán)境里attach的特殊情況容器化部署越來越普遍在容器里用Arthas有時(shí)會(huì)遇到PID namespace限制導(dǎo)致attach失敗或者容器里沒有安裝完整JDK只有JRE。解決辦法是基礎(chǔ)鏡像里提前安裝JDK而不是只有JRE。使用Arthas的agent模式啟動(dòng)應(yīng)用避免動(dòng)態(tài)attach的限制。容器內(nèi)執(zhí)行Arthas時(shí)確認(rèn)/tmp目錄可寫并且PID對(duì)得上宿主機(jī)還是容器內(nèi)的Namespace。5.8 無法訪問8563端口如果Arthas在遠(yuǎn)程機(jī)器上運(yùn)行而你想從本地連上去操作需要確保8563端口默認(rèn)telnet端口和8562端口默認(rèn)HTTP端口被你當(dāng)前的網(wǎng)絡(luò)允許連接。一些公司內(nèi)部網(wǎng)絡(luò)策略較嚴(yán)格需要提網(wǎng)絡(luò)放行申請(qǐng)或者你可以用ssh隧道把遠(yuǎn)程端口映射到本地再訪問這樣就不用額外開防火墻端口了。整體來說Arthas確實(shí)是一個(gè)讓我“用過就回不去”的工具。它解決的不是某一個(gè)具體的問題而是把人從“盲人摸象”的排查模式里解放出來讓你能直接看到運(yùn)行中JVM的內(nèi)部。剛開始接觸時(shí)可能會(huì)被它的命令數(shù)量嚇到但只要把dashboard、thread、jad、watch、trace、tt這幾個(gè)核心命令用熟就已經(jīng)能覆蓋絕大部分日常排查場(chǎng)景了。我自己一次一次踩坑之后才慢慢意識(shí)到滿屏的命令并不可怕關(guān)鍵是把每一條的適用時(shí)機(jī)記清楚——先看全局再鎖線程然后用watch或trace深入方法內(nèi)部再用ognl處理疑難雜癥這套思路比硬記命令參數(shù)重要得多。希望這篇文章能幫你少走一些彎路也歡迎你把這些命令在測(cè)試環(huán)境多試幾遍熟能生巧之后線上問題再也不用靠“重啟大法”來解決了。