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

---

---

可 長按 或 掃描 下面的 小心心 來訂閱作者公眾號 CodeSheep，獲取更多 務實、能看懂、可復現的 原創文 ↓↓↓

---