Arthas使用指南

常用命令： trace -E com.topsoft.aaf.web.controller.outer.v2.authclient.OrganAction getUserSimpleByResCode -v -n 5 '#cost>2000'

原文：https://www.jianshu.com/p/95449939cca3

 

Arthas

一、簡介

Arthas 是Alibaba開源的Java診斷工具。安裝在系統所在服務器。可以幫助開發人員或者運維人員查找問題，分析性能，bug追蹤。

二、解決什么問題 & 適用場景

解決問題：
1、以全局視角來查看系統的運行狀況、健康狀況。
2、反編譯源碼，查看jvm加載的是否為預期的文件內容。
3、查看某個方法的返回值，參數等等。
4、方法內調用路徑及各方法調用耗時。
5、查看jvm運行狀況。
6、外部.class文件重新加載到jvm里。
等等.....

場景：
1）調用接口時，接口返回異常信息，如果該異常信息沒有清晰的定位到代碼，那么我們通常只能依靠大腦回憶代碼，來估計錯誤發生地了，如果無法估計，一般情況下就會進入測試環境，模擬復現，如果無法復現 _。
2）這個查詢，耗時20s，我們想要分析一下到底是哪些代碼導致的。但是該方法內部又穿插調用了其它業務功能方法，難道手寫System.currentTimeMillis()自己做減運算，還是guava的StopWatch亦或是commons的StopWatch？這幾種方式需要我們手動嵌入代碼，容易遺漏、費力還費時。
等等，就不一一舉例了。
arthas可以為我們解決上述問題，幫助程序員盡早下班，盡早交代。

三、安裝&啟動

下載: wget https://alibaba.github.io/arthas/arthas-boot.jar

啟動: java -jar arthas-boot.jar

[INFO] arthas-boot version: 3.0.5.2 [INFO] Process 6020 already using port 3658 [INFO] Process 6020 already using port 8563 [INFO] Found existing java process, please choose one and hit RETURN. *[1]: 6020 org.apache.catalina.startup.Bootstrap [2]: 16420 org.apache.catalina.startup.Bootstrap [3]: 7833 org.apache.catalina.startup.Bootstrap [4]: 19036 org.apache.catalina.startup.Bootstrap 出現上述命令提示，是因為在這個服務器上，存在4個正在運行的java程序，而序號之后的數字就是pid，我們選取對應的pid，然后回車即可。 [INFO] arthas home: /root/.arthas/lib/3.1.4/arthas [INFO] The target process already listen port 3658, skip attach. [INFO] arthas-client connect 127.0.0.1 3658 ,---. ,------. ,--------.,--. ,--. ,---. ,---. / O \ | .--. ''--. .--'| '--' | / O \ ' .-' | .-. || '--'.' | | | .--. || .-. |`. `-. | | | || |\ \ | | | | | || | | |.-' | `--' `--'`--' '--' `--' `--' `--'`--' `--'`-----' wiki https://alibaba.github.io/arthas tutorials https://alibaba.github.io/arthas/arthas-tutorials version 3.1.4 pid 6020 time 2019-10-14 17:56:41 [arthas@6020]$ 啟動成功！ 

四、相關命令

僅以主要的幾個命令作為展示，具體命令及參數可以參閱官方文檔。

1）輸入dashboard，回車，儀表盤顯示當前進程相關信息。

