引言
在我们对Java应用做性能分析的时候，往往采用log进行问题定位和分析，但是如果我们的log缺乏相关的信息呢？远程调试会影响应用的正常工作，修改代码重新部署应用，实时性和灵活性难以保证，有没有不影响正常应用运行，又灵活并无侵入性的方法呢？
答案是有，它就是Java中的神器-BTrace
BTrace是什么？
BTrace使用Java的Attach技术，可以让我们无缝的将我们BTrace脚本挂到JVM上，通过脚本你可以获取到任何你想拿到的数据，在侵入性和安全性都非常可靠，特别是定位线上问题的神器。
BTrace原理
BTrace是基于动态字节码修改技术（Hotswap）向目标程序的字节码注入追踪代码。
安装配置
关于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方法
@GetMapping(value = "/arg1")
public String arg1(@RequestParam("name") String name) throws InterruptedException {
Thread.sleep(2000);
return "7DGroup," + name;
}
BTrace脚本
/**
* 拦截示例
*/
@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();
}
}
拦截结果：
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
拦截构造函数
构造函数
@Data
public class User {
private int id;
private String name;
}
control方法
@GetMapping(value = "/arg2")
public User arg2(User user) {
return user;
}
BTrace脚本
/**
* 拦截构造函数
*/
@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();
}
}
拦截结果
192:Btrace apple$ btrace 34119 PrintConstructor.java
com.techstar.monitordemo.domain.User,<init>
[1, zuozewei, ]
拦截同名函数，以参数区分
control方法
@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脚本
/**
* 拦截同名函数，通过输入的参数区分
*/
@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();
}
}
拦截结果
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
拦截方法返回值
BTrace脚本
/**
* 拦截返回值
*/
@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();
}
}
拦截结果
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
异常分析
有时候开发人员对异常处理不合理，导致某些重要异常人为被吃掉，并且没有日志或者日志不详细，导致性能分析定位问题困难，我们可以使用BTrace来处理
control方法
@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脚本
/**
* 有时候，有些异常被人为吃掉，日志又没有打印，这个时候可以用该类定位问题
* 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;
}
}
}
拦截结果
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)
=====================
...
定位某个超过阈值的函数
BTrace脚本
**
* 探测某个包路径下的方法执行时间是否超过某个阈值的程序，如果超过了该阀值，则打印当前线程的栈信息。
*/
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();
}
}
}
拦截结果
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)
追踪方法执行时间
BTrace脚本
/**
* 追踪某个方法的执行时间，实现原理同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)));
}
}
拦截结果
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
性能分析
压测的时候经常发现某一个服务变慢了，但是由于这个服务有很多的业务逻辑和方法构成，这个时候就不好定位到底慢在哪个地方。BTrace可以解决这个问题，只需要大概定位问题可能存在的地方，通过包路径模糊匹配，就可以找到问题。
BTrace脚本
/**
*
* 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);
}
死锁排查
我们怀疑程序是否有死锁，可以通过以下的脚步扫描追踪，非常简单方便。
/**
* 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秒的方法；
- 查看哪些方法调用了system.gc()，调用栈是怎样的；
- 查看方法的参数和属性
- 哪些方法发生了异常
…
总之，这里只是将部分经常用的列举了下抛砖引玉，还有很多没有列举，大家可以参考官方的其他Sample去玩下。