易用好用的java在线诊断工具arthas

0 前言

应用程序运行中出现了异常,有时通过应用日志或应用程序提供的诊断接口无法或难以定位出问题所在,添加新的诊断代码再重新上线,有可能无法复现问题,这时非常需要一个在线诊断工具可以在线观察应用程序内部变量的值,甚至修改内部变量的值。在C/C++中有GDB工具,在java环境下有BTrace工具,但是BTrace工具使用起来稍显复杂。而arthas则是一款易于学习、易于应用且功能强大的java在线诊断工具。

arthas可以方便处理应用程序正常开发、运行、部署时没有预先考虑到的在线诊断问题,在需要的时候,在不打断应用程序运行的情况下attach到运行中的应用程序,使用完后继续让应用程序恢复到attach前的状态继续运行。

它可以在线提供以下基本功能:

  1. 查看和修改系统属性、环境变量、JVM、类日志等级等运行环境和状态信息
  2. 查找类的classloader、属性、方法信息。查找时支持通配符、OGNL语言。
  3. 查看类实例的运行时属性值,调用类实例的方法
  4. 观察和跟踪实例方法的调用情况,如调用统计、输入返回值、调用栈和执行时间,并能回放方法调用
  5. 支持生成火焰图
  6. 支持后台任务管理

根据官网的介绍,Arthas可以帮助你解决:

  1. 这个类从哪个 jar 包加载的?为什么会报各种类相关的 Exception?
  2. 我改的代码为什么没有执行到?难道是我没 commit?分支搞错了?
  3. 遇到问题无法在线上 debug,难道只能通过加日志再重新发布吗?
  4. 线上遇到某个用户的数据处理有问题,但线上同样无法 debug,线下无法重现!
  5. 是否有一个全局视角来查看系统的运行状况?
  6. 有什么办法可以监控到JVM的实时运行状态?
  7. 怎么快速定位应用的热点,生成火焰图?
  8. 怎样直接从JVM内查找某个类的实例?

1 安装与启动

安装启动arthas只要从官网下载arthas-bin.zip,解压后执行java -jar arthas-boot.jar即可

quit/exit命令可以退出arthas,但是因为arthas连接上目标java进程后会插入一些字节码。如果需要清除掉插入的字节码,让进程回复到之前的原始代码运行,需要使用stop命令退出

$ mkdir arthas
$ mv arthas-bin.zip arthas
$ unzip arthas-bin.zip
$ ls
arthas-agent.jar  arthas-boot.jar    arthas-core.jar    arthas-spy.jar  as-service.bat  async-profiler    lib          math-game.jar
arthas-bin.zip    arthas-client.jar  arthas.properties  as.bat          as.sh           install-local.sh  logback.xml

# 查看帮助
$ java -jar arthas-boot.jar -h

# 启动
% java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.5.4
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.

# arthas自动列出的本用户启动的所有java进程

* [1]: 15634 com.javatest.mapstruct.MapstructApplication
  [2]: 15621 org.codehaus.plexus.classworlds.launcher.Launcher
  [3]: 8757
  [4]: 8783
  
# 输入1,选择需要attach的进程,然后回车
1
[INFO] arthas home: /Users/yangshengbing/Documents/bin/arthas
[INFO] Try to attach process 15634
[INFO] Attach process 15634 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'


wiki       https://arthas.aliyun.com/doc
tutorials  https://arthas.aliyun.com/doc/arthas-tutorials.html
version    3.5.4
main_class com.javatest.mapstruct.MapstructApplication
pid        15634
time       2021-11-10 20:29:09

# JVM进程ID
[arthas@15634]$ session
 Name        Value
--------------------------------------------------
 JAVA_PID    15634
 SESSION_ID  78b4e2d2-2479-406e-a10f-c534b29bc0c2
 
# arthas版本 
[arthas@15634]$ version
3.5.4
[arthas@15634]$ history
    1  session
    2  version
    3  history
    
# 退出,但是arthas server还在目标jvm上运行
[arthas@7989]$ exit
[arthas@7989]$ quit

# 退出,同时停止arthas server
[arthas@7989]$ stop

2 查看和修改JVM系统信息

2.1 dashboard、thread、jvm、sysenv、vmoption

这些命令用于查看进程的系统信息,跟其他jvm工具没什么区别

2.2 sysprop

