背景

工作中,部门内的同事常常会遇到需要定位线上问题的情况。如果能够根据日志直接定位出问题的根因是最理想的情况,但日志往往差的总是最关键的那一点内容,仅靠日志很难定位到每一个问题。 这里给大家介绍一款阿里出品的开源诊断工具Arthas,并结合项目实际使用情况介绍其中的几个常用使用场景与解决方案:

  • 在运行的jvm程序中动态添加日志打印信息
  • 动态查询jvm程序中的某个值
  • 追踪程序中耗时较长的方法

Arthas的安装与使用

可参考Arthas官方使用文档:Arthas中文文档

解压后直接执行java -jar arthas-boot.jar即可。进入arthas的命令行交互界面后,Arthas将展示目前机器上所运行的jvm程序,通过1234进行选择,Arthas将attach到目标进程上。此后才能执行Arthas后续的各项指令。

arthasTest

在运行的jvm程序中动态添加日志打印信息

此功能实现的原理是Arthas可通过JDK中的Instrumentation#redefineClasses方法直接替换JVM中的某个类,实现动态修改JVM中类的功能。此功能不仅可以添加日志打印信息,还可以改变类中的运行逻辑!这里仅展示修改打印日志信息的相关方法。整个过程主要分为以下几步:

  1. 找到目标类的Classloader
  2. 修改目标类的java文件
  3. 编译目标类
  4. redine目标类,替换jvm中的原有类

找到目标类的Classloader

Java程序在运行的过程中通常会有多个Classloader,程序中的类将被分散加入到各个Classloader中,在redefine时必须要指明覆盖哪一个Classloader中的Class. 因此,我们第一步需要找到目标类是由哪个Classloader所加载。这里以ArthasTest类为例,所属包名为:com.sdww.downloaddemo.controller。在Arthas中执行sc命令:

sc -d com.sdww.downloaddemo.controller.ArthasTest

Arthas会返回该类的所有信息,如下图所示。请将最后一行所显示的classLoaderHash值记录下来,它标志着ArthasTest类由哪个Classloader所加载,在redefine时需要指定该参数。

arthasTest

修改目标类的java源文件

修改java源文件通常有两种方式:

  1. 从正在运行的java程序中dump下来目标类的java源代码进行修改。推荐采用这种方式,因为各个局点所使用的版本比较难追溯,难以定位其对应的java文件。
  2. 从版本库中找到对应版本的java源文件进行修改。

com.sdww.downloaddemo.controller.ArthasTest为例,使用jad dump其java文件的命令如下:

jad --source-only com.sdww.downloaddemo.controller.ArthasTest > /home/sdww/test/ArthasTest.java

使用方式与bash命令差距不大,重定向符号后面的地址需根据实际情况进行修改。

这里在其两个方法中都添加一个log,用于增加日志打印信息,如下所示:

    @GetMapping(value={"/greeting"})
    public String demo() {
        log.info("add log to method demo"); //后续添加
        return "hello world";
    }

编译目标类java源文件

与修改类似,编译也有两种选择:本地编译或在服务器上编译。本地使用maven/ide/java命令编译与构建工程差距不大,这里就不介绍了,主要讲一下在服务器上在线编译。 对于服务器上的java文件,如果采用java命令编译通常会出错:编译器将找不到java文件所import的包和类。这是因为缺乏了编译单个java文件的环境,利用arthas可利用正在运行的jvm环境直接编译java文件。命令如下:

mc -c 20ad9418 -d /home/sdww/target /home/sdww/test/ArthasTest.java

其中-c参数为类的classloader的hash值;-d为class文件输出目录

redine目标类,替换jvm中的原有类

在Arthas中使用redefine命令替换jvm中的原有类:

redefine -c 20ad9418 /home/sdww/target/com/sdww/downloaddemo/controller/ArthasTest.class

redefine方法的限制:

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

替换后,通过浏览器调用demo()方法,可以看到日志已被添加:

arthas-add-log-result

经过AOP切面化的类也可如此操作

动态查询java程序中的某个值

以ArthasTest为例,其中有两个变量

public static int INVOKE_COUNT = 0;
public List<Object> collection = new LinkedList<>();

使用watch命令结合ognl表达式可动态修改对应的类,当某个实例的指定方法被调用时,arthas将打印出watch的值

# 打印静态变量
watch com.sdww.downloaddemo.controller.ArthasTest count '@com.sdww.downloaddemo.controller.ArthasTest@INVOKE_COUNT'
# 打印普通变量
watch com.sdww.downloaddemo.controller.ArthasTest count 'target.collection'

调用ArthasTest.count()方法,打印结果分别如下:

静态变量:

arthas-watch-static

普通变量:

arthas-watch-inner

Tips:每一次方法调用都打印两次的原因是我使用CGLIB这个类进行了AOP增强,因此com.sdww.downloaddemo.controller.ArthasTest将匹配两个类,两个实例

说明:

  1. watch [触发类名] [触发方法名] [express]。其中express中的target指的是调用时的目标对象。
  2. 更多的express写法请参考ognl

追踪程序中耗时较长的方法

在实际工作中,我们通常会遇到需要定位某个操作执行特别慢的情况。例如,agent发送某个报文后broker经过了数秒才返回。在这样的情况下,首先应找到整个过程中的入口,例如springboot项目中的controller方法,然后利用arthas的trace方法进行链路整体跟踪。

如下,traceTest中分别调用了service中的method1与method2.其中method1将sleep线程1s后返回,method2将sleep线程2s后返回.

    @GetMapping("/trace")
    public String traceTest() {
        service.method1();
        service.method2();
        return "OK";
    }

在arthas中执行trace命令:

# trace [target-class] [target-method]
trace com.sdww.downloaddemo.controller.ArthasTest traceTest

然后调用该方法,可以看到arthas将整个方法的执行时间以及整个调用链上每一个方法的执行时间都进行了打印

arthas-trace-result