arthas安装以及使用arthas指令排查问题详细实践

启动 math-game

curl -O https://arthas.aliyun.com/math-game.jar
java -jar math-game.jar

math-game是一个简单的程序，每隔一秒生成一个随机数，再执行质因数分解，并打印出分解结果。

启动 arthas

在命令行下面执行（使用和目标进程一致的用户启动，否则可能 attach 失败）：

curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar

执行该程序的用户需要和目标进程具有相同的权限。比如以admin用户来执行：sudo su admin && java -jar arthas-boot.jar 或 sudo -u admin -EH java -jar arthas-boot.jar。
如果 attach 不上目标进程，可以查看~/logs/arthas/ 目录下的日志。
如果下载速度比较慢，可以使用 aliyun 的镜像：java -jar arthas-boot.jar --repo-mirror aliyun --use-http
java -jar arthas-boot.jar -h 打印更多参数信息。
选择应用 java 进程：

$ $ java -jar arthas-boot.jar
* [1]: 35542
  [2]: 71560 math-game.jar

math-game进程是第 2 个，则输入 2，再输入回车/enter。Arthas 会 attach 到目标进程上，并输出日志：

[INFO] Try to attach process 71560
[INFO] Attach process 71560 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'


wiki: https://arthas.aliyun.com/doc
version: 3.0.5.20181127201536
pid: 71560
time: 2019-11-28 19:16:24

输入dashboard，按回车/enter，会展示当前进程的信息，按ctrl+c可以中断执行。

thread 1会打印线程ID 1的栈，通常是main函数的线程。

jad反编译代码

jad --source-only com.example.demo.arthas.user.UserController > /tmp/UserController.java

# windows 复制
jad --source-only cn.mesmile.auth.controller.UserController >> "D:\UserController.java"

sc查找加载UserController的ClassLoader

sc -d *UserController | grep classLoaderHash
classLoaderHash   75ad60d

可以发现是spring boot的 LaunchedURLClassLoader@75ad60d 加载的。

mc内存编绎代码

保存好/tmp/UserController.java之后，使用mc(Memory Compiler)命令来编译，并且通过-c参数指定ClassLoader：

# 可以通过-c参数指定classloader 编译生成.class文件之后，可以结合retransform命令实现热更新代码
mc -c 75ad60d /tmp/UserController.java -d /tmp


# 可以通过-c参数指定classloader
# 可以通过-d命令指定输出目录 编译生成.class文件之后，可以结合retransform命令实现热更新代码
mc -c 75ad60d "D:\UserController.java" -d "D:\tmp"

再使用redefine命令重新加载新编译好的UserController.class：

redefine /tmp/com/example/demo/arthas/user/UserController.class


# windows 方式
redefine "D:\tmp\cn\mesmile\auth\controller\UserController.class"

windows方式

[arthas@7408]$ mc -c 75ad60d "D:\UserController.java" -d "D:\tmp"
Memory compiler output:
D:\tmp\cn\mesmile\auth\controller\UserController.class
Affect(row-cnt:1) cost in 642 ms.
[arthas@7408]$ redefine "D:\tmp\cn\mesmile\auth\controller\UserController.class"
redefine success, size: 1, classes:
cn.mesmile.auth.controller.UserController

检验热更新结果

再次访问 curl http://localhost/user/0，会正常返回：

{ “id”: 0, “name”: “name0”}

[arthas@14712]$ jad demo.MathGame

ClassLoader:
+-sun.misc.Launcher$AppClassLoader@5c647e05
  +-sun.misc.Launcher$ExtClassLoader@28d93b30