可以查看系统属性,也可以新增或修改系统属性

# 查看所有的系统属性,然后grep过滤
[arthas@15634]$ sysprop | grep java.version
 java.version                                                            1.8.0_292
 
# 查看指定系统属性值 
[arthas@15634]$ sysprop java.version
  java.version                                                            1.8.0_292

# 新增系统系统属性
[arthas@15634]$ sysprop application.test testvalue
Successfully changed the system property.
  application.test                                                        testvalue
[arthas@15634]$ sysprop application.test
 application.test                                                        testvalue
[arthas@15634]$

2.3 logger

查看进程的logger信息,如配置的appender,root level等等

$ logger
 name                                                        ROOT
 class                                                       ch.qos.logback.classic.Logger
 classLoader                                                 sun.misc.Launcher$AppClassLoader@4e0e2f2a
 classLoaderHash                                             4e0e2f2a
 level                                                       INFO
 effectiveLevel                                              INFO
 additivity                                                  true
 codeSource                                                  file:/Users/yangshengbing/.m2/repository/ch/qos/logback/logback-classic/1.2.6/logback-classic-1.2.6.jar
 appenders                                                   name            CONSOLE
                                                             class           ch.qos.logback.core.ConsoleAppender
                                                             classLoader     sun.misc.Launcher$AppClassLoader@4e0e2f2a
                                                             classLoaderHash 4e0e2f2a
                                                             target          System.out

查看指定类的logger信息

[arthas@15634]$ logger -n com.javatest.mapstruct.MapstructApplication
 name                                                        com.javatest.mapstruct.MapstructApplication
 class                                                       ch.qos.logback.classic.Logger
 classLoader                                                 sun.misc.Launcher$AppClassLoader@4e0e2f2a
 classLoaderHash                                             4e0e2f2a
 level                                                       null
 effectiveLevel                                              INFO
 additivity                                                  true
 codeSource                                                  file:/Users/yangshengbing/.m2/repository/ch/qos/logback/logback-classic/1.2.6/logback-classic-1.2.6.jar

在线更改指定类的log level,这个比较有用

[arthas@15634]$ logger -n com.javatest.mapstruct.MapstructApplication --level debug
Update logger level success.
[arthas@15634]$ logger -n com.javatest.mapstruct.MapstructApplication | grep level
 level                                                       DEBUG

2.4 ognl

ognl(Object Graph Navigation Language)是apache开源的一个方便查询和设置对象的属性值的表达式语言,它可以沿着对象的属性树一直向下递归查找,直到最底层的基本数据类型属性为止,也是支持map、list等集合成员的选择。

arthas可以用ognl表达式来执行类的静态方法或查看指定类的静态变量值

例如,我们项目中有一个类OgnlTest实例,是一个spring bean,持有两个静态对象,一个是OgnlObject类的实例,一个是spring context的实例,还有一个静态方法。OgnlTest类和OgnlObject类的定义如下:

package com.javatest.arthastest;

import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.BeansException;
import org.springframework.context.ApplicationContext;
import org.springframework.context.ApplicationContextAware;
import org.springframework.stereotype.Component;

@Slf4j
@Component
public class OgnlTest implements ApplicationContextAware {

    private static OgnlObject obj = new OgnlObject();
    private static ApplicationContext context;

    @Override
    public void setApplicationContext(ApplicationContext applicationContext) throws BeansException {
        context = applicationContext;
    }

    public static void staticPrintInfo(String str) {
        log.info("do OgnlTest.staticPrintInfo, param: {}", str);
    }

    public void printInfo(String str) {
        log.info("do OgnlTest.printInfo, param: {}", str);
    }
    
}
package com.javatest.arthastest;

import com.google.common.collect.Lists;
import lombok.Data;

import java.util.List;

@Data
public class OgnlObject {

    private List<String> aList = Lists.newArrayList("hello", "world", "yeah");
    private InnerObject inner = new InnerObject();

    @Data
    public static class InnerObject {
        private String sa = "www";
        private Integer ib = 200;
    }
}

先查下OgnlTest类的ClassLoader的hashcode

[arthas@21926]$ sc -d com.javatest.arthastest.OgnlTest | grep classLoaderHash
 classLoaderHash   18b4aac2

然后执行OgnlTest的静态方法staticPrintInfo()

