21

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

 5 years ago
source link: http://www.codesheep.cn/2019/01/17/springbt-btrace/?amp%3Butm_medium=referral
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

可用于追踪线上 Java服务 运行时信息的神器 BTrace，你们经常用吗 ？

NBFJjiU.jpg!web

概述

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

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

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

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

<PID>
<trace_script>

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

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 [email protected]:btraceio/btrace.git
  • 编译源码 
./gradlew build

mQN7raF.png!web

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

f263y2B.png!web

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

利用btrace追踪 Spring Boot应用例析

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

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

FFzYVr6.png!web

由于 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请求，情况如下：

ErEVZb2.png!web

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

zIbiEvN.png!web

这样一对比很明显，从数据库取数据还是需要 花费十几毫秒 的，但从缓存读取数据 几乎没有耗时 ，这就是为什么要让缓存加持于应用的原因！！！

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 ，会得到如下输出：

qArqam2.png!web

很明显请求参数已经被 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命令后，继续请求想要被监控的业务接口，则可以得到类似如下的输出：

ZrM3Efa.png!web

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请求，观察监控结果如下：

bAZF7fF.png!web

我们发现最耗时的外部调用来源于 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应用监控场景，大家可以去研究一下 官方文档


report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK