Arthas从入门到精通

83 阅读3分钟

Arthas简介

Arthas 是一款线上监控诊断产品,通过全局视角实时查看应用 load、内存、gc、线程的状态信息,并能在不修改应用代码的情况下,对业务问题进行诊断,包括查看方法调用的出入参、异常,监测方法执行耗时,类加载信息等,大大提升线上问题排查效率。

官网地址:arthas.aliyun.com/

了解概况可看官网文档,这里只总结实战常用的

查看哪个子调用比较慢

如果测试反馈,有个接口比较慢,你该如果定位,难道只能通过加日志再重新发布吗?

trace 能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷,但其每次只能跟踪一级方法的调用链路

如果方法调用的次数很多,那么可以用-n参数指定捕捉结果的次数。比如下面的例子里,捕捉到一次调用就退出命令。

$ trace demo.MathGame run -n 1
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 20 ms.
`---ts=2019-12-04 00:45:53;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[0.549379ms] demo.MathGame:run()
        +---[0.059839ms] demo.MathGame:primeFactors() #24
        `---[0.232887ms] demo.MathGame:print() #25

说明:trace 类路径 方法名

可能偶尔几次接口响应比较慢,可根据接口耗时时间进行过滤

$ trace demo.MathGame run '#cost > 10'
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 41 ms.
`---ts=2018-12-04 01:12:02;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[12.033735ms] demo.MathGame:run()
        +---[0.006783ms] java.util.Random:nextInt()
        +---[11.852594ms] demo.MathGame:primeFactors()
        `---[0.05447ms] demo.MathGame:print()

查看方法入参、出参已经异常信息

$ watch demo.MathGame primeFactors "{params, target, returnObj}" -x 2
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 32 ms, listenerId: 5
method=demo.MathGame.primeFactors location=AtExceptionExit
ts=2021-08-31 15:22:57; [cost=0.220625ms] result=@ArrayList[
    @Object[][
        @Integer[-179173],
    ],
    @MathGame[
        random=@Random[java.util.Random@31cefde0],
        illegalArgumentCount=@Integer[44],
    ],
    null,
]
method=demo.MathGame.primeFactors location=AtExit
ts=2021-08-31 15:22:58; [cost=1.020982ms] result=@ArrayList[
    @Object[][
        @Integer[1],
    ],
    @MathGame[
        random=@Random[java.util.Random@31cefde0],
        illegalArgumentCount=@Integer[44],
    ],
    @ArrayList[
        @Integer[2],
        @Integer[2],
        @Integer[26947],
    ],
]

说明:watch 类路径 方法名

"{params, target, returnObj}"对应的方法入参、当前对象以及方法返回值。默认可以不写

-x 表示(方法入参、当前对象以及方法返回值)的展开的深度,看几层

  • 上面的结果里,说明函数被执行了两次,第一次结果是location=AtExceptionExit,说明函数抛出异常了,因此returnObj是 null
  • 在第二次结果里是location=AtExit,说明函数正常返回,因此可以看到returnObj结果是一个 ArrayList
  • -x表示遍历深度,可以调整来打印具体的参数和结果内容,默认值是 1。
  • -x最大值是 4,防止展开结果占用太多内存

特别说明

  • watch 命令定义了 4 个观察事件点,即 -b 函数调用前,-e 函数异常后,-s 函数返回后,-f 函数结束后
  • 4 个观察事件点 -b-e-s 默认关闭,-f 默认打开,当指定观察点被打开后,在相应事件点会对观察表达式进行求值并输出
  • 这里要注意函数入参函数出参的区别,有可能在中间被修改导致前后不一致,除了 -b 事件点 params 代表函数入参外,其余事件都代表函数出参
  • 当使用 -b 时,由于观察事件点是在函数调用前,此时返回值或异常均不存在
  • 在 watch 命令的结果里,会打印出location信息。location有三种可能值:AtEnterAtExitAtExceptionExit。对应函数入口,函数正常 return,函数抛出异常。

条件表达式的例子

$ watch demo.MathGame primeFactors "{params[0],target}" "params[0]<0"
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 68 ms.
ts=2018-12-03 19:36:04; [cost=0.530255ms] result=@ArrayList[
    @Integer[-18178089],
    @MathGame[demo.MathGame@41cf53f9],
]

观察异常信息的例子

$ watch demo.MathGame primeFactors "{params[0],throwExp}" -e -x 2
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 62 ms.
ts=2018-12-03 19:38:00; [cost=1.414993ms] result=@ArrayList[
    @Integer[-1120397038],
    java.lang.IllegalArgumentException: number is: -1120397038, need >= 2
  at demo.MathGame.primeFactors(MathGame.java:46)
  at demo.MathGame.run(MathGame.java:24)
  at demo.MathGame.main(MathGame.java:16)
,
]
  • -e表示抛出异常时才触发
  • express 中,表示异常信息的变量是throwExp

按照耗时进行过滤

$ watch demo.MathGame primeFactors '{params, returnObj}' '#cost>200' -x 2
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 66 ms.
ts=2018-12-03 19:40:28; [cost=2112.168897ms] result=@ArrayList[
    @Object[][
        @Integer[1],
    ],
    @ArrayList[
        @Integer[5],
        @Integer[428379493],
    ],
]
  • #cost>200(单位是ms)表示只有当耗时大于 200ms 时才会输出,过滤掉执行时间小于 200ms 的调用

观察当前对象中的属性

