效能工具之Java分析工具BTrace入門

語言: CN / TW / HK

小知識,大挑戰!本文正在參與“程式設計師必備小知識”創作活動。

本文已參與 「掘力星計劃」 ,贏取創作大禮包,挑戰創作激勵金。


一、引言

在我們對Java應用做效能分析的時候,往往採用log進行問題定位和分析,但是如果我們的log缺乏相關的資訊呢?遠端除錯會影響應用的正常工作,修改程式碼重新部署應用,實時性和靈活性難以保證,有沒有不影響正常應用執行,又靈活並無侵入性的方法呢?

答案是有,它就是Java中的神器-BTrace

二、BTrace是什麼?

BTrace使用Java的Attach技術,可以讓我們無縫的將我們BTrace指令碼掛到JVM上,通過指令碼你可以獲取到任何你想拿到的資料,在侵入性和安全性都非常可靠,特別是定位線上問題的神器。

三、BTrace原理

BTrace是基於動態位元組碼修改技術(Hotswap)向目標程式的位元組碼注入追蹤程式碼。

四、安裝配置

關於BTrace的安裝配置使用,此處就不再重複造輪子,網上有太多的教程。

官網地址:https://github.com/btraceio/btrace

五、注意事項

生產環境可以使用,但修改的位元組碼不會被還原,使用Btrace時,需要確保追蹤的動作是隻讀的(即:追蹤行為不能修改目標程式的狀態)和有限的行為(即:追蹤行為需要在有限的時間內終止),一個追蹤行為需要滿足以下的限制:

  • 不能建立新的物件 不能建立新的陣列
  • 不能丟擲異常
  • 不能捕獲異常
  • 不能對例項或靜態方法呼叫-只有從BTraceUtils中的public static方法中或在當前指令碼中宣告的方法,可以被BTrace呼叫
  • 不能有外部,內部,巢狀或本地類
  • 不能有同步塊或同步方法
  • 不能有迴圈(for,while,do..while)
  • 不能繼承抽象類(父類必須是java.lang.Object)
  • 不能實現介面
  • 不能有斷言語句
  • 不能有class保留字

以上的限制可以通過通過unsafe模式繞過。追蹤指令碼和引擎都必須設定為unsafe模式。指令碼需要使用註解為@BTrace(unsafe = true),需要修改BTrace安裝目錄下bin中btrace指令碼將-Dcom.sun.btrace.unsafe=false改為-Dcom.sun.btrace.unsafe=true

注:關於unsafe的使用,如果你的程式一旦被btrace追蹤過,那麼unsafe的設定會一直伴隨該程序的整個生命週期。如果你修改了unsafe的設定,只有通過重啟目標程序,才能獲得想要的結果。所以該用法不是很好使用,如果你的應用不能隨便重啟,那麼你在第一次使用btrace最終目標程序之前,先想好到底使用那種模式來啟動引擎。

六、使用示例

1、攔截一個普通方法

control方法 JAVA @GetMapping(value = "/arg1") public String arg1(@RequestParam("name") String name) throws InterruptedException { Thread.sleep(2000); return "7DGroup," + name; } BTrace指令碼 ```java /* * 攔截示例 / @BTrace public class PrintArgSimple {

@OnMethod(
        //類名
        clazz = "com.techstar.monitordemo.controller.UserController",
        //方法名
        method = "arg1",
        //攔截時刻:入口
        location = @Location(Kind.ENTRY))

/**
 * 攔截類名和方法名
 */ public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, AnyType[] args) {
    BTraceUtils.printArray(args);
    BTraceUtils.println(pcn + "," + pmn);
    BTraceUtils.println();
}

} 攔截結果:bash 192:Btrace apple$ jps -l 369 5889 /Users/apple/Downloads/performance/apache-jmeter-4.0/bin/ApacheJMeter.jar 25922 sun.tools.jps.Jps 23011 org.jetbrains.idea.maven.server.RemoteMavenServer 25914 org.jetbrains.jps.cmdline.Launcher 25915 com.techstar.monitordemo.MonitordemoApplication 192:Btrace apple$ btrace 25915 PrintArgSimple.java [zuozewei, ] com.techstar.monitordemo.controller.UserController,arg1

[zee, ] com.techstar.monitordemo.controller.UserController,arg1 ```

