如何在生产环境使用Btrace进行调试
转载2篇关于Btrace的文章。以后有实际用过后再做更新。
下面转自: https://www.jianshu.com/p/dbb3a8b5c92f
背景
记得前几天有人问我:在生产环境中可能经常遇到各种问题,你们一般是如何进行调试的? 很惭愧,没有经验。因为平时碰不到生产环境的服务器,定位问题需要各种数据,所以大多数问题的解决方式都是在本地打断点进行调试,或者在测试环境利用输出日志进行调试,这种方式简单粗暴,但过程比较繁琐,需要各种重新发布,重启应用,还不能保证一次就找到问题的根源。直到最近才了解到Btrace这个工具,对于这样一个神器,我觉得有必要记录一篇,让更多的人知道。
Btrace
BTrace是sun公司推出的一款Java 动态、安全追踪(监控)工具,可以在不用重启的情况下监控系统运行情况,方便的获取程序运行时的数据信息,如方法参数、返回值、全局变量和堆栈信息等,并且做到最少的侵入,占用最少的系统资源。
由于Btrace会把脚本逻辑直接侵入到运行的代码中,所以在使用上做很多限制:
1、不能创建对象
2、不能使用数组
3、不能抛出或捕获异常
4、不能使用循环
5、不能使用synchronized关键字
6、属性和方法必须使用static修饰
根据官方声明,不恰当的使用BTrace可能导致JVM崩溃,如在BTrace脚本使用错误的class文件,所以在上生产环境之前,务必在本地充分的验证脚本的正确性。
Btrace可以做什么?
1、接口性能变慢,分析每个方法的耗时情况;
2、当在Map中插入大量数据,分析其扩容情况;
3、分析哪个方法调用了System.gc(),调用栈如何;
4、执行某个方法抛出异常时,分析运行时参数;
5、....
Btrace第一个例子
package com.metty.rpc.common;
import java.util.Random;
/**
* Created by j_zhan on 2016/11/28.
*/
public class BtraceCase {
public static Random random = new Random();
public int size;
public static void main(String[] args) throws Exception {
new BtraceCase().run();
}
public void run() throws Exception {
while (true) {
add(random.nextInt(10), random.nextInt(10));
}
}
public int add(int a, int b) throws Exception {
Thread.sleep(random.nextInt(10) * 100);
return a + b;
}
}
执行add方法时,对传入参数、返回值以及执行耗时进行分析,btrace脚本:
通过jps命令获取pid为8454
执行btrace 8454 Debug.java
实现对运行代码的监控,输出结果如下:
![](https://img2018.cnblogs.com/blog/623461/201906/623461-20190623221509149-195608080.png)
可以发现,Btrace可以获取每次执行add方法时的数据,当然Btrace能做的远远不止这些,比如获取当前jvm堆使用情况、当前线程的执行栈等等。
参数说明
@OnMethod
Btrace使用@OnMethod注解定义需要分析的方法入口
![](https://img2018.cnblogs.com/blog/623461/201906/623461-20190623221530953-1639169682.png)
在@OnMethod注解中,需要指定class、method以及location等,class表明需要监控的类,method表明需要监控的方法,指定方式如下:
1、使用全限定名:clazz="com.metty.rpc.common.BtraceCase", method="add"
2、使用正则表达式:clazz="/javax\\.swing\\..*/", method="/.*/"
3、使用接口:clazz="+com.ctrip.demo.Filter", method="doFilter"
4、使用注解:clazz="@javax.jws.WebService", method=""@javax.jws.WebMethod"
5、如果需要分析构造方法,需要指定method="<init>"
@Location
定义Btrace对方法的拦截位置,通过@Location注解指定,默认为Kind.ENTRY
1、Kind.ENTRY:在进入方法时,调用Btrace脚本
2、Kind.RETURN:方法执行完时,调用Btrace脚本,只有把拦截位置定义为Kind.RETURN,才能获取方法的返回结果@Return和执行时间@Duration
![](https://img2018.cnblogs.com/blog/623461/201906/623461-20190623221542727-1390680371.png)
3、Kind.CALL:分析方法中调用其它方法的执行情况,比如在execute方法中,想获取add方法的执行耗时,必须把where设置成Where.AFTER
![](https://img2018.cnblogs.com/blog/623461/201906/623461-20190623221553233-267327790.png)
4、Kind.LINE:通过设置line,可以监控代码是否执行到指定的位置
![](https://img2018.cnblogs.com/blog/623461/201906/623461-20190623221602683-187740239.png)
5、Kind.ERROR, Kind.THROW, Kind.CATCH
用于对某些异常情况的跟踪,包括异常抛出,异常被捕获,异常未捕获被抛出方法之外
如何使用Btrace定位问题
1、找出所有耗时超过1ms的过滤器Filter
![](https://img2018.cnblogs.com/blog/623461/201906/623461-20190623221613279-406556787.png)
由于@Dutation返回的时间是纳秒级别,需要进行转换,如果定位一个Filter性能变慢,接着使用@Location(Kind.CALL)进行更细粒度的分析。
2、分析哪个方法调用了System.gc(),调用栈如何?
![](https://img2018.cnblogs.com/blog/623461/201906/623461-20190623221623226-308456858.png)
通过查看调用栈,可以很清楚的发现哪个类哪个方法调用了System.gc()
3、统计方法的调用次数,且每隔1分钟打印调用次数
![](https://img2018.cnblogs.com/blog/623461/201906/623461-20190623221634625-1981849731.png)
Btrace的@OnTimer注解可以实现定时执行脚本中的一个方法
4、方法执行时,查看对象的实例属性值
![](https://img2018.cnblogs.com/blog/623461/201906/623461-20190623221642958-1308104084.png)
通过反射机制,可以很方法的得到当前实例的属性值
总结
Btrace能做的事情太多,但使用之前切记检查脚本的可行性,一旦Btrace脚本侵入到系统中,只有通过重启才能恢复。
记录另外一篇代码较多的文章: https://blog.csdn.net/iteye_6700/article/details/82644915
BTrace是一个可以动态跟踪Java代码执行的工具,网上已经有很多文章介绍,我这里分享一个我在实际工作中排查性能问题的例子。
现象
我的一个REST接口调用非常慢,postman耗时3873 ms,这个接口就是从redis里把一批数据取出来,redis性能很好,理论上不会这么慢,于是用btrace,trace方法调用。
/* BTrace Script Template */ import com.sun.btrace.annotations.*; import static com.sun.btrace.BTraceUtils.*; @BTrace public class TracingScript { /* put your code here */ @TLS private static long startlTime = 0; @TLS private static long startmTime = 0; @TLS private static long startjTime = 0; @TLS private static long startrTime = 0; @TLS private static long startbTime = 0; @OnMethod(clazz="com.xx.monitoring.api.util.JedisHelper", method="listSize") public static void startjMethod() { startjTime = timeMillis(); } @OnMethod(clazz="com.xx.monitoring.api.util.JedisHelper", method="listSize", location=@Location(Kind.RETURN)) public static void endjMethod() { println(strcat("listSize method execute time=>", str(timeMillis()-startjTime))); println("-------------------------------------------"); } @OnMethod(clazz="com.xx.monitoring.api.util.JedisHelper", method="listRange") public static void startrMethod() { startrTime = timeMillis(); } @OnMethod(clazz="com.xx.monitoring.api.util.JedisHelper", method="listRange", location=@Location(Kind.RETURN)) public static void endrMethod() { println(strcat("listRange method execute time=>", str(timeMillis()-startrTime))); println("-------------------------------------------"); } @OnMethod(clazz="com.xx.monitoring.api.persistence.MetricRedisDao", method="listMetricByIds") public static void startbMethod() { startbTime = timeMillis(); } @OnMethod(clazz="com.xx.monitoring.api.persistence.MetricRedisDao", method="listMetricByIds", location=@Location(Kind.RETURN)) public static void endbMethod(java.util.List metricIds) { println("metrcIds.size: " + metricIds.size()); println(strcat("listMetricByIds method execute time=>", str(timeMillis()-startbTime))); println("-------------------------------------------"); } @OnMethod(clazz="com.xx.monitoring.api.service.MetricServiceImpl", method="listMetricsInternal") public static void startlMethod() { startlTime = timeMillis(); } @OnMethod(clazz="com.xx.monitoring.api.service.MetricServiceImpl", method="listMetricsInternal", location=@Location(Kind.RETURN)) public static void endlMethod() { println(strcat("listMetricsInternal method execute time=>", str(timeMillis()-startlTime))); println("-------------------------------------------"); } @OnMethod(clazz="com.xx.monitoring.api.service.MetricServiceImpl", method="listMetricsMap") public static void startmMethod() { startmTime = timeMillis(); } @OnMethod(clazz="com.xx.monitoring.api.service.MetricServiceImpl", method="listMetricsMap", location=@Location(Kind.RETURN)) public static void endmMethod() { println(strcat("listMetricsMap execute time=>", str(timeMillis()-startmTime))); println("-------------------------------------------"); } }
编译:
$ btracec TracingScript.java
开始trace
$ btrace 19416 TracingScript.class
结果:
DEBUG: received com.sun.btrace.comm.MessageCommand@5b6f7412
listSize method execute time=>3
DEBUG: received com.sun.btrace.comm.MessageCommand@27973e9b
-------------------------------------------
DEBUG: received com.sun.btrace.comm.MessageCommand@312b1dae
listRange method execute time=>18
DEBUG: received com.sun.btrace.comm.MessageCommand@7530d0a
-------------------------------------------
DEBUG: received com.sun.btrace.comm.MessageCommand@27bc2616
listRange method execute time=>19
DEBUG: received com.sun.btrace.comm.MessageCommand@3941a79c
-------------------------------------------
DEBUG: received com.sun.btrace.comm.MessageCommand@506e1b77
listMetricsInternal method execute time=>4820
DEBUG: received com.sun.btrace.comm.MessageCommand@4fca772d
-------------------------------------------
DEBUG: received com.sun.btrace.comm.MessageCommand@9807454
listMetricsMap execute time=>4821
可以看到listMetricsInternal执行了4820毫秒
这个方法就是把metric的id循环从redis取metric bean,初步判断是id太多导致很慢,继续trace
添加方法:
@OnMethod(clazz="com.xx.monitoring.api.persistence.MetricRedisDao", method="listMetricByIds", location=@Location(Kind.RETURN)) void endbMethod(java.util.List<String> metricIds) { println("metrcIds.size: " + str(metricIds)); println("-------------------------------------------"); }
执行结果:
metrcIds.size: [weblogic.datasource.waiting_for_connection_high_count, weblogic.datasource.leaked_connection_count, weblogic.datasource.active_connections_currentCount, weblogic.threadpool.standby_thread_count, weblogic.threadpool.active_thread_idle_count, weblogic.threadpool.execute_thread_total_count, weblogic.session.open_sessions_current_count, weblogic.session.open_sessions_high_count, weblogic.session.sessions_opened_total_count, weblogic.server.health_state, weblogic.server.activation_time, server.os.kernel_version, server.os.version, server.os.id, server.interfaces.tx, server.interfaces.rx, server.disk.used_percent, server.cpu.load, server.memory.free_percent, server.memory.used_percent, server.cpu.idle, server.cpu.iowait, server.cpu.sys, server.cpu.user, oracle.info.status, oracle.worst.sql, oracle.time_ratio.cpu_time_ratio, oracle.time_ratio.wait_time_ratio, oracle.connection.count, jvm.memory.used, jvm.memory.max, jvm.memory.committed, jvm.thread.total_started_thread_count, jvm.thread.daemon_thread_count, jvm.thread.peak_thread_count, jvm.thread.count, jvm.gc.collection_time, jvm.gc.collection_count, jvm.classsloading.unloaded_class_count, jvm.classsloading.loaded_class_count, jvm.classsloading.total_loaded_class_count, jvm.info.input_arguments, jvm.info.vm_id, jvm.info.vm_version, weblogic.datasource.waiting_for_connection_high_count, weblogic.datasource.leaked_connection_count, weblogic.datasource.active_connections_currentCount, weblogic.threadpool.standby_thread_count, weblogic.threadpool.active_thread_idle_count, weblogic.threadpool.execute_thread_total_count, weblogic.session.open_sessions_current_count, weblogic.session.open_sessions_high_count, weblogic.session.sessions_opened_total_count, weblogic.server.health_state, weblogic.server.activation_time, server.os.kernel_version, server.os.version, serve
还有很多
一共3610个,从redis取一个1ms,那也要3610ms,怪不得。
原因找到了,改代码就很简单了
另外发现BTrace还有一个工具专门分析性能的BTraceUtils.Profiling,代码:
import com.sun.btrace.BTraceUtils; import com.sun.btrace.Profiler; import com.sun.btrace.annotations.*; import static com.sun.btrace.BTraceUtils.*; @BTrace class Profiling { @Property Profiler swingProfiler = BTraceUtils.Profiling.newProfiler(); @OnMethod(clazz="/com\\.xx\\.monitoring\\.api\\..*/", method="/.*/") void entry(@ProbeMethodName(fqn=false) String probeMethod) { //fqn是否打印长方法名 BTraceUtils.Profiling.recordEntry(swingProfiler, probeMethod); } @OnMethod(clazz="/com\\.xx\\.monitoring\\.api\\..*/", method="/.*/", location=@Location(value=Kind.RETURN)) void exit(@ProbeMethodName(fqn=false) String probeMethod, @Duration long duration) { BTraceUtils.Profiling.recordExit(swingProfiler, probeMethod, duration); } @OnTimer(5000) //每5秒打印一次 void timer() { BTraceUtils.Profiling.printSnapshot("Performance profile", swingProfiler); } }
结果:
Performance profile
Block Invocations SelfTime.Total SelfTime.Avg SelfTime.Min SelfTime.Max WallTime.Total WallTime.Avg WallTime.Min WallTime.Max
preHandle 1 96000 96000 96000 96000 96000 96000 96000 96000
listSize 1 2231000 2231000 2231000 2231000 2231000 2231000 2231000 2231000
......
getMetric 3610 20915000 5793 1000 384000 3805159000 1054060 689000 5752000
......
可见getMetric执行了3610次
怎么样,BTrace还是很强大的吧,分析线上问题很方便。