Java 诊断工具 Arthas-实操案例

实操案例

排查函数调用异常

通过curl 请求接口只能看到返回异常，但是看不到具体的请求参数和堆栈信息。

shell@Alicloud:~$ curl http://localhost:61000/user/0 {"timestamp":165****063042,"status":500,"error":"Internal Server Error","exception":"java.lang.IllegalArgumentException","message":"id < 1","path":"/user/0"}

查看UserController的 参数/异常

在Arthas里执行：

watch com.example.demo.arthas.user.UserController * '{params, throwExp}' 

1. 第一个参数是类名，支持通配
2. 第二个参数是函数名，支持通配 访问 curl ,watch命令会打印调用的参数和异常

再次通过curl 调用可以在arthas里面查看到具体的异常信息。

把获取到的结果展开，可以用-x参数：

watch com.example.demo.arthas.user.UserController * '{params, throwExp}' -x 2

返回值表达式

在上面的例子里，第三个参数是返回值表达式，它实际上是一个ognl表达式，它支持一些内置对象：

• loader
• clazz
• method
• target
• params
• returnObj
• throwExp
• isBefore
• isThrow
• isReturn

比如返回一个数组：

watch com.example.demo.arthas.user.UserController * '{params[0], target, returnObj}' 

条件表达式

watch命令支持在第4个参数里写条件表达式，比如： 当访问 user/1 时，watch命令没有输出 当访问 user/101 时，watch会打印出结果。

当异常时捕获

watch命令支持-e选项，表示只捕获抛出异常时的请求：

watch com.example.demo.arthas.user.UserController * "{params[0],throwExp}" -e

按照耗时进行过滤

watch命令支持按请求耗时进行过滤，比如：

watch com.example.demo.arthas.user.UserController * '{params, returnObj}' '#cost>200' 

热更新代码

shell@Alicloud:~$ curl http://localhost:61000/user/0 {"timestamp":165****218020,"status":500,"error":"Internal Server Error","exception":"java.lang.IllegalArgumentException","message":"id < 1","path":"/user/0"}

通过热更新代码，修改这个逻辑。

jad反编译UserController

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

jad反编译的结果保存在 /tmp/UserController.java文件里了。 再打开一个Terminal 窗口，然后用vim来编辑/tmp/UserController.java：

vim /tmp/UserController.java

比如当 user id 小于1时，也正常返回，不抛出异常：

@GetMapping(value={"/user/{id}"})
public User findUserById(@PathVariable Integer id) {
    logger.info("id: {}", (Object)id); if (id != null && id < 1) { return new User(id, "name" + id); // throw new IllegalArgumentException("id < 1"); } return new User(id.intValue(), "name" + id);
    }

sc查找加载UserController的ClassLoader

[arthas@1266]$ sc -d *UserController | grep classLoaderHash
 classLoaderHash   19469ea2 

classLoaderHash 是19469ea2，后面需要使用它。

mc

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

mc --classLoaderClass org.springframework.boot.loader.LaunchedURLClassLoader /tmp/UserController.java -d /tmp

[arthas@1266]$ 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 2879 ms.

也可以通过mc -c /tmp/UserController.java -d /tmp，使用-c参数指定ClassLoaderHash:

mc -c 19469ea2 /tmp/UserController.java -d /tmp

redefine

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

[arthas@1266]$ redefine /tmp/com/example/demo/arthas/user/UserController.class redefine success, size: 1, classes: com.example.demo.arthas.user.UserController

热修改代码结果

redefine成功之后，再次访问 user/0 ，结果正常

shell@Alicloud:~$ curl http://localhost:61000/user/0 {"id":0,"name":"name0"}

动态更新应用Logger Level

查找UserController的ClassLoader

[arthas@1266]$ sc -d *UserController | grep classLoaderHash
 classLoaderHash   19469ea2 

用ognl获取logger

ognl --classLoaderClass org.springframework.boot.loader.LaunchedURLClassLoader '@com.example.demo.arthas.user.UserController@logger'

[arthas@1266]$ ognl --classLoaderClass org.springframework.boot.loader.LaunchedURLClassLoader '@com.example.demo.arthas.user.UserController@logger' @Logger[
    serialVersionUID=@Long[5454405123156820674],
    FQCN=@String[ch.qos.logback.classic.Logger],
    name=@String[com.example.demo.arthas.user.UserController],
    level=null,
    effectiveLevelInt=@Integer[20000],
    parent=@Logger[Logger[com.example.demo.arthas.user]],
    childrenList=null,
    aai=null,
    additive=@Boolean[true],
    loggerContext=@LoggerContext[ch.qos.logback.classic.LoggerContext[default]],
]

可以知道UserController@logger实际使用的是logback。可以看到level=null，则说明实际最终的level是从root logger里来的。

单独设置UserController的logger level

ognl --classLoaderClass org.springframework.boot.loader.LaunchedURLClassLoader '@com.example.demo.arthas.user.UserController@logger.setLevel(@ch.qos.logback.classic.Level@DEBUG)' 

再次获取UserController@logger，可以发现已经是DEBUG了。

修改logback的全局logger level

通过获取root logger，可以修改全局的logger level：

ognl --classLoaderClass org.springframework.boot.loader.LaunchedURLClassLoader '@org.slf4j.LoggerFactory@getLogger("root").setLevel(@ch.qos.logback.classic.Level@DEBUG)' 

获取Spring Context,在获取 bean,再调用函数

使用tt命令获取到spring context

tt即 TimeTunnel，它可以记录下指定方法每次调用的入参和返回信息，并能对这些不同的时间下调用进行观测

tt -t org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter invokeHandlerMethod 

访问user/1，

curl http://localhost:61000/user/1 

可以看到tt命令捕获到了一个请求：

输入 q或者 Ctrl + C 退出上面的 tt -t命令。

使用tt命令从调用记录里获取到spring context

tt -i 1000 -w 'target.getApplicationContext()' 

获取spring bean，并调用函数

tt -i 1000 -w 'target.getApplicationContext().getBean("helloWorldService").getHelloMessage()'

结果如下：

[arthas@1266]$ tt -i 1000 -w 'target.getApplicationContext().getBean("helloWorldService").getHelloMessage()' @String[Hello World]
Affect(row-cnt:1) cost in 1 ms.

排查HTTP请求返回401

请求接口没有权限的时候一般就返回401 Unauthorized。 401通常是被权限管理的Filter拦截了，那么到底是哪个Filter处理了这个请求，返回了401？

跟踪所有的Filter函数

开始trace：

trace javax.servlet.Filter *

可以在调用树的最深层，找到AdminFilterConfig$AdminFilter返回了401

+---[3.806273ms] javax.servlet.FilterChain:doFilter()
|   `---[3.447472ms] com.example.demo.arthas.AdminFilterConfig$AdminFilter:doFilter()
|       `---[0.17259ms] javax.servlet.http.HttpServletResponse:sendError()

通过stack获取调用栈

上面是通过trace命令来获取信息，从结果里，我们可以知道通过stack跟踪HttpServletResponse:sendError()，同样可以知道是哪个Filter返回了401 执行：

stack javax.servlet.http.HttpServletResponse sendError 'params[0]==401' 

访问可以看到如下堆栈信息：

查找Top N线程

查看所有线程信息

thread

查看具体线程的栈

查看线程ID 2的栈：

thread 2

查看CPU使用率top n线程的栈

thread -n 3

查看5秒内的CPU使用率top n线程栈

thread -n 3 -i 5000

查找线程是否有阻塞

thread -b