2、攔截建構函式

建構函式 ```java @Data public class User {

private int id;
private String name;

} control方法java @GetMapping(value = "/arg2") public User arg2(User user) { return user; } BTrace指令碼java /* * 攔截建構函式 / @BTrace public class PrintConstructor {

@OnMethod(clazz = "com.techstar.monitordemo.domain.User", method = "<init>")
public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, AnyType[] args) {
    BTraceUtils.println(pcn + "," + pmn);
    BTraceUtils.printArray(args);
    BTraceUtils.println();
}

} 攔截結果bash 192:Btrace apple$ btrace 34119 PrintConstructor.java com.techstar.monitordemo.domain.User, [1, zuozewei, ] ```

3、攔截同名函式,以引數區分

control方法 ```java @GetMapping(value = "/same1") public String same(@RequestParam("name") String name) { return "7DGroup," + name; }

@GetMapping(value = "/same2")
public String same(@RequestParam("id") int id, @RequestParam("name") String name) {
    return "7DGroup," + name + "," + id;
}

BTrace指令碼java /* * 攔截同名函式,通過輸入的引數區分 /

@BTrace public class PrintSame {

@OnMethod(clazz = "com.techstar.monitordemo.controller.UserController", method = "same")
public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, String name) {
    BTraceUtils.println(pcn + "," + pmn + "," + name);
    BTraceUtils.println();
}

} 攔截結果bash 192:Btrace apple$ jps -l 369 5889 /Users/apple/Downloads/performance/apache-jmeter-4.0/bin/ApacheJMeter.jar 34281 sun.tools.jps.Jps 34220 org.jetbrains.jps.cmdline.Launcher 34221 com.techstar.monitordemo.MonitordemoApplication 192:Btrace apple$ btrace 34221 PrintSame.java com.techstar.monitordemo.controller.UserController,same,zuozewei

com.techstar.monitordemo.controller.UserController,same,zuozewei

com.techstar.monitordemo.controller.UserController,same,zuozewei ```

4、攔截方法返回值

BTrace指令碼 ```java /* * 攔截返回值 / @BTrace public class PrintReturn {

@OnMethod(clazz = "com.techstar.monitordemo.controller.UserController", method = "arg1",
        //攔截時刻:返回值
        location = @Location(Kind.RETURN))
public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, @Return AnyType result) {
    BTraceUtils.println(pcn + "," + pmn + "," + result);
    BTraceUtils.println();
}

} 攔截結果bash 192:Btrace apple$ jps -l 34528 org.jetbrains.jps.cmdline.Launcher 34529 com.techstar.monitordemo.MonitordemoApplication 369 5889 /Users/apple/Downloads/performance/apache-jmeter-4.0/bin/ApacheJMeter.jar 34533 sun.tools.jps.Jps 192:Btrace apple$ btrace 34529 PrintReturn.java com.techstar.monitordemo.controller.UserController,arg1,7DGroup,zuozewei ```

5、異常分析

有時候開發人員對異常處理不合理,導致某些重要異常人為被吃掉,並且沒有日誌或者日誌不詳細,導致效能分析定位問題困難,我們可以使用BTrace來處理