如果想查看函数运行前后,当前对象中的属性,可以使用target关键字,代表当前对象

$ watch demo.MathGame primeFactors 'target'
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 52 ms.
ts=2018-12-03 19:41:52; [cost=0.477882ms] result=@MathGame[
    random=@Random[java.util.Random@522b408a],
    illegalArgumentCount=@Integer[13355],
]

然后使用target.field_name访问当前对象的某个属性

$ watch demo.MathGame primeFactors 'target.illegalArgumentCount'
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 67 ms.
ts=2018-12-03 20:04:34; [cost=131.303498ms] result=@Integer[8]
ts=2018-12-03 20:04:35; [cost=0.961441ms] result=@Integer[8]

查看方法被调用的调用路径

很多时候我们都知道一个方法被执行,但这个方法被执行的路径非常多,或者你根本就不知道这个方法是从那里被执行了,此时你需要的是 stack 命令。

$ stack demo.MathGame primeFactors
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 36 ms.
ts=2018-12-04 01:32:19;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    @demo.MathGame.run()
        at demo.MathGame.main(MathGame.java:16)

说明:stack 类路径 方法名

延伸:这里可以做过滤

例如通过入参过滤

$ stack demo.MathGame primeFactors 'params[0]<0' -n 2
params[0]为第一个参数, -n 2前两条记录

通过执行数据过滤

$ stack demo.MathGame primeFactors '#cost>5'
#cost>5 单位是ms,表示只有当耗时大于 5ms 时才会输出

查看哪些线程比较占cpu?

$ thread -n 1
"arthas-command-execute" Id=72474 cpuUsage=0.75% deltaTime=1ms time=23ms RUNNABLE
    at sun.management.ThreadImpl.dumpThreads0(Native Method)
    at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:448)

说明:指定最忙的前 N 个线程并打印堆栈,实例打印了一个。

  • cpuUsage为采样间隔时间内线程的 CPU 使用率。
  • deltaTime为采样间隔时间内线程的增量 CPU 时间,小于 1ms 时被取整显示为 0ms。
  • time 线程运行总 CPU 时间。

查看哪些线程阻塞了其他线程?

$ 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!

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

查看指定状态的线程

thread --state WAITING
Threads Total: 16, NEW: 0, RUNNABLE: 9, BLOCKED: 0, WAITING: 3, TIMED_WAITING: 4, TERMINATED: 0

说明:状态有NEW、RUNNABLE、BLOCKED、 WAITING、 TIMED_WAITING、 TERMINATED

确定线上某个类运行的代码(反编译)

jad 命令将 JVM 中实际运行的 class 的 byte code 反编译成 java 代码,便于你理解业务逻辑;

$ jad --source-only demo.MathGame
/*
 * Decompiled with CFR 0_132.
 */
package demo;
​
import java.io.PrintStream;
import java.util.ArrayList;
import java.util.Iterator;
import java.util.List;
import java.util.Random;
import java.util.concurrent.TimeUnit;
​
public class MathGame {
    private static Random random = new Random();
    public int illegalArgumentCount = 0;
...

默认情况下,反编译结果里会带有ClassLoader信息,通过--source-only选项,可以只打印源代码。方便和mc/retransform命令结合使用。

也可以只看方法

$ jad demo.MathGame main --lineNumber false
​
ClassLoader:
+-sun.misc.Launcher$AppClassLoader@232204a1
  +-sun.misc.Launcher$ExtClassLoader@7f31245a
​
Location:
/private/tmp/math-game.jar
​
public static void main(String[] args) throws InterruptedException {
    MathGame game = new MathGame();
    while (true) {
        game.run();
        TimeUnit.SECONDS.sleep(1L);
    }
}

--lineNumber 参数默认值为 true,显示指定为 false 则不打印行号。

无须重启服务器,修改线上运行的代码(编译)

mc命令介绍

$ mc --classLoaderClass org.springframework.boot.loader.LaunchedURLClassLoader /tmp/UserController.java -d /tmp
Memory compiler output:
/tmp/com/example/demo/arthas/user/UserController.class
Affect(row-cnt:1) cost in 346 ms

--classLoaderClass参数指定 ClassLoader

-d命令指定输出目录

编译生成.class文件之后,可以结合retransform命令实现热更新代码。

修改线上代码步骤

jad --source-only com.example.demo.arthas.user.UserController > /tmp/UserController.java
​
mc /tmp/UserController.java -d /tmp
​
retransform /tmp/com/example/demo/arthas/user/UserController.class
  • jad 命令反编译,然后可以用其它编译器,比如 vim 来修改源码
  • mc 命令来内存编译修改过的代码
  • 用 retransform 命令加载新的字节码

使用mc命令来编译jad的反编译的代码有可能失败。可以在本地修改代码,编译好后再上传到服务器上。有的服务器不允许直接上传文件,可以使用base64命令来绕过。

  1. 在本地先转换.class文件为 base64,再保存为 result.txt

    base64 < Test.class > result.txt
    
  2. 到服务器上,新建并编辑result.txt,复制本地的内容,粘贴再保存

  3. 把服务器上的 result.txt还原为.class

    base64 -d < result.txt > Test.class
    
  4. 用 md5 命令计算哈希值,校验是否一致

特别说明

  • 不允许新增加 field/method
  • 正在跑的函数,没有退出不能生效

高级用法

watch/stack/trace 这个三个命令都支持#cost

【Arthas问题排查集】活用ognl表达式