0 前言
应用程序运行中出现了异常,有时通过应用日志或应用程序提供的诊断接口无法或难以定位出问题所在,添加新的诊断代码再重新上线,有可能无法复现问题,这时非常需要一个在线诊断工具可以在线观察应用程序内部变量的值,甚至修改内部变量的值。在C/C++中有GDB工具,在java环境下有BTrace工具,但是BTrace工具使用起来稍显复杂。而arthas则是一款易于学习、易于应用且功能强大的java在线诊断工具。
arthas可以方便处理应用程序正常开发、运行、部署时没有预先考虑到的在线诊断问题,在需要的时候,在不打断应用程序运行的情况下attach到运行中的应用程序,使用完后继续让应用程序恢复到attach前的状态继续运行。
它可以在线提供以下基本功能:
- 查看和修改系统属性、环境变量、JVM、类日志等级等运行环境和状态信息
- 查找类的classloader、属性、方法信息。查找时支持通配符、OGNL语言。
- 查看类实例的运行时属性值,调用类实例的方法
- 观察和跟踪实例方法的调用情况,如调用统计、输入返回值、调用栈和执行时间,并能回放方法调用
- 支持生成火焰图
- 支持后台任务管理
根据官网的介绍,Arthas可以帮助你解决:
- 这个类从哪个 jar 包加载的?为什么会报各种类相关的 Exception?
- 我改的代码为什么没有执行到?难道是我没 commit?分支搞错了?
- 遇到问题无法在线上 debug,难道只能通过加日志再重新发布吗?
- 线上遇到某个用户的数据处理有问题,但线上同样无法 debug,线下无法重现!
- 是否有一个全局视角来查看系统的运行状况?
- 有什么办法可以监控到JVM的实时运行状态?
- 怎么快速定位应用的热点,生成火焰图?
- 怎样直接从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.java
的staticPrintInfo()
方法代码,修改前和后的代码如下所示:
修改前:
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-pattern
和method-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/0
2次,网址http://localhost/user/1
6次,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的jobs
、kill
、fg
、bg
等后台任务管理命令