Authas — 開源的java診斷工具
下載安裝
authas是一個(gè)jar包，可以直接下載后運(yùn)行
wget https://alibaba.github.io/arthas/arthas-boot.jar
java -jar arthas-boot.jar
就可以啟動(dòng)起來。啟動(dòng)后，authas會(huì)自動(dòng)檢測(cè)存在的java進(jìn)程，這時(shí)候需要選擇你想要診斷的進(jìn)程，回車即可。如下圖所示：
image-20190515215103606.png
如果不知道某個(gè)java進(jìn)程的詳情，可以使用
jps -mlVv
或
ps -ef| grep java
來查看.
image-20190515215504917.png
常用命令
基礎(chǔ)命令
help——查看命令幫助信息
cat——打印文件內(nèi)容，和linux里的cat命令類似
pwd——返回當(dāng)前的工作目錄，和linux命令類似
cls——清空當(dāng)前屏幕區(qū)域
session——查看當(dāng)前會(huì)話的信息
reset——重置增強(qiáng)類，將被 Arthas 增強(qiáng)過的類全部還原，Arthas 服務(wù)端關(guān)閉時(shí)會(huì)重置所有增強(qiáng)過的類
version——輸出當(dāng)前目標(biāo) Java 進(jìn)程所加載的 Arthas 版本號(hào)
history——打印命令歷史
quit——退出當(dāng)前 Arthas 客戶端，其他 Arthas 客戶端不受影響
shutdown——關(guān)閉 Arthas 服務(wù)端，所有 Arthas 客戶端全部退出
keymap——Arthas快捷鍵列表及自定義快捷鍵
JVM相關(guān)
Dashboard
dashboard
USAGE:
dashboard [-b] [-i <value>] [-n <value>]
SUMMARY:
Overview of target jvm's thread, memory, gc, vm, tomcat info.
EXAMPLES:
dashboard
dashboard -n 10
dashboard -i 2000
WIKI:
https://alibaba.github.io/arthas/dashboard
OPTIONS:
-b, --batch Execute this command in batch mode.
-i, --interval <value> The interval (in ms) between two executions, default is 5000 ms.
-n, --number-of-execution <value> The number of times this command will be executed.
image-20190515215857569.png
可以看到，這里會(huì)顯示出線程(按照cpu占用百分比倒排)、內(nèi)存(堆空間實(shí)時(shí)情況)、GC情況等數(shù)據(jù)。
常用的參數(shù)：
-i 400ms 每次執(zhí)行間隔時(shí)間
-n 執(zhí)行多少次dashboard，不指定的話會(huì)一直刷新
thread
thread命令用來查看當(dāng)前jvm中的線程信息的，如下圖所示：
image-20190515220246248.png
可以看到，默認(rèn)執(zhí)行thread命令，會(huì)直接打印出當(dāng)前所有的線程。
$ thread
USAGE:
thread [-b] [-i <value>] [-n <value>] [id]
SUMMARY:
Display thread info, thread stack
EXAMPLES:
thread
thread 51
thread -n -1
thread -n 5
thread -b
thread -i 2000
WIKI:
https://alibaba.github.io/arthas/thread
OPTIONS:
-b, --include-blocking-th Find the thread who is holding a lock that blocks t
read he most number of threads.
-i, --sample-interval <va Specify the sampling interval (in ms) when calculat
lue> ing cpu usage.
-n, --top-n-threads <valu The number of thread(s) to show, ordered by cpu uti
e> lization, -1 to show all.
<id> Show thread stack
常用參數(shù)：
-b 查看目前block的線程
-i 5000ms 查看在接下來的多長時(shí)間內(nèi) 統(tǒng)計(jì)cpu利用率
-n 5 查看cpu占用率前5的線程的堆棧信息
<thread_id> 直接跟著線程id，可以看到thread的堆棧信息
如下：
$ thread -n 1
"as-command-execute-daemon" Id=396 cpuUsage=53% RUNNABLE
at sun.management.ThreadImpl.dumpThreads0(Native Method)
at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:448)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:133)
at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:79)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111)
at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108)
at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:370)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Number of locked synchronizers = 1
- java.util.concurrent.ThreadPoolExecutor$Worker@21b51d37
Affect(row-cnt:0) cost in 541 ms.
可以看到這里占用cpu最高的一個(gè)線程的棧信息。
jvm
查看當(dāng)前jvm信息
sysprop
查看和修改JVM的系統(tǒng)屬性
sysenv
查看JVM的環(huán)境變量
getstatic
查看類的靜態(tài)屬性
class/classloader相關(guān)
mc
Memory Compiler/內(nèi)存編譯器，編譯.java文件生成.class。
mc /tmp/Test.java
redefine
加載外部的.class文件，redefine jvm已加載的類。
redefine /tmp/Test.class
redefine -c 327a647b /tmp/Test.class /tmp/Test\$Inner.class
sc
Search class
查看jvm中已加載的類，不過直接執(zhí)行sc并沒有太多信息，如下：
$ sc com.google.common.hash.HashFunction
com.google.common.hash.AbstractHashFunction
com.google.common.hash.HashFunction
com.google.common.hash.MessageDigestHashFunction
Affect(row-cnt:3) cost in 213 ms.
需要加入-d參數(shù)，如下
$ sc -d com.google.common.hash.HashFunction
class-info com.google.common.hash.AbstractHashFunction
code-source
name com.google.common.hash.AbstractHashFunction
isInterface false
isAnnotation false
isEnum false
isAnonymousClass false
isArray false
isLocalClass false
isMemberClass false
isPrimitive false
isSynthetic false
simple-name AbstractHashFunction
modifier abstract
annotation com.google.errorprone.annotations.Immutable
interfaces com.google.common.hash.HashFunction
super-class +-java.lang.Object
class-loader +-com.intellij.util.lang.UrlClassLoader@277050dc
classLoaderHash 277050dc
class-info com.google.common.hash.HashFunction
code-source
name com.google.common.hash.HashFunction
isInterface true
isAnnotation false
isEnum false
isAnonymousClass false
isArray false
isLocalClass false
isMemberClass false
isPrimitive false
isSynthetic false
simple-name HashFunction
modifier abstract,interface,public
annotation com.google.errorprone.annotations.Immutable
interfaces
super-class
class-loader +-com.intellij.util.lang.UrlClassLoader@277050dc
classLoaderHash 277050dc
class-info com.google.common.hash.MessageDigestHashFunction
code-source
name com.google.common.hash.MessageDigestHashFunction
isInterface false
isAnnotation false
isEnum false
isAnonymousClass false
isArray false
isLocalClass false
isMemberClass false
isPrimitive false
isSynthetic false
simple-name MessageDigestHashFunction
modifier final
annotation com.google.errorprone.annotations.Immutable
interfaces java.io.Serializable
super-class +-com.google.common.hash.AbstractHashFunction
+-java.lang.Object
class-loader +-com.intellij.util.lang.UrlClassLoader@277050dc
classLoaderHash 277050dc
Affect(row-cnt:3) cost in 102 ms.
可以看到這里有更詳細(xì)的信息。
具體的參數(shù)如下：
$ help sc
USAGE:
sc [-d] [-x <value>] [-f] [-h] [-E] class-pattern
SUMMARY:
Search all the classes loaded by JVM
EXAMPLES:
sc -d org.apache.commons.lang.StringUtils
sc -d org/apache/commons/lang/StringUtils
sc -d *StringUtils
sc -d -f org.apache.commons.lang.StringUtils
sc -E org\\.apache\\.commons\\.lang\\.StringUtils
WIKI:
https://alibaba.github.io/arthas/sc
OPTIONS:
-d, --details Display the details of class
-x, --expand <value> Expand level of object (0 by default)
-f, --field Display all the member variables
-h, --help this help
-E, --regex Enable regular expression to match (wildcard matching by default)
<class-pattern> Class name pattern, use either '.' or '/' as separator
sm
search method
$ sm xx.xxx.xx.xx.xxx.xx.CouponService
xx.xxx.xx.xx.xxx.xx.CouponServiceImpl <init>()V
xx.xxx.xx.xx.xxx.xx.CouponServiceImpl matchCouponOnShopIds(Ljava/lang/Long;Ljava/util/List;)Ljava/util/Map;
xx.xxx.xx.xx.xxx.xx.CouponServiceImpl$$EnhancerByGuice$$9b64c3b8 <init>()V
xx.xxx.xx.xx.xxx.xx.CouponServiceImpl$$EnhancerByGuice$$9b64c3b8 CGLIB$matchCouponOnShopIds$0(Ljava/lang/Long;Ljava/util/List;)Ljava/util/Map;
xx.xxx.xx.xx.xxx.xx.CouponServiceImpl$$EnhancerByGuice$$9b64c3b8 CGLIB$SET_THREAD_CALLBACKS([Lcom/google/inject/internal/cglib/pr$ oxy/$Callback;)V
xx.xxx.xx.xx.xxx.xx.CouponServiceImpl$$EnhancerByGuice$$9b64c3b8 CGLIB$SET_STATIC_CALLBACKS([Lcom/google/inject/internal/cglib/proxy/$Callback;)V
xx.xxx.xx.xx.xxx.xx.CouponServiceImpl$$EnhancerByGuice$$9b64c3b8 CGLIB$STATICHOOK35()V
xx.xxx.xx.xx.xxx.xx.CouponServiceImpl$$EnhancerByGuice$$9b64c3b8 CGLIB$BIND_CALLBACKS(Ljava/lang/Object;)V
xx.xxx.xx.xx.xxx.xx.CouponServiceImpl$$EnhancerByGuice$$9b64c3b8 CGLIB$findMethodProxy(Lcom/google/inject/internal/cglib/core/$Signature;)Lcom/google/inject/internal/cglib/proxy/$MethodProxy;
xx.xxx.xx.xx.xxx.xx.CouponServiceImpl$$EnhancerByGuice$$9b64c3b8 matchCouponOnShopIds(Ljava/lang/Long;Ljava/util/List;)Ljava/util/Map;
xx.xxx.xx.xx.xxx.xx.CouponService matchCouponOnShopIds(Ljava/lang/Long;Ljava/util/List;)Ljava/util/Map;
com.sun.proxy.$Proxy197 <init>(Ljava/lang/reflect/InvocationHandler;)V
com.sun.proxy.$Proxy197 matchCouponOnShopIds(Ljava/lang/Long;Ljava/util/List;)Ljava/util/Map;
com.sun.proxy.$Proxy197 equals(Ljava/lang/Object;)Z
com.sun.proxy.$Proxy197 toString()Ljava/lang/String;
com.sun.proxy.$Proxy197 hashCode()I
Affect(row-cnt:16) cost in 53 ms.
可以看到，通過sm命令可以查到對(duì)應(yīng)類的所有方法
通過加入-d參數(shù)可以獲取method的信息信息
$ sm xx.xxx.xx.xx.xxx.xx.CouponService -d
declaring-class xx.xxx.xx.xx.xxx.xx.CouponServiceImpl
constructor-name <init>
modifier public
annotation
parameters
exceptions
declaring-class xx.xxx.xx.xx.xxx.xx.CouponServiceImpl
method-name matchCouponOnShopIds
modifier public
annotation
parameters java.lang.Long
java.util.List
return java.util.Map
exceptions xx.xxx.xx.xx.xxx.xx.ServiceException
...
sh
jad
反編譯代碼，如下
$ jad com.google.common.hash.HashFunction
ClassLoader:
+-com.intellij.util.lang.UrlClassLoader@277050dc
Location:
/*
* Decompiled with CFR 0_132.
*
* Could not load the following classes:
* com.google.common.hash.Funnel
* com.google.common.hash.HashCode
* com.google.common.hash.Hasher
* com.google.errorprone.annotations.Immutable
*/
package com.google.common.hash;
import com.google.common.hash.Funnel;
import com.google.common.hash.HashCode;
import com.google.common.hash.Hasher;
import com.google.errorprone.annotations.Immutable;
import java.nio.ByteBuffer;
import java.nio.charset.Charset;
@Immutable
public interface HashFunction {
public int bits();
public HashCode hashLong(long var1);
public HashCode hashInt(int var1);
public <T> HashCode hashObject(T var1, Funnel<? super T> var2);
public HashCode hashUnencodedChars(CharSequence var1);
public HashCode hashString(CharSequence var1, Charset var2);
public HashCode hashBytes(ByteBuffer var1);
public HashCode hashBytes(byte[] var1, int var2, int var3);
public HashCode hashBytes(byte[] var1);
public Hasher newHasher();
public Hasher newHasher(int var1);
}
Affect(row-cnt:1) cost in 1730 ms.
classloader
查看classloader的繼承樹，urls，類加載信息
image-20190520141344323.png
查看其參數(shù)如下
$ help classloader
USAGE:
classloader [-a] [-c <value>] [-h] [-i] [-l] [--load <value>] [-r <value>] [-t]
SUMMARY:
Show classloader info
EXAMPLES:
classloader
classloader -t
classloader -l
classloader -c 327a647b
classloader -c 327a647b -r META-INF/MANIFEST.MF
classloader -a
classloader -a -c 327a647b
classloader -c 659e0bfd --load demo.MathGame
WIKI:
https://alibaba.github.io/arthas/classloader
OPTIONS:
-a, --all Display all classes loaded by ClassLoader
-c, --classloader <value> The hash code of the special ClassLoader
-h, --help this help
-i, --include-reflection-classloader Include sun.reflect.DelegatingClassLoader
-l, --list-classloader Display statistics info by classloader instance
--load <value> Use ClassLoader to load class, won't work without -c specified
-r, --resource <value> Use ClassLoader to find resources, won't work without -c specified
-t, --tree Display ClassLoader tree
-t : 把classloader的樹打印出來，也會(huì)打印出來粗略的hashcode
-l : 根據(jù)classloader實(shí)例的個(gè)數(shù)來打印classloader，會(huì)打印出來hashcode
-c : 用classloader對(duì)應(yīng)的hashcode 來查看對(duì)應(yīng)的jar urls
查看classloader tree信息
$ classloader -t
+-BootstrapClassLoader
+-sun.misc.Launcher$ExtClassLoader@6379eb
+-com.taobao.arthas.agent.ArthasClassloader@5ab570f5
+-sun.misc.Launcher$AppClassLoader@18b4aac2
+-com.alibaba.fastjson.util.ASMClassLoader@34c3f8d2
+-com.alibaba.fastjson.util.ASMClassLoader@463b35ac
+-com.alibaba.jvm.sandbox.agent.SandboxClassLoader@567d299b
+-ModuleClassLoader[crc32=3750510264;file=/data/.ewatch/ewatch-install/sandbox/lib/../module/sandbox-mgr-module.jar;]
+-ModuleClassLoader[crc32=2030492332;file=/data/.ewatch/ewatch-install/sandbox/ewatch/ewatch-agent-jar-with-dependencies.jar;]
+-com.alibaba.jvm.sandbox.core.classloader.ProviderClassLoader@42f93a98
Affect(row-cnt:10) cost in 20 ms.
查看URLClassLoader實(shí)際的urls
$ classloader -c 5ab570f5
file:/root/.arthas/lib/3.1.1/arthas/arthas-core.jar
Affect(row-cnt:1790) cost in 19 ms.
使用ClassLoader去查找resource
$ classloader -c 3d4eac69 -r META-INF/MANIFEST.MF
jar:file:/System/Library/Java/Extensions/MRJToolkit.jar!/META-INF/MANIFEST.MF
jar:file:/private/tmp/arthas-demo.jar!/META-INF/MANIFEST.MF
jar:file:/Users/hengyunabc/.arthas/lib/3.0.5/arthas/arthas-agent.jar!/META-INF/MANIFEST.MF
也可以嘗試查找類的class文件：
$ classloader -c 1b6d3586 -r java/lang/String.class
jar:file:/Library/Java/JavaVirtualMachines/jdk1.8.0_60.jdk/Contents/Home/jre/lib/rt.jar!/java/lang/String.class
使用ClassLoader去加載類
$ classloader -c 3d4eac69 --load demo.MathGame
load class success.
class-info demo.MathGame
code-source /private/tmp/arthas-demo.jar
name demo.MathGame
isInterface false
isAnnotation false
isEnum false
isAnonymousClass false
isArray false
isLocalClass false
isMemberClass false
isPrimitive false
isSynthetic false
simple-name MathGame
modifier public
annotation
interfaces
super-class +-java.lang.Object
class-loader +-sun.misc.Launcher$AppClassLoader@3d4eac69
+-sun.misc.Launcher$ExtClassLoader@66350f69
classLoaderHash 3d4eac69
monitor/watch/trace相關(guān)
monitor
對(duì)匹配 class-pattern／method-pattern的類、方法的調(diào)用進(jìn)行監(jiān)控。
monitor 命令是一個(gè)非實(shí)時(shí)返回命令.
實(shí)時(shí)返回命令是輸入之后立即返回，而非實(shí)時(shí)返回的命令，則是不斷的等待目標(biāo) Java 進(jìn)程返回信息，直到用戶輸入 Ctrl+C 為止。
服務(wù)端是以任務(wù)的形式在后臺(tái)跑任務(wù)，植入的代碼隨著任務(wù)的中止而不會(huì)被執(zhí)行，所以任務(wù)關(guān)閉后，不會(huì)對(duì)原有性能產(chǎn)生太大影響，而且原則上，任何Arthas命令不會(huì)引起原有業(yè)務(wù)邏輯的改變。
監(jiān)控的維度說明
| 監(jiān)控項(xiàng) | 說明 |
|---|---|
| timestamp | 時(shí)間戳 |
| class | Java類 |
| method | 方法（構(gòu)造方法、普通方法） |
| total | 調(diào)用次數(shù) |
| success | 成功次數(shù) |
| fail | 失敗次數(shù) |
| rt | 平均RT |
| fail-rate | 失敗率 |
$ monitor -c 5 demo.MathGame primeFactors
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 94 ms.
timestamp class method total success fail avg-rt(ms) fail-rate
-----------------------------------------------------------------------------------------------
2018-12-03 19:06:38 demo.MathGame primeFactors 5 1 4 1.15 80.00%
timestamp class method total success fail avg-rt(ms) fail-rate
-----------------------------------------------------------------------------------------------
2018-12-03 19:06:43 demo.MathGame primeFactors 5 3 2 42.29 40.00%
timestamp class method total success fail avg-rt(ms) fail-rate
-----------------------------------------------------------------------------------------------
2018-12-03 19:06:48 demo.MathGame primeFactors 5 3 2 67.92 40.00%
timestamp class method total success fail avg-rt(ms) fail-rate
-----------------------------------------------------------------------------------------------
2018-12-03 19:06:53 demo.MathGame primeFactors 5 2 3 0.25 60.00%
timestamp class method total success fail avg-rt(ms) fail-rate
-----------------------------------------------------------------------------------------------
2018-12-03 19:06:58 demo.MathGame primeFactors 1 1 0 0.45 0.00%
timestamp class method total success fail avg-rt(ms) fail-rate
-----------------------------------------------------------------------------------------------
2018-12-03 19:07:03 demo.MathGame primeFactors 2 2 0 3182.72 0.00%
watch
查看函數(shù)的參數(shù)、返回值、異常信息，如果有請(qǐng)求觸發(fā)，就回打印對(duì)應(yīng)的數(shù)據(jù)。用法如下
$ help watch
USAGE:
watch [-b] [-e] [-x <value>] [-f] [-h] [-n <value>] [-E] [-M <value>] [-s] class-pattern method-pattern express [condition-express]
SUMMARY:
Display the input/output parameter, return object, and thrown exception of specified method invocation
The express may be one of the following expression (evaluated dynamically):
target : the object
clazz : the object's class
method : the constructor or method
params : the parameters array of method
params[0..n] : the element of parameters array
returnObj : the returned object of method
throwExp : the throw exception of method
isReturn : the method ended by return
isThrow : the method ended by throwing exception
#cost : the execution time in ms of method invocation
Examples:
watch -b org.apache.commons.lang.StringUtils isBlank params
watch -f org.apache.commons.lang.StringUtils isBlank returnObj
watch org.apache.commons.lang.StringUtils isBlank '{params, target, returnObj}' -x 2
watch -bf *StringUtils isBlank params
watch *StringUtils isBlank params[0]
watch *StringUtils isBlank params[0] params[0].length==1
watch *StringUtils isBlank params '#cost>100'
watch -E -b org\.apache\.commons\.lang\.StringUtils isBlank params[0]
OPTIONS:
-b, --before Watch before invocation
-e, --exception Watch after throw exception
-x, --expand <value> Expand level of object (1 by default)
-f, --finish Watch after invocation, enable by default
-h, --help this help
-n, --limits <value> Threshold of execution times
-E, --regex Enable regular expression to match (wildcard matching by default)
-M, --sizeLimit <value> Upper size limit in bytes for the result (10 * 1024 * 1024 by default)
-s, --success Watch after successful invocation
<class-pattern> The full qualified class name you want to watch
<method-pattern> The method name you want to watch
<express> the content you want to watch, written by ognl.
Examples:
params
params[0]
'params[0]+params[1]'
'{params[0], target, returnObj}'
returnObj
throwExp
target
clazz
method
<condition-express> Conditional expression in ognl style, for example:
TRUE : 1==1
TRUE : true
FALSE : false
TRUE : 'params.length>=0'
FALSE : 1==2
具體執(zhí)行如下（查看請(qǐng)求參數(shù)）：
$ watch xxx.xxx.xxx.xxx.BerlinService view params
Press Q or Ctrl+C to abort.
Affect(class-cnt:3 , method-cnt:3) cost in 393 ms.
ts=2019-05-17 14:43:36; [cost=37.391098ms] result=@Object[][
@BerlinRequest[BerlinRequest(activityId=RC_12, userId=309314913, latitude=31.224360913038254, longitude=121.55064392834902, userAgent=Rajax/1 MI_MAX/helium Android/7.0 Display/NRD90M me/8.16.1 Channel/tengxun ID/e75ef7ec-4069-38ee-83c4-51fb7067f3e1; KERNEL_VERSION:3.10.84-perf-gd39c060 API_Level:24 Hardware: Mozilla/5.0 (Linux; Android 7.0; MI MAX Build/NRD90M; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/64.0.3282.137 Mobile Safari/537.36 AliApp(ELMC/8.16.1) TTID/offical WindVane/8.5.0,UT4Aplus/0.2.16, deviceId=null, limit=8, offset=0)],
]
ts=2019-05-17 14:43:36; [cost=46.358372ms] result=@Object[][
@BerlinRequest[BerlinRequest(activityId=RC_12, userId=309314913, latitude=31.224360913038254, longitude=121.55064392834902, userAgent=Rajax/1 MI_MAX/helium Android/7.0 Display/NRD90M me/8.16.1 Channel/tengxun ID/e75ef7ec-4069-38ee-83c4-51fb7067f3e1; KERNEL_VERSION:3.10.84-perf-gd39c060 API_Level:24 Hardware: Mozilla/5.0 (Linux; Android 7.0; MI MAX Build/NRD90M; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/64.0.3282.137 Mobile Safari/537.36 AliApp(ELMC/8.16.1) TTID/offical WindVane/8.5.0,UT4Aplus/0.2.16, deviceId=null, limit=8, offset=0)],
]
查看請(qǐng)求參數(shù)及相應(yīng)
$ watch xx.xxx.xx.xx.xxx.xx.BerlinService view '{params[0], returnObj}'
Press Q or Ctrl+C to abort.
Affect(class-cnt:3 , method-cnt:3) cost in 416 ms.
ts=2019-05-17 14:52:38; [cost=33.968815ms] result=@ArrayList[
@BerlinRequest[BerlinRequest(activityId=RC_12, userId=117043063, latitude=22.682775497436523, longitude=114.04010772705078, userAgent=Rajax/1 Apple/iPhone9,2 iOS/12.2 me/8.16.3 ID/6E92FDB8-FF9F-4F11-BC1A-490E67B39047; IsJailbroken/0 ASI/30F47DE7-0DE5-488E-A479-C94EB9284301 Mozilla/5.0 (iPhone; CPUiPhone OS 12_2 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 AliApp(ELMC/8.16.3) UT4Aplus/0.0.4 WindVane/8.5.0 1242x2208 WK, deviceId=null, limit=8, offset=0)],
@BerlinCommonResponse[xx.xxx.xx.xx.xxx.xx.BerlinCommonResponse@4c5df030],
]
可以看到，包含了請(qǐng)求及相應(yīng)數(shù)據(jù)、整體cost-time,不過需要注意的是，這里并沒有打印出所有詳細(xì)數(shù)據(jù)。如果需要打印所有數(shù)據(jù)，加入-x參數(shù)表示遍歷深度，可以調(diào)整來打印具體的參數(shù)和結(jié)果內(nèi)容。默認(rèn)-x 的深度為1，可以指定 2 3 等,如下：
$ watch xx.xxx.xx.xx.xxx.xx.BerlinService view '{params, returnObj}' -x 2
ts=2019-05-20 11:12:57; [cost=41.677987ms] result=@ArrayList[
@Object[][
@BerlinRequest[BerlinRequest(activityId=RC_12, userId=840800602, latitude=36.042474, longitude=103.849928, userAgent=Mozilla/5.0 (Linux; U; Android 8.1.0; zh-CN; DUB-AL00 Build/HUAWEIDUB-AL00) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/57.0.2987.108 UCBrowser/11.8.8.968 UWS/2.13.2.74 Mobile Safari/537.36 UCBS/2.13.2.74_190419112332 NebulaSDK/1.8.100112 Nebula AlipayDefined(nt:4G,ws:360|0|2.0) AliApp(AP/10.1.62.5549) AlipayClient/10.1.62.5549 Language/zh-Hans useStatusBar/true isConcaveScreen/true, deviceId=null, limit=8, offset=0)],
],
@BerlinCommonResponse[
code=@String[200],
message=@String[成功],
data=@ArrayList[isEmpty=false;size=7],
],
]
如過需要按照耗時(shí)進(jìn)行過濾，需要加入： '#cost>200' 代表耗時(shí)超過200ms的才會(huì)打印出來。
watch/stack/trace這個(gè)三個(gè)命令都支持#cost
trace
方法內(nèi)部調(diào)用路徑，并輸出方法路徑上的每個(gè)節(jié)點(diǎn)上耗時(shí)
查看help
$ help trace
USAGE:
trace [-h] [-j] [-n <value>] [-p <value>] [-E] class-pattern method-pattern [condition-express]
SUMMARY:
Trace the execution time of specified method invocation.
FALSE : false
TRUE : 'params.length>=0'
FALSE : 1==2
The express may be one of the following expression (evaluated dynamically):
target : the object
clazz : the object's class
method : the constructor or method
params : the parameters array of method
params[0..n] : the element of parameters array
returnObj : the returned object of method
throwExp : the throw exception of method
isReturn : the method ended by return
isThrow : the method ended by throwing exception
#cost : the execution time in ms of method invocation
EXAMPLES:
trace org.apache.commons.lang.StringUtils isBlank
trace *StringUtils isBlank
trace *StringUtils isBlank params[0].length==1
trace *StringUtils isBlank '#cost>100'
trace -E org\\.apache\\.commons\\.lang\\.StringUtils isBlank
trace -E com.test.ClassA|org.test.ClassB method1|method2|method3
WIKI:
https://alibaba.github.io/arthas/trace
OPTIONS:
-h, --help this help
-j, --jdkMethodSkip skip jdk method trace
-n, --limits <value> Threshold of execution times
-p, --path <value> path tracing pattern
-E, --regex Enable regular expression to match (wildcard matching by default)
<class-pattern> Class name pattern, use either '.' or '/' as separator
<method-pattern> Method name pattern
<condition-express> Conditional expression in ognl style, for example:
TRUE : 1==1
TRUE : true
平時(shí)主要使用-j (忽略jdk method trace)、'#cost>10'(過濾耗時(shí)時(shí)間) -n (執(zhí)行次數(shù))
$ trace xx.xxx.xx.xx.xxx.xx.QueryAction queryByReq -j '#cost>5' -n 5
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 781 ms.
`---ts=2019-05-20 15:27:10;thread_name=thread-272;id=1fb;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2
`---[12.250248ms] xx.xxx.xx.xx.xxx.xx.QueryAction:queryByReq()
...
...
stack
輸出當(dāng)前方法被調(diào)用的調(diào)用路徑
很多時(shí)候我們都知道一個(gè)方法被執(zhí)行，但這個(gè)方法被執(zhí)行的路徑非常多，或者你根本就不知道這個(gè)方法是從那里被執(zhí)行了，此時(shí)你需要的是 stack 命令。
主要使用-n 命令，用于控制執(zhí)行次數(shù)
stack xx.xxx.xx.xx.xxx.xx.QueryAction queryByReq -n 1
tt
先看個(gè)例子
$ tt -t xx.xxx.xx.xx.xxx.xx.QueryAction queryByReq -n 5
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 995 ms.
IND TIMESTAMP COST( IS- IS OBJECT CLASS METHOD
EX ms) RET -E
XP
--------------------------------------------------------------------------------
100 2019-05-20 17.52 tru fa 0x7df629 QueryValidSkuAct queryValidSkuActi
5 15:41:29 694 e ls 87 ivityAction vityByReq
e
100 2019-05-20 10.26 tru fa 0x4bb52c QueryValidSkuAct queryValidSkuActi
6 15:41:29 7017 e ls 96 ivityAction vityByReq
e
100 2019-05-20 19.80 tru fa 0x20d351 QueryValidSkuAct queryValidSkuActi
7 15:41:29 7279 e ls d3 ivityAction vityByReq
e
100 2019-05-20 19.84 tru fa 0x286366 QueryValidSkuAct queryValidSkuActi
8 15:41:29 4526 e ls b4 ivityAction vityByReq
e
100 2019-05-20 19.91 tru fa 0x31297b QueryValidSkuAct queryValidSkuActi
9 15:41:29 0582 e ls 01 ivityAction vityByReq
e
Command execution times exceed limit: 5, so command will exit. You can set it with -n option.
101 2019-05-20 19.94 tru fa 0x7a3c2f QueryValidSkuAct queryValidSkuActi
0 15:41:29 8529 e ls c4 ivityAction vityByReq
- 表格字段說明
| 表格字段 | 字段解釋 |
|---|---|
| INDEX | 時(shí)間片段記錄編號(hào)，每一個(gè)編號(hào)代表著一次調(diào)用，后續(xù)tt還有很多命令都是基于此編號(hào)指定記錄操作，非常重要。 |
| TIMESTAMP | 方法執(zhí)行的本機(jī)時(shí)間，記錄了這個(gè)時(shí)間片段所發(fā)生的本機(jī)時(shí)間 |
| COST(ms) | 方法執(zhí)行的耗時(shí) |
| IS-RET | 方法是否以正常返回的形式結(jié)束 |
| IS-EXP | 方法是否以拋異常的形式結(jié)束 |
| OBJECT | 執(zhí)行對(duì)象的hashCode()，注意，曾經(jīng)有人誤認(rèn)為是對(duì)象在JVM中的內(nèi)存地址，但很遺憾他不是。但他能幫助你簡(jiǎn)單的標(biāo)記當(dāng)前執(zhí)行方法的類實(shí)體 |
| CLASS | 執(zhí)行的類名 |
| METHOD | 執(zhí)行的方法名 |
-t
tt 命令有很多個(gè)主參數(shù)，-t 就是其中之一。這個(gè)參數(shù)的表明希望記錄下類 *Test 的 print 方法的每次執(zhí)行情況。
-n 3
當(dāng)你執(zhí)行一個(gè)調(diào)用量不高的方法時(shí)可能你還能有足夠的時(shí)間用 CTRL+C 中斷 tt 命令記錄的過程，但如果遇到調(diào)用量非常大的方法，瞬間就能將你的 JVM 內(nèi)存撐爆。
此時(shí)你可以通過 -n 參數(shù)指定你需要記錄的次數(shù)，當(dāng)達(dá)到記錄次數(shù)時(shí) Arthas 會(huì)主動(dòng)中斷tt命令的記錄過程，避免人工操作無法停止的情況。
檢索調(diào)用記錄
當(dāng)你用 tt 記錄了一大片的時(shí)間片段之后，你希望能從中篩選出自己需要的時(shí)間片段，這個(gè)時(shí)候你就需要對(duì)現(xiàn)有記錄進(jìn)行檢索。
假設(shè)我們有這些記錄
$ tt -l
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
-------------------------------------------------------------------------------------------------------------------------------------
1000 2018-12-04 11:15:38 1.096236 false true 0x4b67cf4d MathGame primeFactors
1001 2018-12-04 11:15:39 0.191848 false true 0x4b67cf4d MathGame primeFactors
1002 2018-12-04 11:15:40 0.069523 false true 0x4b67cf4d MathGame primeFactors
1003 2018-12-04 11:15:41 0.186073 false true 0x4b67cf4d MathGame primeFactors
1004 2018-12-04 11:15:42 17.76437 true false 0x4b67cf4d MathGame primeFactors
9
1005 2018-12-04 11:15:43 0.4776 false true 0x4b67cf4d MathGame primeFactors
Affect(row-cnt:6) cost in 4 ms.
我需要篩選出 primeFactors 方法的調(diào)用信息
$ tt -s 'method.name=="primeFactors"'
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
-------------------------------------------------------------------------------------------------------------------------------------
1000 2018-12-04 11:15:38 1.096236 false true 0x4b67cf4d MathGame primeFactors
1001 2018-12-04 11:15:39 0.191848 false true 0x4b67cf4d MathGame primeFactors
1002 2018-12-04 11:15:40 0.069523 false true 0x4b67cf4d MathGame primeFactors
1003 2018-12-04 11:15:41 0.186073 false true 0x4b67cf4d MathGame primeFactors
1004 2018-12-04 11:15:42 17.76437 true false 0x4b67cf4d MathGame primeFactors
9
1005 2018-12-04 11:15:43 0.4776 false true 0x4b67cf4d MathGame primeFactors
Affect(row-cnt:6) cost in 607 ms.
你需要一個(gè) -s 參數(shù)。同樣的，搜索表達(dá)式的核心對(duì)象依舊是 Advice 對(duì)象。
查看調(diào)用信息
對(duì)于具體一個(gè)時(shí)間片的信息而言，你可以通過 -i 參數(shù)后邊跟著對(duì)應(yīng)的 INDEX 編號(hào)查看到他的詳細(xì)信息。
$ tt -i 1003
INDEX 1003
GMT-CREATE 2018-12-04 11:15:41
COST(ms) 0.186073
OBJECT 0x4b67cf4d
CLASS demo.MathGame
METHOD primeFactors
IS-RETURN false
IS-EXCEPTION true
PARAMETERS[0] @Integer[-564322413]
THROW-EXCEPTION java.lang.IllegalArgumentException: number is: -564322413, need >= 2
at demo.MathGame.primeFactors(MathGame.java:46)
at demo.MathGame.run(MathGame.java:24)
at demo.MathGame.main(MathGame.java:16)
Affect(row-cnt:1) cost in 11 ms.
重做一次調(diào)用
當(dāng)你稍稍做了一些調(diào)整之后，你可能需要前端系統(tǒng)重新觸發(fā)一次你的調(diào)用，此時(shí)得求爺爺告奶奶的需要前端配合聯(lián)調(diào)的同學(xué)再次發(fā)起一次調(diào)用。而有些場(chǎng)景下，這個(gè)調(diào)用不是這么好觸發(fā)的。
tt 命令由于保存了當(dāng)時(shí)調(diào)用的所有現(xiàn)場(chǎng)信息，所以我們可以自己主動(dòng)對(duì)一個(gè) INDEX 編號(hào)的時(shí)間片自主發(fā)起一次調(diào)用，從而解放你的溝通成本。此時(shí)你需要 -p 參數(shù)。通過 --replay-times 指定 調(diào)用次數(shù)，通過 --replay-interval 指定多次調(diào)用間隔(單位ms, 默認(rèn)1000ms)
$ tt -i 1004 -p
RE-INDEX 1004
GMT-REPLAY 2018-12-04 11:26:00
OBJECT 0x4b67cf4d
CLASS demo.MathGame
METHOD primeFactors
PARAMETERS[0] @Integer[946738738]
IS-RETURN true
IS-EXCEPTION false
COST(ms) 0.186073
RETURN-OBJ @ArrayList[
@Integer[2],
@Integer[11],
@Integer[17],
@Integer[2531387],
]
Time fragment[1004] successfully replayed.
Affect(row-cnt:1) cost in 14 ms.
你會(huì)發(fā)現(xiàn)結(jié)果雖然一樣，但調(diào)用的路徑發(fā)生了變化，有原來的程序發(fā)起變成了 Arthas 自己的內(nèi)部線程發(fā)起的調(diào)用了。
-
需要強(qiáng)調(diào)的點(diǎn)
-
ThreadLocal 信息丟失
很多框架偷偷的將一些環(huán)境變量信息塞到了發(fā)起調(diào)用線程的 ThreadLocal 中，由于調(diào)用線程發(fā)生了變化，這些 ThreadLocal 線程信息無法通過 Arthas 保存，所以這些信息將會(huì)丟失。
一些常見的 CASE 比如：鷹眼的 TraceId 等。
-
引用的對(duì)象
需要強(qiáng)調(diào)的是，
tt命令是將當(dāng)前環(huán)境的對(duì)象引用保存起來，但僅僅也只能保存一個(gè)引用而已。如果方法內(nèi)部對(duì)入?yún)⑦M(jìn)行了變更，或者返回的對(duì)象經(jīng)過了后續(xù)的處理，那么在tt查看的時(shí)候?qū)o法看到當(dāng)時(shí)最準(zhǔn)確的值。這也是為什么watch命令存在的意義。
-
