引言

在我们对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最终目标进程之前，先想好到底使用那种模式来启动引擎。

使用示例

拦截一个普通方法

control方法

1. @GetMapping(value = "/arg1")

2.    public String arg1(@RequestParam("name") String name) throws InterruptedException {

3.        Thread.sleep(2000);

4.        return "7DGroup," + name;

5.    }

BTrace脚本

1. /**

2. * 拦截示例

3. */

4. @BTrace

5. public class PrintArgSimple {

7.    @OnMethod(

8.            //类名

9.            clazz = "com.techstar.monitordemo.controller.UserController",

10.            //方法名

11.            method = "arg1",

12.            //拦截时刻：入口

13.            location = @Location(Kind.ENTRY))

15.    /**

16.     * 拦截类名和方法名

17.     */ public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, AnyType[] args) {

18.        BTraceUtils.printArray(args);

19.        BTraceUtils.println(pcn + "," + pmn);

20.        BTraceUtils.println();

21.    }

22. }

拦截结果：

1. 192:Btrace apple$ jps -l

2. 369

3. 5889 /Users/apple/Downloads/performance/apache-jmeter-4.0/bin/ApacheJMeter.jar

4. 25922 sun.tools.jps.Jps

5. 23011 org.jetbrains.idea.maven.server.RemoteMavenServer

6. 25914 org.jetbrains.jps.cmdline.Launcher

7. 25915 com.techstar.monitordemo.MonitordemoApplication

8. 192:Btrace apple$ btrace 25915 PrintArgSimple.java

9. [zuozewei, ]

10. com.techstar.monitordemo.controller.UserController,arg1

12. [zee, ]

13. com.techstar.monitordemo.controller.UserController,arg1

拦截构造函数

构造函数

1. @Data

2. public class User {

4.    private int id;

5.    private String name;

7. }

control方法

1. @GetMapping(value = "/arg2")

2.    public User arg2(User user) {

3.        return user;

4.    }

BTrace脚本

1. /**

2. * 拦截构造函数

3. */

4. @BTrace

5. public class PrintConstructor {

7.    @OnMethod(clazz = "com.techstar.monitordemo.domain.User", method = "<init>")

8.    public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, AnyType[] args) {

9.        BTraceUtils.println(pcn + "," + pmn);

10.        BTraceUtils.printArray(args);

11.        BTraceUtils.println();

12.    }

13. }

拦截结果

1. 192:Btrace apple$ btrace 34119 PrintConstructor.java

2. com.techstar.monitordemo.domain.User,<init>

3. [1, zuozewei, ]

拦截同名函数，以参数区分

control方法

1. @GetMapping(value = "/same1")

2.    public String same(@RequestParam("name") String name) {

3.        return "7DGroup," + name;

4.    }

6.    @GetMapping(value = "/same2")

7.    public String same(@RequestParam("id") int id, @RequestParam("name") String name) {

8.        return "7DGroup," + name + "," + id;

9.    }

BTrace脚本

1. /**

2. * 拦截同名函数，通过输入的参数区分

3. */

5. @BTrace

6. public class PrintSame {

8.    @OnMethod(clazz = "com.techstar.monitordemo.controller.UserController", method = "same")

9.    public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, String name) {

10.        BTraceUtils.println(pcn + "," + pmn + "," + name);

11.        BTraceUtils.println();

12.    }

13. }

拦截结果

1. 192:Btrace apple$ jps -l

2. 369

3. 5889 /Users/apple/Downloads/performance/apache-jmeter-4.0/bin/ApacheJMeter.jar

4. 34281 sun.tools.jps.Jps

5. 34220 org.jetbrains.jps.cmdline.Launcher

6. 34221 com.techstar.monitordemo.MonitordemoApplication

7. 192:Btrace apple$ btrace 34221 PrintSame.java

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

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

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

拦截方法返回值

BTrace脚本

1. /**

2. * 拦截返回值

3. */

4. @BTrace

5. public class PrintReturn {

7.    @OnMethod(clazz = "com.techstar.monitordemo.controller.UserController", method = "arg1",

8.            //拦截时刻：返回值

9.            location = @Location(Kind.RETURN))

10.    public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, @Return AnyType result) {

11.        BTraceUtils.println(pcn + "," + pmn + "," + result);

12.        BTraceUtils.println();

13.    }

14. }

拦截结果

1. 192:Btrace apple$ jps -l

2. 34528 org.jetbrains.jps.cmdline.Launcher

3. 34529 com.techstar.monitordemo.MonitordemoApplication

4. 369

5. 5889 /Users/apple/Downloads/performance/apache-jmeter-4.0/bin/ApacheJMeter.jar

6. 34533 sun.tools.jps.Jps

7. 192:Btrace apple$ btrace 34529 PrintReturn.java

8. com.techstar.monitordemo.controller.UserController,arg1,7DGroup,zuozewei

异常分析

有时候开发人员对异常处理不合理，导致某些重要异常人为被吃掉，并且没有日志或者日志不详细，导致性能分析定位问题困难，我们可以使用BTrace来处理

