如何在生产环境使用Btrace进行调试

　　转载2篇关于Btrace的文章。以后有实际用过后再做更新。

       下面转自： https://www.jianshu.com/p/dbb3a8b5c92f

  

　　背景

　　记得前几天有人问我：在生产环境中可能经常遇到各种问题，你们一般是如何进行调试的？ 很惭愧，没有经验。因为平时碰不到生产环境的服务器，定位问题需要各种数据，所以大多数问题的解决方式都是在本地打断点进行调试，或者在测试环境利用输出日志进行调试，这种方式简单粗暴，但过程比较繁琐，需要各种重新发布，重启应用，还不能保证一次就找到问题的根源。直到最近才了解到Btrace这个工具，对于这样一个神器，我觉得有必要记录一篇，让更多的人知道。

　　Btrace

　　BTrace是sun公司推出的一款Java 动态、安全追踪（监控）工具，可以在不用重启的情况下监控系统运行情况，方便的获取程序运行时的数据信息，如方法参数、返回值、全局变量和堆栈信息等，并且做到最少的侵入，占用最少的系统资源。

　　项目地址：Btrace
　　用户指南：UserGuide

　　由于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实现对运行代码的监控，输出结果如下：

　　可以发现，Btrace可以获取每次执行add方法时的数据，当然Btrace能做的远远不止这些，比如获取当前jvm堆使用情况、当前线程的执行栈等等。

　　参数说明

　　@OnMethod

　　Btrace使用@OnMethod注解定义需要分析的方法入口

 

　　在@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

　　3、Kind.CALL：分析方法中调用其它方法的执行情况，比如在execute方法中，想获取add方法的执行耗时，必须把where设置成Where.AFTER

　　4、Kind.LINE：通过设置line，可以监控代码是否执行到指定的位置

　　5、Kind.ERROR, Kind.THROW, Kind.CATCH
　　用于对某些异常情况的跟踪，包括异常抛出，异常被捕获，异常未捕获被抛出方法之外

　　如何使用Btrace定位问题

　　1、找出所有耗时超过1ms的过滤器Filter

　　由于@Dutation返回的时间是纳秒级别，需要进行转换，如果定位一个Filter性能变慢，接着使用@Location(Kind.CALL)进行更细粒度的分析。

　　2、分析哪个方法调用了System.gc()，调用栈如何？

　　通过查看调用栈，可以很清楚的发现哪个类哪个方法调用了System.gc()

　　3、统计方法的调用次数，且每隔1分钟打印调用次数

　　Btrace的@OnTimer注解可以实现定时执行脚本中的一个方法

　　4、方法执行时，查看对象的实例属性值

　　通过反射机制，可以很方法的得到当前实例的属性值

　　总结

　　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还是很强大的吧，分析线上问题很方便。