背景:
一次線上問題的綜合排查排查,兩個相同的系統的某個模塊,數據量更少的系統查詢更慢。
先說下整體思路:
- 查看系統整理負載,網絡有100左右毫秒的延遲,看起來影響不大
- 查看正序運行整體情況,一次查詢會經歷3次FGC,有問題,解決后雖然會快一些但是還是有點慢
- 跟蹤調用棧,發現有點在獲查詢結果的時候特別慢
- 排查是否有mysql慢查詢(定義為1秒以上的查詢),結果是沒有
- 通過arthas發現調用了20多次查詢,每次網絡延遲100ms,加起來就有2s了,定位出問題。
這樣看起來arthas真的很強大,它不僅僅能處理上述問題,還能....
- 這個類從哪個 jar 包加載的?為什么會報各種類相關的 Exception?
- 我改的代碼為什么沒有執行到?難道是我沒 commit?分支搞錯了?
- 遇到問題無法在線上 debug,難道只能通過加日志再重新發布嗎?
- 線上遇到某個用戶的數據處理有問題,但線上同樣無法 debug,線下無法重現!
- 是否有一個全局視角來查看系統的運行狀況?
- 有什么辦法可以監控到JVM的實時運行狀態?
- 代碼出現異常,怎么能獲取請求參數和返回值。
Arthas到底是什么
Arthas 是Alibaba開源的Java診斷工具,采用命令行交互模式,提供了豐富的功能,是排查jvm相關問題的利器。
在逛github時,發現了這款利器,深入了解之后,簡直驚為天人。下面先列舉一下它能做的一些事情:
- 提供性能看板,包括線程、cpu、內存等信息,並且會定時的刷新。
- 根據各種條件查看線程快照。比如找出cpu占用率最高的n個線程等
- 輸出jvm的各種信息,如gc算法、jdk版本、ClassPath等
- 查看/設置sysprop和sysenv
- 查看某個類的靜態屬性,也可以通過ognl語法執行一些語句
- 查看已加載的類的詳細信息,比如這個類從哪個jar包加載的。也可以查看類的方法的信息
- dump某個類的字節碼到指定目錄
- 直接反編譯指定的類
- 查看類加載器的一些信息
- 可以讓jvm重新加載某個類
- 監控方法的執行,同時可以獲取到執行的入參、出參以及拋出的異常
- 追蹤方法執行的調用棧,以及各個方法的調用時間
Arthas運行原理
Arthas命令列表
athas的各個命令
sc 和 sm
- 通過sc可以查看已加載類的相關信息,比如該類是從哪個jar包加載的,被哪個類加載器加載的,以及是否是接口等等。
- sm查看已加載類的方法詳情。
dashboard
進入當前系統的實時數據面板,按 ctrl+c 退出。這個面板會實時刷新,其中包括線程信息、內存信息、gc信息、還有一些運行時的數據。
另外,當運行在Ali-tomcat時,會顯示當前tomcat的實時信息,如HTTP請求的qps, rt, 錯誤數, 線程池信息等等。
thread
通過thread命令可以查看當前jvm進程的線程詳情。可以查看線程的cpu使用時間占比,通過指定各種參數可以找出最忙的幾個線程,以及阻塞其他線程的線程。具體如何使用這里不多做介紹,大家可以去看arthas的官方文檔。
當前最忙的前N個線程並打印堆棧
thread -i 5000
thread -i 5000
jvm
通過jvm命令直接輸出當前jvm的各種信息。
getstatic
通過getstatic命令可以方便的查看類的靜態屬性。
getstatic demo.MahtGame random
sysprop和sysenv
- 通過sysprop可以查看所有的系統變量,也可以設置某個系統變量。
- 同理,通過sysenv可以查看所有的操作系統環境變量,也可以查看設置某個環境變量。
ognl
執行ognl表達式,可執行任意代碼
Ognl @demo.MathGame@random
動態修改日志級別
- 通過ognl獲取對應類上的logger對象實現類
- sc命令來查看具體從哪個jar包里加載的,sc -d org.apache.log4j.Logger
- 通過ognl修改日志級別
更詳細的介紹:https://github.com/alibaba/arthas/issues/11
dump
將已加載類的字節碼dump到本地磁盤上。
jad
有時我們經常會不確定線上或者測試環境的包是否是我們修改過的,這時候就可以通過jad反編譯來看下。
反編譯指定已加載類的源碼,jad demo.MathGame
classloader
將 JVM 中所有的classloader的信息統計出來,並可以展示繼承樹,urls等。
redafine
該命令可以加載外部的.class文件,然后覆蓋 jvm已加載的類。注意,這個命令不一定都能覆蓋成功,如果添加了新的field,就不會加載成功。
關於redefine,arthas的github上有個非常經典的userCase:
https://github.com/alibaba/arthas/issues/263
動態更新代碼,不用重啟jvm
watch
- 讓你能方便的觀察到指定方法的調用情況。能觀察到的范圍為:返回值、拋出異常、入參,通過編寫 OGNL 表達式進行對應變量的查看。
- watch的使用姿勢比較豐富,可以在四個不同的場景觀察方法的執行。比如方法調用之前、方法調用之后、方法異常之后、方法結束之后。默認觀察的是方法結束之后。
- 如果觀察的是方法結束之后的場景,由於入參可能在執行方法時被改變,所以此時輸出的可能不是真正的入參。因此,要看真正的入參,要看方法調用之前的,也就是加上-b的參數。
- 另外,使用-b參數觀察的話,則觀察不到方法返回的結果以及拋出的異常了。
參數名稱 | 參數說明 |
---|---|
class-pattern | 類名表達式匹配 |
method-pattern | 方法名表達式匹配 |
express | 觀察表達式 |
condition-express | 條件表達式 |
[b] | 在方法調用之前觀察 |
[e] | 在方法異常之后觀察 |
[s] | 在方法返回之后觀察 |
[f] | 在方法結束之后(正常返回和異常返回)觀察 |
[E] | 開啟正則表達式匹配,默認為通配符匹配 |
[x:] | 指定輸出結果的屬性遍歷深度,默認為 1 |
[n:] | 只執行n次,默認會不斷輸出,除非用戶按下cltr+c |
# 觀察CommonTest的test方法 # 輸出 入參、返回結果、拋出的異常 —— 輸出的內容可以動態調整 # 后面跟着的是 條件表達式,表示耗時超過10ms才輸出 # -n 表示只執行一次,-x表示 入參和返回結果的展開層次為5層 watch *.CommonTest test "{params,returnObj,throwExp}" '#cost>10' -x 5 -n 1 # 耗時大於10ms並且第一個參數等於1才輸出 watch *.CommonTest test "{params,returnObj,throwExp}" '#cost>10 && params[0]==1' -x 5 -n 1 # 第一個參數大於1 並且第二個參數等於hello才輸出 watch *.CommonTest test "{params,returnObj,throwExp}" 'params[0]>1 && params[1]=="hello"' -x 5 -n 1 # 第一個參數小於5或者第二個參數等於"world"就輸出 watch *.CommonTest test "{params,returnObj,throwExp}" 'params[0]<5 || params[1]=="wolrd"' -x 5 -n 1 # 第一個參數的name字段等於world時才輸出。 # 由於在方法執行過程中參數的name屬性可能發生改變,因此加上-b才能觀察到真正的入參 watch -b *.CommonTest test "{params,returnObj,throwExp}" 'params[0].name=="wolrd"' -x 5 -n 1 # 由於同時指定了-s和-b,所以方法被調用一次,就會輸出2次結果(兩個場景分開輸出),分別是方法被調用前,和返回之后 # 注意,這里如果-n只設置成1,那么只會輸出-b對應的輸出,-s對應的輸出由於沒有次數了就無法輸出了 watch *.CommonTest test '{params,returnObj,throwExp}' -x 5 -n 2 -s -b
在填寫條件表達式時要注意一點,條件表達式中的params默認都是獲取的方法執行完后的參數信息,比如入參a的屬性name方法執行前是"hello",在方法執行后變成了"world",那么條件表達式傳入'params[0].name="hello"'將不會輸出,只有填入'params[0].name="hello"'才可以匹配上。這點對於后面的trace、stack命令也是一樣的。
查看方法輸入參數/返回值/異常信息,watch demo.MathGame primeFactors "{params,returnObj}" -x 2
monitor
monitor命令可以監控方法的執行情況。比如調用成功次數,失敗次數,失敗率、平均執行時間等等。默認120秒輸出一次,也就是說,當我們輸入monitor命令之后,每120秒就會輸出一次統計結果。
通過-c參數可以修改輸出頻率,支持通配符和正則表達式。
monitor -c 5 demo.MathGame primeFactors
trace
方法內部調用路徑,並輸出方法路徑上的每個節點上耗時,tt命令會記錄每次方法調用的各種信息。它和watch有些相似但是它能記錄下各個時間點的調用信息,之后隨時查看,甚至replay這次調用。
trace demo.MathGame run
tt
timetunnel,記錄下指定方法每次調用的入參和返回信息,並能對這些不同的時間下調用進行觀測,同時可回放該方法調用
tt -t demo.MathGame primeFactors
直接重放請求參數
1.使用tt –t 類名次 方法名次 2.tt –play -i 1000
另外介紹幾個我經常用的工具,jmap,jstat,jstack,dump這些基本的就不介紹了。
Tprofiler
TProfiler是一個可以在生產環境長期使用的性能分析工具.它同時支持剖析和采樣兩種方式,記錄方法執行的時間和次數,生成方法熱點 對象創建熱點 線程狀態分析等數據,為查找系統性能瓶頸提供數據支持.
TProfiler在JVM啟動時把時間采集程序注入到字節碼中,整個過程無需修改應用源碼.運行時會把數據寫到日志文件,一般情況下每小時輸出的日志小於50M.
show-busy-java-threads
- 查找cpu性能消耗過程
top命令找出消耗CPU高的Java進程及其線程id:
開啟線程顯示模式(top -H,或是打開top后按H)
按CPU使用率排序(top缺省是按CPU使用降序,已經合要求;打開top后按P可以顯式指定按CPU使用降序)
記下Java進程id及其CPU高的線程id - 查看消耗CPU高的線程棧:
用進程id作為參數,jstack出有問題的Java進程
手動轉換線程id成十六進制(可以用printf %x 1234)
在jstack輸出中查找十六進制的線程id(可以用vim的查找功能/0x1234,或是grep 0x1234 -A 20) - 查看對應的線程棧,分析問題
查問題時,會要多次上面的操作以分析確定問題,這個過程太繁瑣太慢了。
參考:https://blog.csdn.net/u013332124/article/details/84888074#11_redefine_157