control方法

1. @GetMapping(value = "/exception")

2.    public String exception() {

3.        try {

4.            System.out.println("start...");

5.            System.out.println(1 / 0); //模拟异常

6.            System.out.println("end...");

7.        } catch (Exception e) {}

8.        return "successful...";

9.    }

BTrace脚本

1. /**

2. * 有时候，有些异常被人为吃掉，日志又没有打印，这个时候可以用该类定位问题

3. * This example demonstrates printing stack trace

4. * of an exception and thread local variables. This

5. * trace script prints exception stack trace whenever

6. * java.lang.Throwable's constructor returns. This way

7. * you can trace all exceptions that may be caught and

8. * "eaten" silently by the traced program. Note that the

9. * assumption is that the exceptions are thrown soon after

10. * creation [like in "throw new FooException();"] rather

11. * that be stored and thrown later.

12. */

13. @BTrace

14. public class PrintOnThrow {

15.    // store current exception in a thread local

16.    // variable (@TLS annotation). Note that we can't

17.    // store it in a global variable!

18.    @TLS

19.    static Throwable currentException;

21.    // introduce probe into every constructor of java.lang.Throwable

22.    // class and store "this" in the thread local variable.

23.    @OnMethod(clazz = "java.lang.Throwable", method = "<init>")

24.    public static void onthrow(@Self Throwable self) {

25.        currentException = self;

26.    }

28.    @OnMethod(clazz = "java.lang.Throwable", method = "<init>")

29.    public static void onthrow1(@Self Throwable self, String s) {

30.        currentException = self;

31.    }

33.    @OnMethod(clazz = "java.lang.Throwable", method = "<init>")

34.    public static void onthrow1(@Self Throwable self, String s, Throwable cause) {

35.        currentException = self;

36.    }

38.    @OnMethod(clazz = "java.lang.Throwable", method = "<init>")

39.    public static void onthrow2(@Self Throwable self, Throwable cause) {

40.        currentException = self;

41.    }

43.    // when any constructor of java.lang.Throwable returns

44.    // print the currentException's stack trace.

45.    @OnMethod(clazz = "java.lang.Throwable", method = "<init>", location = @Location(Kind.RETURN))

46.    public static void onthrowreturn() {

47.        if (currentException != null) {

48.            Threads.jstack(currentException);

49.            BTraceUtils.println("=====================");

50.            currentException = null;

51.        }

52.    }

53. }

拦截结果

1. 192:Btrace apple$ jps -l

2. 369

3. 5889 /Users/apple/Downloads/performance/apache-jmeter-4.0/bin/ApacheJMeter.jar

4. 34727 sun.tools.jps.Jps

5. 34666 org.jetbrains.jps.cmdline.Launcher

6. 34667 com.techstar.monitordemo.MonitordemoApplication

7. 192:Btrace apple$ btrace 34667 PrintOnThrow.java

8. java.lang.ClassNotFoundException: org.apache.catalina.webresources.WarResourceSet

9.    java.net.URLClassLoader.findClass(URLClassLoader.java:381)

10.    java.lang.ClassLoader.loadClass(ClassLoader.java:424)

11.    java.lang.ClassLoader.loadClass(ClassLoader.java:411)

12.    sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:349)

13.    java.lang.ClassLoader.loadClass(ClassLoader.java:357)

14.    org.apache.catalina.webresources.StandardRoot.isPackedWarFile(StandardRoot.java:656)

15.    org.apache.catalina.webresources.CachedResource.validateResource(CachedResource.java:109)

16.    org.apache.catalina.webresources.Cache.getResource(Cache.java:69)

17.    org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:216)

18.    org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:206)

19.    org.apache.catalina.mapper.Mapper.internalMapWrapper(Mapper.java:1027)

20.    org.apache.catalina.mapper.Mapper.internalMap(Mapper.java:842)

21.    org.apache.catalina.mapper.Mapper.map(Mapper.java:698)

22.    org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:679)

23.    org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:336)

24.    org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:800)

25.    org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)

26.    org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:800)

27.    org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1471)

28.    org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)

29.    java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

30.    java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

31.    org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)

32.    java.lang.Thread.run(Thread.java:748)

33. =====================

34. ...

定位某个超过阈值的函数

BTrace脚本

1. **

2. * 探测某个包路径下的方法执行时间是否超过某个阈值的程序，如果超过了该阀值，则打印当前线程的栈信息。

3. */

5. import com.sun.btrace.BTraceUtils;

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

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

10. @BTrace

11. public class PrintDurationTracer {

12.    @OnMethod(clazz = "/com\\.techstar\\.monitordemo\\..*/", method = "/.*/", location = @Location(Kind.RETURN))

13.    public static void trace(@ProbeClassName String pcn, @ProbeMethodName String pmn, @Duration long duration) {

14.        //duration的单位是纳秒

15.        if (duration > 1000 * 1000 * 2) {

16.            BTraceUtils.println(Strings.strcat(Strings.strcat(pcn, "."), pmn));

17.            BTraceUtils.print(" 耗时:");

18.            BTraceUtils.print(duration);

19.            BTraceUtils.println("纳秒,堆栈信息如下");

20.            jstack();

21.        }

22.    }

23. }