Location:
/C:/Users/SuperZheng/Desktop/arthas/math-game.jar

       /*
        * Decompiled with CFR.
        */
       package demo;

       import java.util.ArrayList;
       import java.util.List;
       import java.util.Random;
       import java.util.concurrent.TimeUnit;

       public class MathGame {
           private static Random random = new Random();
           private int illegalArgumentCount = 0;

           public static void main(String[] args) throws InterruptedException {
               MathGame game = new MathGame();
               while (true) {
/*16*/             game.run();
/*17*/             TimeUnit.SECONDS.sleep(1L);
               }
           }

           public void run() throws InterruptedException {
               try {
/*23*/             int number = random.nextInt() / 10000;
/*24*/             List<Integer> primeFactors = this.primeFactors(number);
/*25*/             MathGame.print(number, primeFactors);
               }
               catch (Exception e) {
/*28*/             System.out.println(String.format("illegalArgumentCount:%3d, ", this.illegalArgumentCount) + e.getMessage());
               }
           }

           public static void print(int number, List<Integer> primeFactors) {
               StringBuffer sb = new StringBuffer(number + "=");
/*34*/         for (int factor : primeFactors) {
/*35*/             sb.append(factor).append('*');
               }
/*37*/         if (sb.charAt(sb.length() - 1) == '*') {
/*38*/             sb.deleteCharAt(sb.length() - 1);
               }
/*40*/         System.out.println(sb);
           }

           public List<Integer> primeFactors(int number) {
/*44*/         if (number < 2) {
/*45*/             ++this.illegalArgumentCount;
                   throw new IllegalArgumentException("number is: " + number + ", need >= 2");
               }
               ArrayList<Integer> result = new ArrayList<Integer>();
/*50*/         int i = 2;
/*51*/         while (i <= number) {
/*52*/             if (number % i == 0) {
/*53*/                 result.add(i);
/*54*/                 number /= i;
/*55*/                 i = 2;
                       continue;
                   }
/*57*/             ++i;
               }
/*61*/         return result;
           }
       }

Affect(row-cnt:1) cost in 370 ms.

通过watch命令来查看demo.MathGame#primeFactors函数的返回值：

[arthas@14712]$ watch demo.MathGame primeFactors returnObj
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 74 ms, listenerId: 1
method=demo.MathGame.primeFactors location=AtExit
ts=2021-08-14 20:41:07; [cost=0.687518ms] result=@ArrayList[
    @Integer[2],
    @Integer[2],
    @Integer[3],
    @Integer[3],
    @Integer[47],
    @Integer[113],
]
method=demo.MathGame.primeFactors location=AtExit
ts=2021-08-14 20:41:08; [cost=0.01753ms] result=@ArrayList[
    @Integer[13],
    @Integer[29],
    @Integer[439],
]
method=demo.MathGame.primeFactors location=AtExit
ts=2021-08-14 20:41:09; [cost=0.068584ms] result=@ArrayList[
    @Integer[17],
    @Integer[6079],
]

# 监控返回值
watch cn.mesmile.project.common.CommonController methodName returnObject

# 监控入参
watch cn.mesmile.project.common.CommonController methodName params

基础命令

* help——查看命令帮助信息
* cat——打印文件内容，和linux里的cat命令类似
* echo–打印参数，和linux里的echo命令类似
* grep——匹配查找，和linux里的grep命令类似
* base64——base64编码转换，和linux里的base64命令类似
* tee——复制标准输入到标准输出和指定的文件，和linux里的tee命令类似
* pwd——返回当前的工作目录，和linux命令类似
* cls——清空当前屏幕区域
* session——查看当前会话的信息
* reset——重置增强类，将被 Arthas 增强过的类全部还原，Arthas 服务端关闭时会重置所有增强过的类
* version——输出当前目标 Java 进程所加载的 Arthas 版本号
* history——打印命令历史
* quit——退出当前 Arthas 客户端，其他 Arthas 客户端不受影响
* stop——关闭 Arthas 服务端，所有 Arthas 客户端全部

* keymap——Arthas快捷键列表及自定义快捷键

JVM相关

* dashboard——当前系统的实时数据面板
* thread——查看当前 JVM 的线程堆栈信息
* jvm——查看当前 JVM 的信息
* sysprop——查看和修改JVM的系统属性
* sysenv——查看JVM的环境变量
* vmoption——查看和修改JVM里诊断相关的option
* perfcounter——查看当前 JVM 的Perf Counter信息
* logger——查看和修改logger
* getstatic——查看类的静态属性
* ognl——执行ognl表达式
* mbean——查看 Mbean 的信息
* heapdump——dump java heap, 类似jmap命令的heap dump功能
* vmtool——从jvm里查询对象，执行forceGc

[arthas@14712]$ echo 'abc' > ./test.txt
[arthas@14712]$ cat ./test.txt
abc

[arthas@14712]$ base64 ./test.txt
YWJjCg==