____________________________________________________________________________________________________________________________________________________________________________________________________________________________________________
| ①Thread相關信息 | 線程id 線程名稱 線程組 線程優先級 線程狀態 線程消耗的cpu百分比 運行總時間 線程當前的中斷位狀態 是否守護線程 | ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON | 188 Timer-for-arthas-dashboard-f5864b5b-762a-4fb5-8cc5-65559bd6 system 10 RUNNABLE 19 0:0 false true | 36 pool-1-thread-1 main 5 TIMED_WAITING 5 0:1 false false | 33 Abandoned connection cleanup thread main 5 TIMED_WAITING 0 0:0 false true | 179 AsyncAppender-Worker-arthas-cache.result.AsyncAppender system 9 WAITING 0 0:0 false true | 12 AsyncFileHandlerWriter-225534817 main 5 TIMED_WAITING 0 0:0 false true | 94 Attach Listener system 9 RUNNABLE 0 0:0 false true | 70 ContainerBackgroundProcessor[StandardEngine[Catalina]] main 5 TIMED_WAITING 0 0:0 false true | 34 Druid-ConnectionPool-Create-300669762 main 5 WAITING 0 0:0 false true | 35 Druid-ConnectionPool-Destroy-300669762 main 5 TIMED_WAITING 0 0:0 false true | 3 Finalizer system 8 WAITING 0 0:0 false true | 13 GC Daemon system 2 TIMED_WAITING 0 0:0 false true | 14 NioBlockingSelector.BlockPoller-1 main 5 RUNNABLE 0 0:0 false true | 15 NioBlockingSelector.BlockPoller-2 main 5 RUNNABLE 0 0:0 false true | 2 Reference Handler system 10 WAITING 0 0:0 false true | 4 Signal Dispatcher system 9 RUNNABLE 0 0:0 false true | 76 ajp-nio-38009-Acceptor-0 main 5 RUNNABLE 0 0:0 false true | 74 ajp-nio-38009-ClientPoller-0 main 5 RUNNABLE 0 0:0 false true | 75 ajp-nio-38009-ClientPoller-1 main 5 RUNNABLE 0 0:0 false true | 187 as-command-execute-daemon system 10 TIMED_WAITING 0 0:0 false true | 73 http-nio-37080-Acceptor-0 main 5 RUNNABLE 0 0:0 false true | 71 http-nio-37080-ClientPoller-0 main 5 RUNNABLE 0 0:0 false true | 72 http-nio-37080-ClientPoller-1 main 5 RUNNABLE 0 0:0 false true | | ②內存信息 ③垃圾回收 | Memory used total max usage GC | （堆） （垃圾回收次數） | heap 424M 1897M 1897M 22.37% gc.ps_scavenge.count 19 | （伊甸園） （垃圾回收消耗時間） | ps_eden_space 311M 387M 403M 77.28% gc.ps_scavenge.time(ms) 1405 | （幸存者區） （標記-清除算法的次數） | ps_survivor_space 40M 144M 144M 27.74% gc.ps_marksweep.count 3 | （老年代） （標記-清除算法的消耗時間） | ps_old_gen 72M 1365M 1365M 5.32% gc.ps_marksweep.time(ms) 446 | （非堆區） | nonheap 137M 141M -1 97.49% | （代碼緩存區） | code_cache 40M 41M 240M 16.99% | （元空間） | metaspace 86M 89M -1 97.09% | （壓縮空間） | compressed_class_space 10M 10M 1024M 0.99% | direct 80K 80K - 100.00% | mapped 0K 0K - NaN% | | ④運行信息 | Runtime | os.name Linux | os.version 3.10.0-957.1.3.el7.x86_64 | java.version 1.8.0_101 | java.home /opt/jdk1.8.0_101/jre | systemload.average 0.03 | processors 8 | uptime 11956s |________________________________________________________________________________________________________________________________________________________________________________________________________________________________________ 說明 ID: Java級別的線程ID，注意這個ID不能跟jstack中的nativeID一一對應 NAME: 線程名 GROUP: 線程組名 PRIORITY: 線程優先級, 1~10之間的數字，越大表示優先級越高 STATE: 線程的狀態 CPU%: 線程消耗的cpu占比，采樣100ms，將所有線程在這100ms內的cpu使用量求和，再算出每個線程的cpu使用占比。 TIME: 線程運行總時間，數據格式為分：秒 INTERRUPTED: 線程當前的中斷位狀態 DAEMON: 是否是daemon線程 通過上述信息，可以幫助我們快速定位相關問題線程。 

2）查看具體線程信息使用 [thread 線程id]

3）查看類里某個方法的返回值和入參

命令+類完全限定名+監測方法+表達式
watch cn.asae.e.contract.web.ContractSubjectController getContractSubjectLogs "{params,returnObj}"

表達式核心變量列表：
loader      本次調用類所在的 ClassLoader clazz 本次調用類的 Class 引用 method 本次調用方法反射引用 target 本次調用類的實例 params 本次調用參數列表，這是一個數組，如果方法是無參方法則為空數組 returnObj 本次調用返回的對象。當且僅當 isReturn==true 成立時候有效，表明方法調用是以正常返回的方式結束。如果當前方法無返回值 void，則值為 null throwExp 本次調用拋出的異常。當且僅當 isThrow==true 成立時有效，表明方法調用是以拋出異常的方式結束。 isBefore 輔助判斷標記，當前的通知節點有可能是在方法一開始就通知，此時 isBefore==true 成立，同時 isThrow==false 和 isReturn==false，因為在方法剛開始時，還無法確定方法調用將會如何結束。 isThrow 輔助判斷標記，當前的方法調用以拋異常的形式結束。 isReturn 輔助判斷標記，當前的方法調用以正常返回的形式結束。 

 

return.png

4）方法調用路徑、耗時解析

方法內部調用路徑，並輸出方法路徑上的每個節點上耗時
trace cn.asae.e.contract.web.ContractController getContract