# -c 用于指定类的ClassLoader, 两个@符号之间是查询目标类的全限定名
[arthas@21926]ognl -c 18b4aac2 '@com.javatest.arthastest.OgnlTest@staticPrintInfo("hello")'
null

查看应用程序的日志,打印了以下一条日志:

2021-11-10 22:23:33.225  INFO 21926 --- [command-execute] com.javatest.arthastest.OgnlTest         : do OgnlTest.staticPrintInfo, param: hello

查看OgnlTest的静态字段obj以及它的各级属性值

# -x 表示展开的实例属性的级数

[arthas@21926]$ ognl -c 18b4aac2 '@com.javatest.arthastest.OgnlTest@obj' -x 2
@OgnlObject[
    aList=@ArrayList[
        @String[hello],
        @String[world],
        @String[yeah],
    ],
    inner=@InnerObject[
        sa=@String[www],
        ib=@Integer[200],
    ],
]

# 查看OgnlObject的aList属性值
[arthas@21926]$ ognl -c 18b4aac2 '@com.javatest.arthastest.OgnlTest@obj.aList' -x 2
@ArrayList[
    @String[hello],
    @String[world],
    @String[yeah],
]
# 查看OgnlObject的aList属性的第一个元素
[arthas@21926]$ ognl -c 18b4aac2 '@com.javatest.arthastest.OgnlTest@obj.aList[0]'
@String[hello]
[arthas@21926]$ ognl -c 18b4aac2 '@com.javatest.arthastest.OgnlTest@obj.inner''
>
[arthas@21926]$ ognl -c 18b4aac2 '@com.javatest.arthastest.OgnlTest@obj.inner'
@InnerObject[
    sa=@String[www],
    ib=@Integer[200],
]
# 查看OgnlObject的第三层属性sa字段的值
[arthas@21926]$ ognl -c 18b4aac2 '@com.javatest.arthastest.OgnlTest@obj.inner.sa'
@String[www]

ognl支持中间变量,我们可以在一个表达式中调用多个方法,通过中间变量传递值

# #tempValue表示一个中间变量
[arthas@21926]$ ognl -c 18b4aac2 '#tempValue=@com.javatest.arthastest.OgnlTest@obj.inner.sa, @com.javatest.arthastest.OgnlTest@staticPrintInfo(#tempValue)'

我们留心一下会发现,ObjectTest实例持有了一个spring context的一个静态属性,因为ognl可以获取类的静态属性,那么就可以获取spring context的实例,然后就可以获取所有注册到spring context的所有bean,并遍历检查他们的各级属性以及执行它们的方法,也就是说这样我们几乎可以查看所有的类,执行所有的类的方法。

让我们尝试一下调用OgnlTest实例的非静态方法printInfo():

# 验证一下,确实可以通过spring context的geBean()方法获取到OgnlTest类实例
[arthas@21926]$ ognl -c 18b4aac2 '@com.javatest.arthastest.OgnlTest@context.getBean("ognlTest")' -x 1
@OgnlTest[
    log=@Logger[Logger[com.javatest.arthastest.OgnlTest]],
    obj=@OgnlObject[OgnlObject(aList=[hello, world, yeah], inner=OgnlObject.InnerObject(sa=www, ib=200))],
    context=@AnnotationConfigServletWebServerApplicationContext[org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@3c9754d8, started on Wed Nov 10 22:22:17 CST 2021],
]

# 调用实例的非静态方法
[arthas@21926]$ ognl -c 18b4aac2 '@com.javatest.arthastest.OgnlTest@context.getBean("ognlTest").printInfo("haha")'
null

查看应用程序的日志,打印了以下日志内容,说明调用成功了

2021-11-10 22:33:18.962  INFO 21926 --- [command-execute] com.javatest.arthastest.OgnlTest         : do OgnlTest.printInfo, param: haha

3 查询和热加载class

3.1 classloader

查询应用程序classloader的信息

[arthas@22999]$ classloader
 name                                                numberOfInstances  loadedCountTotal
 sun.misc.Launcher$AppClassLoader                    1                  3557
 BootstrapClassLoader                                1                  3226
 com.taobao.arthas.agent.ArthasClassloader           1                  1496
 sun.reflect.DelegatingClassLoader                   64                 64
 sun.misc.Launcher$ExtClassLoader                    1                  39
 javax.management.remote.rmi.NoCallStackClassLoader  2                  2