control方法 JAVA @GetMapping(value = "/exception") public String exception() { try { System.out.println("start..."); System.out.println(1 / 0); //模擬異常 System.out.println("end..."); } catch (Exception e) {} return "successful..."; } BTrace指令碼 ```java /* * 有時候,有些異常被人為吃掉,日誌又沒有列印,這個時候可以用該類定位問題 * This example demonstrates printing stack trace * of an exception and thread local variables. This * trace script prints exception stack trace whenever * java.lang.Throwable's constructor returns. This way * you can trace all exceptions that may be caught and * "eaten" silently by the traced program. Note that the * assumption is that the exceptions are thrown soon after * creation [like in "throw new FooException();"] rather * that be stored and thrown later. / @BTrace public class PrintOnThrow { // store current exception in a thread local // variable (@TLS annotation). Note that we can't // store it in a global variable! @TLS static Throwable currentException;

// introduce probe into every constructor of java.lang.Throwable
// class and store "this" in the thread local variable.
@OnMethod(clazz = "java.lang.Throwable", method = "<init>")
public static void onthrow(@Self Throwable self) {
    currentException = self;
}

@OnMethod(clazz = "java.lang.Throwable", method = "<init>")
public static void onthrow1(@Self Throwable self, String s) {
    currentException = self;
}

@OnMethod(clazz = "java.lang.Throwable", method = "<init>")
public static void onthrow1(@Self Throwable self, String s, Throwable cause) {
    currentException = self;
}

@OnMethod(clazz = "java.lang.Throwable", method = "<init>")
public static void onthrow2(@Self Throwable self, Throwable cause) {
    currentException = self;
}

// when any constructor of java.lang.Throwable returns
// print the currentException's stack trace.
@OnMethod(clazz = "java.lang.Throwable", method = "<init>", location = @Location(Kind.RETURN))
public static void onthrowreturn() {
    if (currentException != null) {
        Threads.jstack(currentException);
        BTraceUtils.println("=====================");
        currentException = null;
    }
}

} 攔截結果bash 192:Btrace apple$ jps -l 369 5889 /Users/apple/Downloads/performance/apache-jmeter-4.0/bin/ApacheJMeter.jar 34727 sun.tools.jps.Jps 34666 org.jetbrains.jps.cmdline.Launcher 34667 com.techstar.monitordemo.MonitordemoApplication 192:Btrace apple$ btrace 34667 PrintOnThrow.java java.lang.ClassNotFoundException: org.apache.catalina.webresources.WarResourceSet java.net.URLClassLoader.findClass(URLClassLoader.java:381) java.lang.ClassLoader.loadClass(ClassLoader.java:424) java.lang.ClassLoader.loadClass(ClassLoader.java:411) sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:349) java.lang.ClassLoader.loadClass(ClassLoader.java:357) org.apache.catalina.webresources.StandardRoot.isPackedWarFile(StandardRoot.java:656) org.apache.catalina.webresources.CachedResource.validateResource(CachedResource.java:109) org.apache.catalina.webresources.Cache.getResource(Cache.java:69) org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:216) org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:206) org.apache.catalina.mapper.Mapper.internalMapWrapper(Mapper.java:1027) org.apache.catalina.mapper.Mapper.internalMap(Mapper.java:842) org.apache.catalina.mapper.Mapper.map(Mapper.java:698) org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:679) org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:336) org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:800) org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:800) org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1471) org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) java.lang.Thread.run(Thread.java:748) ===================== ... ```

6、定位某個超過閾值的函式

BTrace指令碼 ```java * * 探測某個包路徑下的方法執行時間是否超過某個閾值的程式,如果超過了該閥值,則列印當前執行緒的棧資訊。 /

import com.sun.btrace.BTraceUtils; import com.sun.btrace.annotations.*;

import static com.sun.btrace.BTraceUtils.*;