__________________________________________________________________________________________________________________________________________________________________
| 時間戳 線程名稱 線程id 是否守護進程 優先級 線程上下文類加載器 | `---ts=2019-10-21 16:33:13;thread_name=http-nio-37080-exec-5;id=52;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.WebappClassLoader@67fff846 | | 調用信息 - 方法攔截器 - 目標方法 | `---[1483.931493ms] cn.asae.e.contract.web.ContractController$$EnhancerBySpringCGLIB$$feabdb7f:getContract() | | `---[1483.715988ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() #0 | | `---[1482.519392ms] cn.asae.e.contract.web.ContractController:getContract() | | +---[0.03355ms] cn.asae.core.common.response.v2.ResponseBodyV2:<init>() #243 | | +---[0.016195ms] cn.asae.core.common.token.TokenCache:getInstance() #246 | | +---[0.01442ms] cn.asae.core.common.token.TokenCache:get() #246 | | +---[0.02442ms] cn.asae.e.common.model.Op:createOp() #246 | | +---[161.579687ms] cn.asae.e.contract.service.ContractService:getContract() #249 | | +---[164.980125ms] cn.asae.e.contract.service.ContractService:getContractOcrs() #251 | | +---[0.036474ms] com.google.common.collect.Maps:newHashMap() #255 | | +---[158.223852ms] cn.asae.e.contract.service.ContractService:getContractMembers() #260 | | +---[0.025848ms] com.google.common.collect.Lists:newArrayList() #263 | | +---[0.024837ms] cn.asae.e.contract.model.ContractVO:getContractNum() #264 | | +---[160.942618ms] cn.asae.e.contract.service.ContractService:getContracts() #266 | | +---[0.024172ms] org.apache.commons.collections.MapUtils:isNotEmpty() #271 | | +---[198.281335ms] cn.asae.e.organization.service.AccountService:getAccountLite() #291 | | +---[159.761087ms] cn.asae.e.organization.service.DepartmentService:getDepartment() #295 | | +---[0.009013ms] org.apache.commons.collections.MapUtils:isNotEmpty() #297 | | +---[0.013967ms] cn.asae.e.contract.model.ContractVO:getSignId() #312 | | +---[0.006482ms] com.google.common.collect.Lists:newArrayList() #312 | | +---[160.503511ms] cn.asae.e.organization.service.AccountService:getAccountLite() #312 | | +---[0.015528ms] cn.asae.e.contract.model.ContractVO:getDepartmentId() #316 | | +---[0.006504ms] com.google.common.collect.Lists:newArrayList() #316 | | +---[159.023976ms] cn.asae.e.organization.service.DepartmentService:getDepartment() #316 | | +---[0.005827ms] cn.asae.e.contract.model.ContractVO:getSignId() #319 | | +---[0.017222ms] cn.asae.e.organization.model.Account:<init>() #319 | | +---[0.0142ms] cn.asae.e.organization.model.Account:getFullname() #319 | | +---[0.012931ms] cn.asae.e.contract.model.ContractVO:setSignName() #319 | | +---[0.00492ms] cn.asae.e.contract.model.ContractVO:getDepartmentId() #321 | | +---[0.010856ms] cn.asae.e.organization.model.DepartmentVO:<init>() #321 | | +---[0.018637ms] cn.asae.e.organization.model.DepartmentVO:getName() #323 | | +---[0.011019ms] cn.asae.e.contract.model.ContractVO:setDepartmentName() #323 | | +---[0.010145ms] cn.asae.e.organization.model.DepartmentVO:getOrganizationName() #324 | | +---[0.010541ms] cn.asae.e.contract.model.ContractVO:setOrganizationName() #324 | | +---[0.005493ms] com.google.common.collect.Maps:newHashMap() #326 | | +---[0.014093ms] cn.asae.core.common.response.v2.ResponseBodyV2:init() #333 | | +---[145.783843ms] cn.asae.e.contract.service.ContractService:addContractLog() #335 | | `---[0.386367ms] cn.asae.core.common.response.v2.ResponseBodyV2:toResponse() #342 | |________________________________________________________________________________________________________________________________________________________________| 

5）時空隧道
方法執行數據的時空隧道，記錄下指定方法每次調用的入參和返回信息，並能對這些不同的時間下調用進行觀測

tt -t cn.asae.e.contract.web.ContractSubjectController getContractSubjectLogs
-t 代表記錄下每次方法執行情況

_________________________________________________________________________________________________________________________________________________________________
| INDEX | TIMESTAMP | COST(ms) | IS-RET | IS-EXP | OBJECT | CLASS | METHOD | |-------|---------------------|------------|--------|--------|------------|--------------------------------------------------------|----------------------------| | 1000 | 2019-10-17 16:46:20 | 315.436761 | true | false | 0x2eb74ebb | ContractSubjectController | getContractSubjectLogs | | 1001 | 2019-10-17 16:46:20 | 326.193324 | true | false | 0xeb982ed6 | ContractSubjectController$$EnhancerBySpringCGLIB$$23d1 | getContractSubjectLogs | |_______|_____________________|____________|________|________|____________|________________________________________________________|____________________________| 表格字段說明 表格字段 字段解釋 INDEX 時間片段記錄編號，每一個編號代表着一次調用，后續tt還有很多命令都是基於此編號指定記錄操作，非常重要。 TIMESTAMP 方法執行的本機時間，記錄了這個時間片段所發生的本機時間 COST(ms) 方法執行的耗時 IS-RET 方法是否以正常返回的形式結束 IS-EXP 方法是否以拋異常的形式結束 OBJECT 執行對象的hashCode()，注意，曾經有人誤認為是對象在JVM中的內存地址，但很遺憾他不是。但他能幫助你簡單的標記當前執行方法的類實體 CLASS 執行的類名 METHOD 執行的方法名 