拦截结果

1. 192:Btrace apple$ btrace 39644 PrintDurationTracer.java

2. com.techstar.monitordemo.controller.Adder.execute 耗时:1715294657纳秒,堆栈信息如下

3. com.techstar.monitordemo.controller.Adder.execute(Adder.java:13)

4. com.techstar.monitordemo.controller.Main.main(Main.java:10)

5. com.techstar.monitordemo.controller.Adder.execute 耗时:893795666纳秒,堆栈信息如下

6. com.techstar.monitordemo.controller.Adder.execute(Adder.java:13)

7. com.techstar.monitordemo.controller.Main.main(Main.java:10)

8. com.techstar.monitordemo.controller.Adder.execute 耗时:1331363658纳秒,堆栈信息如下

9. com.techstar.monitordemo.controller.Adder.execute(Adder.java:13)

追踪方法执行时间

BTrace脚本

1. /**

2. * 追踪某个方法的执行时间，实现原理同AOP一样。

3. */

4. @BTrace

5. public class PrintExecuteTimeTracer {

6.    @TLS

7.    static long beginTime;

9.    @OnMethod(clazz = "com.techstar.monitordemo.controller.Adder", method = "execute")

10.    public static void traceExecuteBegin() {

11.        beginTime = timeMillis();

12.    }

14.    @OnMethod(clazz = "com.techstar.monitordemo.controller.Adder", method = "execute", location = @Location(Kind.RETURN))

15.    public static void traceExecute(int arg1, int arg2, @Return int result) {

16.        BTraceUtils.println(strcat(strcat("Adder.execute 耗时:", str(timeMillis() - beginTime)), "ms"));

17.        BTraceUtils.println(strcat("返回结果为:", str(result)));

18.    }

19. }

拦截结果

1. 192:Btrace apple$ btrace 40863 PrintExecuteTimeTracer.java

2. Adder.execute 耗时:803ms

3. 返回结果为:797

4. Adder.execute 耗时:1266ms

5. 返回结果为:1261

6. Adder.execute 耗时:788ms

7. 返回结果为:784

8. Adder.execute 耗时:1524ms

9. 返回结果为:1521

10. Adder.execute 耗时:1775ms

性能分析

压测的时候经常发现某一个服务变慢了，但是由于这个服务有很多的业务逻辑和方法构成，这个时候就不好定位到底慢在哪个地方。BTrace可以解决这个问题，只需要大概定位问题可能存在的地方，通过包路径模糊匹配，就可以找到问题。

BTrace脚本

1. /**

2. *

3. * Description:

4. * This script demonstrates new capabilities built into BTrace 1.2

5. * Shortened syntax - when omitting "public" identifier in the class

6. * definition one can safely omit all other modifiers when declaring methods

7. * and variables

8. * Extended syntax for @ProbeMethodName annotation - you can use

9. * parameter to request a fully qualified method name instead of

10. * the short one

11. * Profiling support - you can use {@linkplain Profiler} instance to gather

12. * performance data with the smallest overhead possible

13. */

14. @BTrace

15. class Profiling {

16.    @Property

17.    Profiler profiler = BTraceUtils.Profiling.newProfiler();

19.    @OnMethod(clazz = "/com\\.techstar\\..*/", method = "/.*/")

20.    void entry(@ProbeMethodName(fqn = true) String probeMethod) {

21.        BTraceUtils.Profiling.recordEntry(profiler, probeMethod);

22.    }

24.    @OnMethod(clazz = "/com\\.techstar\\..*/", method = "/.*/", location = @Location(value = Kind.RETURN))

25.    void exit(@ProbeMethodName(fqn = true) String probeMethod, @Duration long duration) {

26.        BTraceUtils.Profiling.recordExit(profiler, probeMethod, duration);

27.    }

29.    @OnTimer(5000)

30.    void timer() {

31.        BTraceUtils.Profiling.printSnapshot("Performance profile", profiler);

32.    }

死锁排查

我们怀疑程序是否有死锁，可以通过以下的脚本扫描追踪，非常简单方便。

1. /**

2. * This BTrace program demonstrates deadlocks

3. * built-in function. This example prints

4. * deadlocks (if any) once every 4 seconds.

5. */

6. @BTrace

7. public class PrintDeadlock {

8.    @OnTimer(4000)

9.    public static void print() {

10.        deadlocks();

11.    }

12. }

小结

BTrace是一个事后工具，所谓的事后工具就是在服务已经上线或者压测后，但是发现有问题的时候，可以使用BTrace动态跟踪分析。

1. 比如哪些方法执行太慢，例如监控方法执行时间超过1秒的方法；

2. 查看哪些方法调用了system.gc( )，调用栈是怎样的；

3. 查看方法的参数和属性

4. 哪些方法发生了异常

5. .....

总之，这里只是将部分经常用的列举了下抛砖引玉，还有很多没有列举，大家可以参考官方的其他Sample去玩下。