Affect(row-cnt:6) cost in 62 ms.
[arthas@22999]$
[arthas@22999]$
[arthas@22999]$ classloader -l
 name                                                         loadedCount  hash      parent
 BootstrapClassLoader                                         3226         null      null
 com.taobao.arthas.agent.ArthasClassloader@1fe83cc2           1499         1fe83cc2  sun.misc.Launcher$ExtClassLoader@5f5a92bb
 javax.management.remote.rmi.NoCallStackClassLoader@7e774085  1            7e774085  null
 javax.management.remote.rmi.NoCallStackClassLoader@53e25b76  1            53e25b76  null
 sun.misc.Launcher$AppClassLoader@18b4aac2                    3557         18b4aac2  sun.misc.Launcher$ExtClassLoader@5f5a92bb
 sun.misc.Launcher$ExtClassLoader@5f5a92bb                    39           5f5a92bb  null
Affect(row-cnt:6) cost in 37 ms.
[arthas@22999]$ classloader -t
+-BootstrapClassLoader
+-javax.management.remote.rmi.NoCallStackClassLoader@7e774085
+-javax.management.remote.rmi.NoCallStackClassLoader@53e25b76
+-sun.misc.Launcher$ExtClassLoader@5f5a92bb
  +-com.taobao.arthas.agent.ArthasClassloader@1fe83cc2
  +-sun.misc.Launcher$AppClassLoader@18b4aac2
Affect(row-cnt:6) cost in 18 ms.
[arthas@22999]$
[arthas@22999]$ classloader -c 1fe83cc2
file:/Users/yangshengbing/Documents/bin/arthas/arthas-core.jar

Affect(row-cnt:2) cost in 3 ms.

3.2 sc

sc(Search Class)可以查找指定类的信息,比如ClassLoader、字段等

[arthas@22999]$ sc com.javatest.arthastest.OgnlTest
com.javatest.arthastest.OgnlTest

# -d 打印类的详细信息
[arthas@22999]$ sc -d com.javatest.arthastest.OgnlTest
 class-info        com.javatest.arthastest.OgnlTest
 code-source       /Users/yangshengbing/Documents/idea_java/example/javatest/arthastest/target/classes/
 name              com.javatest.arthastest.OgnlTest
 isInterface       false
 isAnnotation      false
 isEnum            false
 isAnonymousClass  false
 isArray           false
 isLocalClass      false
 isMemberClass     false
 isPrimitive       false
 isSynthetic       false
 simple-name       OgnlTest
 modifier          public
 annotation        org.springframework.stereotype.Component
 interfaces        org.springframework.context.ApplicationContextAware
 super-class       +-java.lang.Object
 class-loader      +-sun.misc.Launcher$AppClassLoader@18b4aac2
                     +-sun.misc.Launcher$ExtClassLoader@5f5a92bb
 classLoaderHash   18b4aac2

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

# -f 打印类的字段的详细信息
[arthas@22999]$ sc -d -f com.javatest.arthastest.OgnlTest
 class-info        com.javatest.arthastest.OgnlTest
 code-source       /Users/yangshengbing/Documents/idea_java/example/javatest/arthastest/target/classes/
 name              com.javatest.arthastest.OgnlTest
 isInterface       false
 isAnnotation      false
 isEnum            false
 isAnonymousClass  false
 isArray           false
 isLocalClass      false
 isMemberClass     false
 isPrimitive       false
 isSynthetic       false
 simple-name       OgnlTest
 modifier          public
 annotation        org.springframework.stereotype.Component
 interfaces        org.springframework.context.ApplicationContextAware
 super-class       +-java.lang.Object
 class-loader      +-sun.misc.Launcher$AppClassLoader@18b4aac2
                     +-sun.misc.Launcher$ExtClassLoader@5f5a92bb
 classLoaderHash   18b4aac2
 fields            name     log
                   type     org.slf4j.Logger
                   modifier final,private,static
                   value    Logger[com.javatest.arthastest.OgnlTest]

                   name     obj
                   type     com.javatest.arthastest.OgnlObject
                   modifier private,static
                   value    OgnlObject(aList=[hello, world, yeah], inner=OgnlObject.InnerObject(sa=www, ib=200))

                   name     context
                   type     org.springframework.context.ApplicationContext
                   modifier private,static
                   value    org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@3c9754d8, started on Wed Nov 10 22:22:17 CST 2
                            021


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

