利用神器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）