利用神器BTrace 追踪线上 Spring Boot应用运行时信息

---

概述

生产环境中的服务可能会出现各类问题，但总不能让服务下线来专门排查错误，这时候最好有一些手段来获取程序运行时信息，好比 接口方法参数/返回值、外部调用状况 以及 函数执行时间等信息以便定位问题。传统的日志记录方式的确能够，但有时很是麻烦，甚至可能须要重启服务，所以代价太大，这时能够借助一个牛批的工具：BTrace ！

BTrace 可用于动态跟踪正在运行的 Java程序，其原理是经过动态地检测目标应用程序的类并注入跟踪代码 ( “字节码跟踪” )，所以能够直接用于监控和追踪线上问题而无需修改业务代码并重启应用程序。

BTrace 的使用方式是用户本身编写符合 BTrace使用语法的脚本，并结合btrace命令，来获取应用的一切调用信息，就像下面这样：

<btrace>/bin/btrace <PID> <trace_script>

• 其中 <PID>为被监控 Java应用的 进程ID
• <trace_script> 为 根据须要监控的信息 而自行编写的 Java脚本

本文就来实操一波 BTrace工具的使用，实验环境以下：

• OS：CentOS 7.4 64bit
• BTrace版本：1.3.11.3
• 被追踪的 Java应用：Spring Boot 2.1.1 应用，这里使用个人文章《Spring Boot应用缓存实践之：Ehcache加持》一文中的 Spring Boot工程

注： 本文首发于 My Personal Blog：CodeSheep·程序羊，欢迎光临 小站

---

BTrace 安装部署

• 下载 二进制文件并解压

这里我解压到目录：/home/btrace

• 配置系统环境变量

vim /etc/profile

BTRACE_HOME=/home/btrace
export BTRACE_HOME
export PATH=$PATH:$BTRACE_HOME/bin

• 验证 BTrace安装状况

btrace --version

---

编译 BTrace源码

• 克隆源码

git clone git@github.com:btraceio/btrace.git

• 编译源码

./gradlew build

• 构建完成的生成物路径位于：build/libs目录下

咱们取出构建生成的 jar包供下文使用。

---

利用btrace追踪 Spring Boot应用例析

首先咱们得构造一个 Spring Boot的模拟业务 用于下文被追踪和分析，这里我就使用文章 《Spring Boot应用缓存实践之：Ehcache加持》中的实验工程。

咱们在此工程里再添加一个 scripts包，用于放置 btrace 脚本文件：

因为 btrace脚本中须要用到 btrace相关的组件和函数库，所以咱们还须要在工程的 pom.xml中引入 btrace的依赖，所使用的 jar包就是上文编译生成的 btrace-1.3.11.3.jar

<dependency>
            <groupId>com.sun.btrace</groupId>
            <artifactId>btrace</artifactId>
            <version>1.3.11.3</version>
        </dependency>

Talk is cheap ，Show you the code ！接下来就用四五个实验来讲明一切吧：

---

0x01 监控方法耗时状况

btrace 脚本：

@BTrace
public class BtraceTest2 {

    @OnMethod(clazz = "cn.codesheep.springbt_brace.controller.UserController", method = "getUsersByName", location = @Location(Kind.RETURN))
    public static void getFuncRunTime( @ProbeMethodName String pmn, @Duration long duration) {
        println( "接口 " + pmn + strcat("的执行时间(ms)为: ", str(duration / 1000000)) ); //单位是纳秒，要转为毫秒
    }
}

接下来开始运行 btrace脚原本拦截方法的参数，首先咱们用 jps命令取到须要被监控的 Spring Boot应用的进程 Id为 27887，而后执行：

/home/btrace/bin/btrace 27887 BtraceTest2.java

这里我总共对 /getusersbyname接口发出了 12次 POST请求，状况以下：

接下来咱们再看看利用btrace脚本监控到的 /getuserbyname接口的执行时间：

这样一对比很明显，从数据库取数据仍是须要 花费十几毫秒的，但从缓存读取数据 几乎没有耗时，这就是为何要让缓存加持于应用的缘由！！！

---

0x02 拦截方法的 参数/返回值

btrace 脚本：

@OnMethod(
            clazz = "cn.codesheep.springbt_brace.controller.UserController",
            method = "getUsersByName",
            location = @Location(Kind.ENTRY)
    )
    public static void getFuncEntry(@ProbeClassName String pcn, @ProbeMethodName String pmn, User user ) {

        println("类名: " + pcn);
        println("方法名: " + pmn);

        // 先打印入参实体总体信息
        BTraceUtils.print("入参实体为: ");
        BTraceUtils.printFields(user);

        // 再打印入参实体每一个属性的信息
        Field oneFiled = BTraceUtils.field("cn.codesheep.springbt_brace.entity.User", "userName");
        println("userName字段为: " + BTraceUtils.get(oneFiled, user));

        oneFiled = BTraceUtils.field("cn.codesheep.springbt_brace.entity.User", "userAge");
        println("userAge字段为: " + BTraceUtils.get(oneFiled, user));

    }

接下来开始运行 btrace脚原本拦截方法的参数，首先咱们用 jps命令取到须要被监控的java应用的进程 Id为 27887，而后执行：

/home/btrace/bin/btrace -cp springbt_brace/target/classes 27887 BtraceTest4.java

此时正常带参数 {"userName":"codesheep.cn"} 去请求业务接口：POST /getusersbyname，会获得以下输出：

很明显请求参数已经被 btrace给拦截到了

同理，若是想拦截方法的返回值，可使用以下 btrace脚本：

@OnMethod(
            clazz = "cn.codesheep.springbt_brace.controller.UserController",
            method = "getUsersByName",
            location = @Location(Kind.RETURN)  //函数返回的时候执行，若是不填，则在函数开始的时候执行
    )
    public static void getFuncReturn( @Return List<User> users ) {
        println("返回值为: ");
        println(str(users));
    }

运行 btrace命令后，继续请求想要被监控的业务接口，则能够获得相似以下的输出：

---

0x03 监控代码是否到达了某类的某一行

btrace 脚本以下：

@BTrace
public class BtraceTest3 {

    @OnMethod(
            clazz="cn.codesheep.springbt_brace.service.UserService",
            method="getUsersByName",
            location=@Location(value= Kind.LINE, line=28)  // 好比拦截第28行, 28行是从数据库取数据操做
    )
    public static void lineTest( @ProbeClassName String pcn, @ProbeMethodName String pmn, int line ) {
        BTraceUtils.println("ClassName: " + pcn);
        BTraceUtils.println("MethodName: " + pmn);
        BTraceUtils.println("执行到的line行数: " + line);
    }
}

执行 btrace追踪命令

/home/btrace/bin/btrace 28927 BtraceTest3.java

接着用 POSTMAN工具连续发出了对 /getuserbyname接口的 十几回POST请求，因为只有第一次请求没有缓存时才会从数据库读，所以也才会执行到 UserService类的第 28行 ！

---

0x04 监控指定函数中全部外部调用的耗时状况

btrace脚本以下：

@BTrace
public class BtraceTest5 {

    @OnMethod (clazz = "cn.codesheep.springbt_brace.service.UserService",method = "getUsersByName",
    location=@Location(value= Kind.CALL, clazz="/.*/", method="/.*/", where = Where.AFTER) )
    public static void printMethodRunTime(@Self Object self,@TargetInstance Object instance,@TargetMethodOrField String method, @Duration long duration) {

        if( duration > 5000000 ){  //若是外部调用耗时大于 5ms 则打印出来
            println( "self: " + self );
            println( "instance: " + instance );
            println( method + ",cost:" + duration/1000000 + " ms" );
        }
    }

}

执行监控命令：

/home/btrace/bin/btrace 28927 BtraceTest5.java

而后再对接口 /getuserbyname发出POST请求，观察监控结果以下：

咱们发现最耗时的外部调用来源于 MyBatis调用。

---

0x05 其余追踪与监控

除了上面四种典型的追踪场景以外，其余的 btrace追踪与监控场景还好比 查看谁调用了System.gc()，调用栈如何，则可使用以下 btrace脚本进行监控

@BTrace
public class BtraceTest {
    @OnMethod(clazz = "java.lang.System", method = "gc")
    public static void onSystemGC() {
        println("entered System.gc()");
        jstack();
    }
}

很明显，由于btrace 内置了一系列诸如 jstack等十分有用的监控命令。

固然最后须要说明的是 btrace内置了不少语法和命令，能够应对不少线上 Java应用监控场景，你们能够去研究一下官方文档

---

后记

因为能力有限，如有错误或者不当之处，还请你们批评指正，一块儿学习交流！

• My Personal Blog：CodeSheep 程序羊
• 程序羊的 2018年终总（gen）结（feng）