# 支持通配符
[arthas@22999]$ sc com.javatest.*.OgnlTest
com.javatest.arthastest.OgnlTest
Affect(row-cnt:1) cost in 37 ms.

3.3 sm

sm(Search Method)可以查看类的方法定义信息

# 查看类的所有接口
[arthas@22999]$ sm com.javatest.arthastest.OgnlTest
com.javatest.arthastest.OgnlTest <init>()V
com.javatest.arthastest.OgnlTest staticPrintInfo(Ljava/lang/String;)V
com.javatest.arthastest.OgnlTest printInfo(Ljava/lang/String;)V
com.javatest.arthastest.OgnlTest setApplicationContext(Lorg/springframework/context/ApplicationContext;)V
Affect(row-cnt:4) cost in 34 ms.

[arthas@22999]$ sm com.javatest.arthastest.OgnlTest staticPrintInfo
com.javatest.arthastest.OgnlTest staticPrintInfo(Ljava/lang/String;)V
Affect(row-cnt:1) cost in 22 ms.

# 查看指定接口的详细信息
[arthas@22999]$ sm -d com.javatest.arthastest.OgnlTest staticPrintInfo
 declaring-class  com.javatest.arthastest.OgnlTest
 method-name      staticPrintInfo
 modifier         public,static
 annotation
 parameters       java.lang.String
 return           void
 exceptions
 classLoaderHash  18b4aac2

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

3.4 jad、mc、redefine实现class热加载

先用jad命令反汇编需要修改的类,执行一下命令:

[arthas@13180]$ jad --source-only com.javatest.arthastest.OgnlTest > ./arthas/src/java/OgnlTest.java

--source-only表示只生成反汇编的.java文件,否则jad命令除了输出.java文件内容,还是输出ClassLoader等信息。生成的.java文件存放在当前工作目录的./arthas/src/java子目录下。注意,当前工作目录是指应用程序的当前工作目录,而不是arthas的执行文件目录。

然后修改反汇编的OgnlTest.javastaticPrintInfo()方法代码,修改前和后的代码如下所示:
修改前:

public static void staticPrintInfo(String str) {
        log.info("do OgnlTest.staticPrintInfo, param: {}", str);
    }

修改后:

public static void staticPrintInfo(String str) {
        String modifiedStr = "hello, " + str;
        log.info("do OgnlTest.staticPrintInfo, param: {}", (Object)modifiedStr);
    }

修改源文件时需要注意:
1)只能修改现有方法的内部代码,不能修改或增加类的字段,也不能增加新的方法
2)因为后面替换旧的class时,替换的时机是方法的代码不在循环中执行,所有如果方法中有一个无限循环的代码块,则改方法不支持修改

然后使用mc(Memory Compile)命令编译一下修改后的类

[arthas@13180]$ mc -c 18b4aac2 /Users/yangshengbing/Documents/bin/arthas/src/java/OgnlTest.java -d ./arthas/src/classes
Memory compiler output:
./arthas/src/classes/com/javatest/arthastest/OgnlTest.class
Affect(row-cnt:1) cost in 1426 ms.

编译完后可以看到在目录./arthas/src/classes/com/javatest/arthastest/下生成了OgnlTest.class文件
然后用refefine命令将生成的新class文件加载到JVM中,替换旧的对象。

[arthas@13180]$ redefine ./arthas/src/classes/com/javatest/arthastest/OgnlTest.class
redefine success, size: 1, classes:
com.javatest.arthastest.OgnlTest

执行一下刚刚修改的方法:

[arthas@13180]$ ognl -c 18b4aac2 '@com.javatest.arthastest.OgnlTest@staticPrintInfo("a test")'
null

应用程序打印了以下日志内容,说明成功替换了:

2021-11-11 16:02:18.514  INFO 13180 --- [command-execute] com.javatest.arthastest.OgnlTest         : do OgnlTest.staticPrintInfo, param: hello, a test

4 监测应用程序方法运行情况

arthas提供了持续监控方法运行的统计、输入参数、返回值、调用栈、调用栈中每个方法花费的时间的命令,如monitor、watch、trace、stack、tt。下面我们用官方提供的一个测试程序来说明这些命令基本使用方法。

监控命令的基本格式为:

命令名 [参数] class-pattern method-pattern [condition-express]