# 对文件进行 base64 编码并把结果保存到文件里
base64 --input /tmp/test.txt --output /tmp/result.txt

# 用 base64 解码文件
base64 -d /tmp/result.txt

# 用 base64 解码文件并保存结果到文件里
base64 -d /tmp/result.txt --output /tmp/bbb.txt

还原指定类

$ trace Test test
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 57 ms.
`---ts=2017-10-26 17:10:33;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.590102ms] Test:test()

`---ts=2017-10-26 17:10:34;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.068692ms] Test:test()

$ reset Test
Affect(class-cnt:1 , method-cnt:0) cost in 11 ms.

还原所有类

$ trace Test test
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 15 ms.
`---ts=2017-10-26 17:12:06;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.128518ms] Test:test()

$ reset
Affect(class-cnt:1 , method-cnt:0) cost in 9 ms.

dashboard

* ID: Java级别的线程ID，注意这个ID不能跟jstack中的nativeID一一对应。
* NAME: 线程名
* GROUP: 线程组名
* PRIORITY: 线程优先级, 1~10之间的数字，越大表示优先级越高
* STATE: 线程的状态
* CPU%: 线程的cpu使用率。比如采样间隔1000ms，某个线程的增量cpu时间为100ms，则cpu使用率=100/1000=10%
* DELTA_TIME: 上次采样之后线程运行增量CPU时间，数据格式为秒 * TIME: 线程运行总CPU时间，数据格式为分:秒 * INTERRUPTED: 线程当前的中断位状态
* DAEMON: 是否是daemon线程

Java 8之后支持获取JVM内部线程CPU时间，这些线程只有名称和CPU时间，没有ID及状态等信息（显示ID为-1）。 通过内部线程可以观测到JVM活动，如GC、JIT编译等占用CPU情况，方便了解JVM整体运行状况。
* 当JVM 堆(heap)/元数据(metaspace)空间不足或OOM时，可以看到GC线程的CPU占用率明显高于其他的线程。
* 当执行trace/watch/tt/redefine等命令后，可以看到JIT线程活动变得更频繁。因为JVM热更新class字节码时清除了此class相关的JIT编译结果，需要重新编译。
JVM内部线程包括下面几种：
* JIT编译线程: 如 C1 CompilerThread0, C2 CompilerThread0 * GC线程: 如GC Thread0, G1 Young RemSet Sampling * 其它内部线程: 如VM Periodic Task Thread, VM Thread, Service Thread

thread指令

支持一键展示当前最忙的前N个线程并打印堆栈

[arthas@14712]$ thread -n 3
"Reference Handler" Id=2 cpuUsage=0.0% deltaTime=0ms time=0ms WAITING on java.lang.ref.Reference$Lock@40d1b78e
    at java.lang.Object.wait(Native Method)
    -  waiting on java.lang.ref.Reference$Lock@40d1b78e
    at java.lang.Object.wait(Unknown Source)
    at java.lang.ref.Reference.tryHandlePending(Unknown Source)
    at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)


"Finalizer" Id=3 cpuUsage=0.0% deltaTime=0ms time=0ms WAITING on java.lang.ref.ReferenceQueue$Lock@4ef062e5
    at java.lang.Object.wait(Native Method)
    -  waiting on java.lang.ref.ReferenceQueue$Lock@4ef062e5
    at java.lang.ref.ReferenceQueue.remove(Unknown Source)
    at java.lang.ref.ReferenceQueue.remove(Unknown Source)
    at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)


"Signal Dispatcher" Id=4 cpuUsage=0.0% deltaTime=0ms time=0ms RUNNABLE

* 没有线程ID，包含[Internal]表示为JVM内部线程，参考dashboard命令的介绍。
* cpuUsage为采样间隔时间内线程的CPU使用率，与dashboard命令的数据一致。
* deltaTime为采样间隔时间内线程的增量CPU时间，小于1ms时被取整显示为0ms。
* time 线程运行总CPU时间。
注意：线程栈为第二采样结束时获取，不能表明采样间隔时间内该线程都是在处理相同的任务。建议间隔时间不要太长，可能间隔时间越大越不准确。 可以根据具体情况尝试指定不同的间隔时间，观察输出结果。

thread –all, 显示所有匹配的线程

thread id, 显示指定线程的运行堆栈

[arthas@14712]$ thread 1
"main" Id=1 TIMED_WAITING
    at java.lang.Thread.sleep(Native Method)
    at java.lang.Thread.sleep(Unknown Source)
    at java.util.concurrent.TimeUnit.sleep(Unknown Source)
    at demo.MathGame.main(MathGame.java:17)

thread -b, 找出当前阻塞其他线程的线程

有时候我们发现应用卡住了， 通常是由于某个线程拿住了某个锁， 并且其他线程都在等待这把锁造成的。 为了排查这类问题， arthas提供了thread -b， 一键找出那个罪魁祸首。

$ thread -b
"http-bio-8080-exec-4" Id=27 TIMED_WAITING
    at java.lang.Thread.sleep(Native Method)
    at test.arthas.TestThreadBlocking.doGet(TestThreadBlocking.java:22)
    -  locked java.lang.Object@725be470 <---- but blocks 4 other threads!
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:624)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at test.filter.TestDurexFilter.doFilter(TestDurexFilter.java:46)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
    at com.taobao.tomcat.valves.ContextLoadFilterValve$FilterChainAdapter.doFilter(ContextLoadFilterValve.java:191)
    at com.taobao.eagleeye.EagleEyeFilter.doFilter(EagleEyeFilter.java:81)
    at com.taobao.tomcat.valves.ContextLoadFilterValve.invoke(ContextLoadFilterValve.java:150)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:429)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1085)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:318)
    -  locked org.apache.tomcat.util.net.SocketWrapper@7127ee12
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
 
    Number of locked synchronizers = 1
    - java.util.concurrent.ThreadPoolExecutor$Worker@31a6493e

注意， 目前只支持找出synchronized关键字阻塞住的线程， 如果是java.util.concurrent.Lock， 目前还不支持。

thread -i, 指定采样时间间隔

* thread -i 1000 : 统计最近1000ms内的线程CPU时间。
* thread -n 3 -i 1000 : 列出1000ms内最忙的3个线程栈

[arthas@14712]$ thread -n 3 -i 1000
"Reference Handler" Id=2 cpuUsage=0.0% deltaTime=0ms time=0ms WAITING on java.lang.ref.Reference$Lock@40d1b78e
    at java.lang.Object.wait(Native Method)
    -  waiting on java.lang.ref.Reference$Lock@40d1b78e
    at java.lang.Object.wait(Unknown Source)
    at java.lang.ref.Reference.tryHandlePending(Unknown Source)
    at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)


"Finalizer" Id=3 cpuUsage=0.0% deltaTime=0ms time=0ms WAITING on java.lang.ref.ReferenceQueue$Lock@4ef062e5
    at java.lang.Object.wait(Native Method)
    -  waiting on java.lang.ref.ReferenceQueue$Lock@4ef062e5
    at java.lang.ref.ReferenceQueue.remove(Unknown Source)
    at java.lang.ref.ReferenceQueue.remove(Unknown Source)
    at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)


"Signal Dispatcher" Id=4 cpuUsage=0.0% deltaTime=0ms time=0ms RUNNABLE

thread –state ，查看指定状态的线程

[arthas@14712]$ thread --state WAITING
Threads Total: 15, NEW: 0, RUNNABLE: 8, BLOCKED: 0, WAITING: 4, TIMED_WAITING: 3, TERMINATED: 0
ID   NAME                          GROUP          PRIORITY  STATE    %CPU      DELTA_TIM TIME      INTERRUPT DAEMON
2    Reference Handler             system         10        WAITING  0.0       0.000     0:0.000   false     true
3    Finalizer                     system         8         WAITING  0.0       0.000     0:0.000   false     true
12   arthas-timer                  system         5         WAITING  0.0       0.000     0:0.000   false     true
20   arthas-UserStat               system         5         WAITING  0.0       0.000     0:0.000   false     true

jvm指令

THREAD相关

• COUNT: JVM当前活跃的线程数
• DAEMON-COUNT: JVM当前活跃的守护线程数
• PEAK-COUNT: 从JVM启动开始曾经活着的最大线程数
• STARTED-COUNT: 从JVM启动开始总共启动过的线程次数
• DEADLOCK-COUNT: JVM当前死锁的线程数

文件描述符相关

• MAX-FILE-DESCRIPTOR-COUNT：JVM进程最大可以打开的文件描述符数
• OPEN-FILE-DESCRIPTOR-COUNT：JVM当前打开的文件描述符数

sysprop 查看和修改JVM的系统属性

sysprop [-h] [property-name] [property-value]

EXAMPLES:
 sysprop
 sysprop file.encoding
 sysprop production.mode true


# 查看单个属性
sysprop java.version

# 修改单个属性
$ sysprop user.country
user.country=US
$ sysprop user.country CN
Successfully changed the system property.
user.country=CN

sysenv 查看JVM的环境变量

EXAMPLES:

  sysenv

  sysenv USER 

vmoption 查看和修改JVM里诊断相关的option

更新指定的option

$ vmoption PrintGC true
Successfully updated the vm option.
 NAME     BEFORE-VALUE  AFTER-VALUE
------------------------------------
 PrintGC  false         true


$ vmoption PrintGCDetails true
Successfully updated the vm option.
 NAME            BEFORE-VALUE  AFTER-VALUE
-------------------------------------------
 PrintGCDetails  false         true 

perfcounter——查看当前 JVM 的Perf Counter信息

$ perfcounter


$ perfcounter -d
 Name                                   Variability   Units        Value
---------------------------------------------------------------------------------
 java.ci.totalTime                      Monotonic     Ticks        3242526906
 java.cls.loadedClasses                 Monotonic     Events       3404

logger——查看和修改logger

logger

getstatic——查看类的静态属性

* 推荐直接使用ognl命令，更加灵活。
通过getstatic命令可以方便的查看类的静态属性。使用方法为getstatic class_name field_name

$ getstatic demo.MathGame random
field: random
@Random[
    serialVersionUID=@Long[3905348978240129619],
    seed=@AtomicLong[120955813885284],
    multiplier=@Long[25214903917],
    addend=@Long[11],
    mask=@Long[281474976710655],
    DOUBLE_UNIT=@Double[1.1102230246251565E-16],
    BadBound=@String[bound must be positive],
    BadRange=@String[bound must be greater than origin],
    BadSize=@String[size must be non-negative],
    seedUniquifier=@AtomicLong[-3282039941672302964],
    nextNextGaussian=@Double[0.0],
    haveNextNextGaussian=@Boolean[false],
    serialPersistentFields=@ObjectStreamField[][isEmpty=false;size=3],
    unsafe=@Unsafe[sun.misc.Unsafe@2eaa1027],
    seedOffset=@Long[24],
]

诊断Docker里的Java进程

docker exec -it ${containerId} /bin/bash -c “wget https://arthas.aliyun.com/arthas-boot.jar && java -jar arthas-boot.jar”

诊断k8s里容器里的Java进程

kubectl exec -it ${pod} --container ${containerId} – /bin/bash -c “wget https://arthas.aliyun.com/arthas-boot.jar && java -jar arthas-boot.jar”

把Arthas安装到基础镜像里

可以很简单把Arthas安装到你的Docker镜像里。

FROM openjdk:8-jdk-alpine

copy arthas

COPY --from=hengyunabc/arthas:latest /opt/arthas /opt/arthas

实际开发中，接口很少加时间统计，arthas的trace可以清晰的显示方法耗时

反编译查看代码，进行了sleep操作，所以耗时较长

打印id=10的线程堆栈信息，可以看到这个线程正在执行high()方法

反编译hign方法，查看源码，可以看到进行了死循环。去除死循环后，cpu占比降低

进入arthas监控页面，找到目前正在阻塞其他线程的线程，可以看到loop方法中正在锁定一个字符串，阻塞了其他线程

反编译loop方法，可以看到使用了synchronized进行了同步操作，阻塞了其他线程

这个问题其实是我们在用 btrace 这样的工具的大部分时候的初衷！虽然 trace 脚本编写并不复杂，但是千篇一律和频繁地更改，也给我们带来了许多麻烦。

而这在 arthas 就是一个命令的事！

watch com.test.ob testMethod “{params, returnObj, throwExp}” -e -x 2 # 同时监控入参，返回值，及异常

如果有异常，直接打印出来，否则出入参直接监控，超级方便！

sc -d *UserController | grep classLoaderHash

classLoaderHash 75ad60d