為什么調用一次接口會出現兩條記錄？
因為SpringMVC初始化時會通過cglib生成ContractSubjectController的代理對象，DispatchServlet真正使用的卻是這個代理對象，在代理對象里調用ContractSubjectController的getContractSubjectLogs方法，所以當我們執行tt watch命令時，會出現兩條。

順序如下：

ContractSubjectController$$EnhancerBySpringCGLIB$$eefa08b -> ContractSubjectController -> getContractSubjectLogs()
往上查找調用者，並做展示，我們會發現第一條的執行時間略小於第二條的執行時間，基本符合上述我們的推斷。

6）查看JVM已加載的類信息

sc -d cn.asae.e.contract.web.ContractSubjectController

-d 輸出當前類的詳細信息，包括這個類所加載的原始文件來源、類的聲明、加載的ClassLoader等詳細信息。
如果一個類被多個ClassLoader所加載，則會出現多次

____________________________________________________________________________________________________________________________________________
| class-info cn.asae.e.contract.web.ContractSubjectController | | code-source /opt/tomcat-servers/apache-tomcat-e/webapps/asae-e/WEB-INF/classes/ | | name cn.asae.e.contract.web.ContractSubjectController | | isInterface false | | isAnnotation false | | isEnum false | | isAnonymousClass false | | isArray false | | isLocalClass false | | isMemberClass false | | isPrimitive false | | isSynthetic false | | simple-name ContractSubjectController | | modifier public | | annotation org.springframework.web.bind.annotation.RestController,org.springframework.web.bind.annotation.RequestMapping | | interfaces | | super-class +-java.lang.Object | | class-loader +-WebappClassLoader | | context: asae-e | | delegate: false | | ----------> Parent Classloader: | | java.net.URLClassLoader@3af49f1c | | | | +-java.net.URLClassLoader@3af49f1c | | +-sun.misc.Launcher$AppClassLoader@5c647e05 | | +-sun.misc.Launcher$ExtClassLoader@6537cf78 | | classLoaderHash 67fff846 | | | | class-info cn.asae.e.contract.web.ContractSubjectController$$EnhancerBySpringCGLIB$$8d1d153a | | code-source /opt/tomcat-servers/apache-tomcat-e/webapps/asae-e/WEB-INF/classes/ | | name cn.asae.e.contract.web.ContractSubjectController$$EnhancerBySpringCGLIB$$8d1d153a | | isInterface false | | isAnnotation false | | isEnum false | | isAnonymousClass false | | isArray false | | isLocalClass false | | isMemberClass false | | isPrimitive false | | isSynthetic false | | simple-name ContractSubjectController$$EnhancerBySpringCGLIB$$8d1d153a | | modifier public | | annotation | | interfaces org.springframework.aop.SpringProxy,org.springframework.aop.framework.Advised,org.springframework.cglib.proxy.Factory | | super-class +-cn.asae.e.contract.web.ContractSubjectController | | +-java.lang.Object | | class-loader +-WebappClassLoader | | context: asae-e | | delegate: false | | ----------> Parent Classloader: | | java.net.URLClassLoader@3af49f1c | | | | +-java.net.URLClassLoader@3af49f1c | | +-sun.misc.Launcher$AppClassLoader@5c647e05 | | +-sun.misc.Launcher$ExtClassLoader@6537cf78 | | classLoaderHash 67fff846 | |__________________________________________________________________________________________________________________________________________| 

7）退出arthas
quit —— 退出當前 Arthas 客戶端，其他 Arthas 客戶端不受影響
shutdown —— 關閉 Arthas 服務端，所有 Arthas 客戶端全部退出 & 重置所有增強過的類，就不用單獨調用reset

五、來自天邊的"海市蜃樓"

Arthas還提供 Web Console。

java -jar arthas-boot.jar --target-ip 192.168.168.67
在局域網內，其它機器可訪問 http://192.168.168.67:8563
默認情況下，arthas只listen 127.0.0.1，所以如果想從遠程連接，則可以使用 --target-ip參數指定listen的IP，更多參考-h的幫助說明。 注意會有安全風險，考慮tunnel server的方案。