class-patternmethod-pattern指定类和方法的匹配模式,支持通配符,如果提供了condition-express,则只有条件表达式为真时的方法运行才会被监控

这些监控命令都是持续监控运行的,需要退出时输入CTRL + C

首先从github下载测试程序相应的jar包到本地,然后启动应用程序:

% curl -L https://github.com/hengyunabc/spring-boot-inside/raw/master/demo-arthas-spring-boot/demo-arthas-spring-boot.jar -o demo-arthas-spring-boot.jar
% java -jar demo-arthas-spring-boot.jar

从应用程序打印的日志可以知道web监听的端口为80

我们在github上查看下spring-boot-inside/demo-arthas-spring-boot/src/main/java/com/example/demo/arthas/user/UserController.java文件的内容如下:

package com.example.demo.arthas.user;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class UserController {
    private static final Logger logger = LoggerFactory.getLogger(UserController.class);

    @GetMapping("/user/{id}")
    public User findUserById(@PathVariable Integer id) {
        logger.info("id: {}" , id);

        if (id != null && id < 1) {
            // return new User(id, "name" + id);
            throw new IllegalArgumentException("id < 1");
        } else {
            return new User(id, "name" + id);
        }
    }

}

可见它提供了一个方法,如果输入的id值小于1,则抛出一个异常,否则返回一个User实例。

4.1 monitor

monitor命令会持续统计指定统计周期内方法运行的统计信息,如成功次数、失败次数、平均运行时间等信息

输入以下命令,会监控findUserById()方法的运行统计情况,-c 表示统计周期,单位为秒。然后60秒内在浏览器中分别输入地址http://localhost/user/02次,网址http://localhost/user/16次,60秒后会输出下面的统计信息。按CTRL + C退出监控

[arthas@27175]$ monitor -c 60 com.example.demo.arthas.user.UserController findUserById
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 63 ms, listenerId: 3
 timestamp                                               class                                                                               method                                                                              total                       success                     fail                        avg-rt(ms)                  fail-rate
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 2021-11-11 20:41:21                                     com.example.demo.arthas.user.UserController                                         findUserById                                                                        8                           6                           2                           0.41                        25.00%

4.2 watch

watch命令是使用的非常频繁的一个命令,它监控指定方法的输入、输出、异常等值,从而发现方法在特定环境下运行是否符合预期。

watch命令的基本格式为:

watch [-besfEx] class-pattern method-pattern [express] [condition-express]

-b: Before,表示在方法调用之前观察
-e: Exception,表示方法调用异常时观察
-s:Success,表示方法调用正常返回之后观察
-f:Finish,表示方法调用完后(正常返回或抛出异常)观察
-E:采用正则表达式,否则使用通配符
-x:观察对应值的属性的层次深度

express:表示观察的方法调用的值,支持OGNL表达式,默认值为{params, target, returnObj}
表达式支持的观察对象包括:
1)loader
2)clazz 
3)method
4)target
5)params:方法参数
6)returnObj:方法返回值
7)throwExp:方法异常
8)isBefore
9)isThrow
10)isReturn
常用的是默认的几个表达式

condition-express:条件表达式,只有条件表达式为真时才观察

特别说明:

watch 命令定义了4个观察事件点,即 -b 方法调用前,-e 方法异常后,-s 方法返回后,-f 方法结束后

4个观察事件点 -b、-e、-s 默认关闭,-f 默认打开,当指定观察点被打开后,在相应事件点会对观察表达式进行求值并输出

这里要注意方法入参和方法出参的区别,有可能在中间被修改导致前后不一致,除了 -b 事件点 params 代表方法入参外,其余事件都代表方法出参

当使用 -b 时,由于观察事件点是在方法调用前,此时返回值或异常均不存在

在watch命令的结果里,会打印出location信息。location有三种可能值:AtEnter,AtExit,AtExceptionExit。对应函数入口,函数正常return,函数抛出异常。

在arthas中输入下面的命令,观察方法调用的输入参数和异常:

[arthas@27175]$ watch com.example.demo.arthas.user.UserController * '{params, throwExp}' -x 2

然后在浏览器地址栏输入http://localhost/user/1,arthas输出一下信息:

Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 2) cost in 203 ms, listenerId: 5
method=com.example.demo.arthas.user.UserController.findUserById location=AtExit
ts=2021-11-11 21:16:04; [cost=1.347667ms] result=@ArrayList[
    @Object[][
        @Integer[1],
    ],
    null,
]