@BTrace public class PrintDurationTracer { @OnMethod(clazz = "/com\.techstar\.monitordemo\../", method = "/./", location = @Location(Kind.RETURN)) public static void trace(@ProbeClassName String pcn, @ProbeMethodName String pmn, @Duration long duration) { //duration的單位是納秒 if (duration > 1000 * 1000 * 2) { BTraceUtils.println(Strings.strcat(Strings.strcat(pcn, "."), pmn)); BTraceUtils.print(" 耗時:"); BTraceUtils.print(duration); BTraceUtils.println("納秒,堆疊資訊如下"); jstack(); } } } ```

攔截結果 ```bash 192:Btrace apple$ btrace 39644 PrintDurationTracer.java com.techstar.monitordemo.controller.Adder.execute 耗時:1715294657納秒,堆疊資訊如下 com.techstar.monitordemo.controller.Adder.execute(Adder.java:13) com.techstar.monitordemo.controller.Main.main(Main.java:10) com.techstar.monitordemo.controller.Adder.execute 耗時:893795666納秒,堆疊資訊如下 com.techstar.monitordemo.controller.Adder.execute(Adder.java:13) com.techstar.monitordemo.controller.Main.main(Main.java:10) com.techstar.monitordemo.controller.Adder.execute 耗時:1331363658納秒,堆疊資訊如下 com.techstar.monitordemo.controller.Adder.execute(Adder.java:13)

```

7、追蹤方法執行時間

BTrace指令碼 ```java /* * 追蹤某個方法的執行時間,實現原理同AOP一樣。 / @BTrace public class PrintExecuteTimeTracer { @TLS static long beginTime;

@OnMethod(clazz = "com.techstar.monitordemo.controller.Adder", method = "execute")
public static void traceExecuteBegin() {
    beginTime = timeMillis();
}

@OnMethod(clazz = "com.techstar.monitordemo.controller.Adder", method = "execute", location = @Location(Kind.RETURN))
public static void traceExecute(int arg1, int arg2, @Return int result) {
    BTraceUtils.println(strcat(strcat("Adder.execute 耗時:", str(timeMillis() - beginTime)), "ms"));
    BTraceUtils.println(strcat("返回結果為:", str(result)));
}

}

攔截結果bash 192:Btrace apple$ btrace 40863 PrintExecuteTimeTracer.java Adder.execute 耗時:803ms 返回結果為:797 Adder.execute 耗時:1266ms 返回結果為:1261 Adder.execute 耗時:788ms 返回結果為:784 Adder.execute 耗時:1524ms 返回結果為:1521 Adder.execute 耗時:1775ms ```

8、效能分析

壓測的時候經常發現某一個服務變慢了,但是由於這個服務有很多的業務邏輯和方法構成,這個時候就不好定位到底慢在哪個地方。BTrace可以解決這個問題,只需要大概定位問題可能存在的地方,通過包路徑模糊匹配,就可以找到問題。

BTrace指令碼 ```java /* * * Description: * This script demonstrates new capabilities built into BTrace 1.2 * Shortened syntax - when omitting "public" identifier in the class * definition one can safely omit all other modifiers when declaring methods * and variables * Extended syntax for @ProbeMethodName annotation - you can use * parameter to request a fully qualified method name instead of * the short one * Profiling support - you can use {@linkplain Profiler} instance to gather * performance data with the smallest overhead possible / @BTrace class Profiling { @Property Profiler profiler = BTraceUtils.Profiling.newProfiler();

@OnMethod(clazz = "/com\\.techstar\\..*/", method = "/.*/")
void entry(@ProbeMethodName(fqn = true) String probeMethod) {
    BTraceUtils.Profiling.recordEntry(profiler, probeMethod);
}

@OnMethod(clazz = "/com\\.techstar\\..*/", method = "/.*/", location = @Location(value = Kind.RETURN))
void exit(@ProbeMethodName(fqn = true) String probeMethod, @Duration long duration) {
    BTraceUtils.Profiling.recordExit(profiler, probeMethod, duration);
}

@OnTimer(5000)
void timer() {
    BTraceUtils.Profiling.printSnapshot("Performance profile", profiler);
}

```

9、死鎖排查

我們懷疑程式是否有死鎖,可以通過以下的腳步掃描追蹤,非常簡單方便。

```java /* * This BTrace program demonstrates deadlocks * built-in function. This example prints * deadlocks (if any) once every 4 seconds. / @BTrace public class PrintDeadlock { @OnTimer(4000) public static void print() { deadlocks(); } }

```

七、小結

BTrace是一個事後工具,所謂的事後工具就是在服務已經上線或者壓測後,但是發現有問題的時候,可以使用BTrace動態跟蹤分析。 1. 比如哪些方法執行太慢,例如監控方法執行時間超過1秒的方法; 2. 檢視哪些方法呼叫了system.gc(),呼叫棧是怎樣的; 3. 檢視方法的引數和屬性 4. 哪些方法發生了異常 ...

總之,這裡只是將部分經常用的列舉了下拋磚引玉,還有很多沒有列舉,大家可以參考官方的其他Sample去玩下。

本文原始碼: https://github.com/zuozewei/blog-example/tree/master/Performance-testing/03-performance-monitoring/btrace