method表示调用的方法,location=AtExit表示正常返回,ts表示方法调用的时间,cost表示方法调用花费的时间,result是一个列表,元素分别与观察的对象对应。本例子中表示输入了1个参数,参数是Integer类型,值为1。result列表第二个元素为null,表示没有抛出异常。

然后在浏览器中输入地址http://localhost/user/0,arthas会输出下面内容:

method=com.example.demo.arthas.user.UserController.findUserById location=AtExceptionExit
ts=2021-11-11 21:21:21; [cost=2.491166ms] result=@ArrayList[
    @Object[][
        @Integer[0],
    ],
    java.lang.IllegalArgumentException: id < 1
    at com.example.demo.arthas.user.UserController.findUserById(UserController.java:19)
    .....

location=AtExceptionExit表示异常退出,result的第二个元素则是抛出的异常对象的信息。

如果需要添加条件表达是,比如第一个入参大于0时才跟踪,则使用下面命令:

[arthas@27175]$ watch com.example.demo.arthas.user.UserController * '{params, throwExp}' 'params[0] > 0' -x 2

4.3 trace

trace命令用来跟踪方法调用栈各层方法运行花费的时间信息,在定位方法调用性能瓶颈时比较有用。

在arthas中执行下面命令,-n 1表示跟踪方法调用的次数,然后在浏览器中输入地址http://localhost/user/0,arthas输出以下信息:

[arthas@27175]$ trace com.example.demo.arthas.user.UserController * -n 1
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 2) cost in 97 ms, listenerId: 6
`---ts=2021-11-11 21:28:45;thread_name=http-nio-80-exec-7;id=18;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@befeb39
    `---[1.262ms] com.example.demo.arthas.user.UserController:findUserById() [throws Exception]
        +---[0.71525ms] org.slf4j.Logger:info() #15
        `---throw:java.lang.IllegalArgumentException #19 [id < 1]

Command execution times exceed limit: 1, so command will exit. You can set it with -n option.

4.4 stack

stack命令用来跟踪方法调用栈

[arthas@27175]$ stack com.example.demo.arthas.user.UserController findUserById
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 74 ms, listenerId: 8
ts=2021-11-11 21:33:07;thread_name=http-nio-80-exec-4;id=15;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@befeb39
    @com.example.demo.arthas.user.UserController.findUserById()
        at sun.reflect.GeneratedMethodAccessor42.invoke(null:-1)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
        .......

4.5 tt

tt(Time Tunnel)命令可以把每次方法调用跟踪数据存储起来(存储在JVM中,注意不要让JVM发生oom),然后可以查看每次的调用数据或重放某次调用

在arthas中执行下面命令。-t表示记录所有的调用,-n表示记录调用10次。然后调用findUserById()方法10次,输出信息如下所示

[arthas@27175]$ tt -t com.example.demo.arthas.user.UserController findUserById -n 10
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 120 ms, listenerId: 9
 INDEX                  TIMESTAMP                                               COST(ms)                    IS-RET                 IS-EXP                OBJECT                                     CLASS                                                                               METHOD
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 1000                   2021-11-11 22:03:34                                     1.687875                    true                   false                 0x7f464261                                 UserController                                                                      findUserById
 1001                   2021-11-11 22:03:38                                     0.986084                    true                   false                 0x7f464261                                 UserController                                                                      findUserById
 1002                   2021-11-11 22:03:40                                     0.985625                    false                  true                  0x7f464261                                 UserController                                                                      findUserById
 1003                   2021-11-11 22:03:45                                     0.252625                    true                   false                 0x7f464261                                 UserController                                                                      findUserById
 1004                   2021-11-11 22:03:46                                     0.321875                    true                   false                 0x7f464261                                 UserController                                                                      findUserById
 1005                   2021-11-11 22:03:50                                     1.786959                    true                   false                 0x7f464261                                 UserController                                                                      findUserById
 1006                   2021-11-11 22:03:51                                     0.26375                     true                   false                 0x7f464261                                 UserController                                                                      findUserById
 1007                   2021-11-11 22:04:01                                     2.78175                     true                   false                 0x7f464261                                 UserController                                                                      findUserById
 1008                   2021-11-11 22:04:02                                     1.225834                    true                   false                 0x7f464261                                 UserController                                                                      findUserById
 1009                   2021-11-11 22:04:06                                     0.221709                    true                   false                 0x7f464261                                 UserController                                                                      findUserById
Command execution times exceed limit: 10, so command will exit. You can set it with -n option.

参看某次调用的详细信息:

[arthas@27175]$ tt -i 1001
 INDEX          1001
 GMT-CREATE     2021-11-11 22:03:38
 COST(ms)       0.986084
 OBJECT         0x7f464261
 CLASS          com.example.demo.arthas.user.UserController
 METHOD         findUserById
 IS-RETURN      true
 IS-EXCEPTION   false
 PARAMETERS[0]  @Integer[1]
 RETURN-OBJ     @User[
                    id=@Integer[1],
                    name=@String[name1],
                ]
Affect(row-cnt:1) cost in 15 ms.

重放某次调用, -p表示执行重放,--replay-times 2表示重放2次,--replay-interval 1000表示重放间隔为1秒(replay-interval单位是ms):

[arthas@27175]$ tt -i 1001 -p --replay-times 2 --replay-interval 1000
 RE-INDEX       1001
 GMT-REPLAY     2021-11-11 22:11:04
 OBJECT         0x7f464261
 CLASS          com.example.demo.arthas.user.UserController
 METHOD         findUserById
 PARAMETERS[0]  @Integer[1]
 IS-RETURN      true
 IS-EXCEPTION   false
 COST(ms)       1.614084
 RETURN-OBJ     @User[
                    id=@Integer[1],
                    name=@String[name1],
                ]
Time fragment[1001] successfully replayed 1 times.

 RE-INDEX       1001
 GMT-REPLAY     2021-11-11 22:11:05
 OBJECT         0x7f464261
 CLASS          com.example.demo.arthas.user.UserController
 METHOD         findUserById
 PARAMETERS[0]  @Integer[1]
 IS-RETURN      true
 IS-EXCEPTION   false
 COST(ms)       0.73875
 RETURN-OBJ     @User[
                    id=@Integer[1],
                    name=@String[name1],
                ]
Time fragment[1001] successfully replayed 2 times.

5 生成火焰图

arthas也支持生成应用程序的火焰图。

profile命令的格式:

profiler [-ifde] action [actionArg]

action:执行的动作,比如start、stop等
actionArg:动作参数

-i:采样间隔,单位为ns,(默认值:10'000'000,即10 ms)
-f:采样结果输出的文件路径
-d:采样周期,单位为秒
-e:跟踪的事件(如cpu, alloc, lock, cache-misses等),默认是cpu

查看支持的profile事件

[arthas@7989]$ profiler list
Basic events:
  cpu
  alloc
  lock
  wall
  itimer
Java method calls:
  ClassName.methodName
Perf events:
  page-faults
  context-switches
  cycles
  instructions
  cache-references
  cache-misses
  branches
  branch-misses
  bus-cycles
  L1-dcache-load-misses
  LLC-load-misses
  dTLB-load-misses
  mem:breakpoint
  trace:tracepoint

profiler其他几个常用的命令

# 开始profile,周期300秒
[arthas@7989]$ profiler start -d 300
Started [cpu] profiling
profiler will silent stop after 300 seconds.

# 当前采样数
[arthas@7989]$ profiler getSamples
24

# 当前状态
[arthas@7989]$ profiler status
[perf] profiling is running for 55 seconds

# 停止
[arthas@7989]$ profiler stop --file /tmp/output.svg
[arthas@7989]$ profiler stop --format html

6 后台任务执行

watch/trace/tt等命令往往需要长时间运行,以收集关心的数据,arthas支持linux的常用后台任务管理命令。比如可以使用重定向功能(>)将结果输出到结果文件,使用&让跟踪功能在后台运行,也支持linux的jobskillfgbg等后台任务管理命令

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 215,794评论 6 498
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,050评论 3 391
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 161,587评论 0 351
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,861评论 1 290
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,901评论 6 388
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,898评论 1 295
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,832评论 3 416
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,617评论 0 271
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,077评论 1 308
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,349评论 2 331
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,483评论 1 345
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,199评论 5 341
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,824评论 3 325
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,442评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,632评论 1 268
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,474评论 2 368
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,393评论 2 352

推荐阅读更多精彩内容