使用Btrace进行线上系统性能分析

最近花了点时间调查系统的性能问题，这中间用到了几个小工具，趁热记录下来供以后参考：

首先为了能够了解线上系统到底哪些方法存在性能瓶颈，得需要查看线上每个方法的执行时间，这个如果之前开发者在代码中记录了日志，或者web系统配置了日志拦截器记录下每次请求的响应时间，就可以从这些日志中分析出所有的慢接口，但是因为每个开发者习惯不同，现有系统中并不是每个方法都有这些日志。因此就得想其它办法，需要一个既不用重新修改代码并重发系统，用能获取到线上系统每个方法实际执行情况的方案，Btrace就是用来干这个活的工具。

Btrace的基本使用

1）下载btrace包，解压到本地目录，修改本机path路径后，执行btrace命令即可启动btrace功能。

     下载地址：https://kenai.com/projects/btrace/downloads

     修改path：

# add btrace cmd

export BTRACE_HOME=/Users/*yourusername*/Downloads/btrace-bin-1.3.8.1

export PATH=$BTRACE_HOME/bin:$PATH

2）编写跟踪线上执行情况的脚本，btrace脚本也是java代码，例如：

 /* BTrace Script Template */

import com.sun.btrace.AnyType;

import com.sun.btrace.annotations.*;

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

@BTrace

public class TracingScript {

    /* put your code here */

    @TLS private static long startTime = 0;

    @OnMethod(

            clazz="com.xxx.gate.common.hessian.service.GateTargetHessianServiceImpl",

            method="gateTargetInvocation"

    )

    public static void startExecute(){

        startTime = timeNanos();

    }

    @OnMethod(

            clazz="/com\\.xxx\\.gate\\.common\\.hessian\\.service\\.GateTargetHessianService.*/",

            method="/gateTargetInvocation.*/"

    )

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

        println(pcn);

        println(pmn);

        printArray(args);

    }

    @OnMethod(

            clazz="com.xxx.gate.common.hessian.service.GateTargetHessianServiceImpl",

            method="/gateTargetInvocation.*/",

            location=@Location(Kind.RETURN)

    )

    public static void endExecute(@Duration long duration, @Return AnyType ret){

        println(strcat("duration(haomiao): ", str(duration/1000000)));

        if(ret == null) {

            print("result: null");

        } else if(isPrimitive(classOf(ret))){

            print("result: ");

            print(ret);

        } else {

            print("result: ");

            printFields(ret);

        }

    }

}

这个脚本的功能其实就是记录了我们gate系统上所有hessian接口的调用信息，包含类名、方法名、时长、返回值等。其中用到了btrace的一些注解，简单说明如下：

@OnMethod 描述本函数要监控的方法属性，可指定clazz，method，location等属性来制定定被监控的那些方法。

@ProbeClassName 把被监控的类名作为参数传给当前方法

@ProbeMethodName 把被监控的方法名作为参数传给当前方法

@Duration 把被监控方法执行的时间作为参数传给当前方法

@Return 把被监控方法的返回值作为参数传给当前方法

@Location 描述当前方法执行的时机，Kind.RETURN表示在方法return时执行。

其它还有更详细的例子可以参考前面下载下来btrace包里的userguide文档，内容不多的。

3）执行btrace脚本，监测线上系统情况

     首先找到你要监控的应用进程号，可通过jps -v查看，比如下面是gate的，第一个14250就是进程号。

14250 Bootstrap -Djava.util.logging.config.file=/xxx/tomcat/apache-tomcat-6.0.35/conf/logging.properties -Xms2g -Xmx2g -XX:PermSize=1024m -XX:MaxPermSize=1024m -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -Dproduction.mode=ONLINE -Djava.rmi.server.hostname=***.**.***.*** -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=7000 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Xdebug -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=8800 -Djava.endorsed.dirs=/xxx/tomcat/apache-tomcat-6.0.35_bak/endorsed -Dcatalina.base=/xxx/tomcat/apache-tomcat-6.0.35_bak -Dcatalina.home=/xxx/tomcat/apache-tomcat-6.0.35_bak -Djava.io.tmpdir=/xxx/tomcat/apache-tomcat-6.0.35_bak/temp

     其次运行命令：btrace 14250 TraceGate.java > trace.log &

     这里TraceGate.java就是前面写的btrace脚本，完整的命令格式如下: 

btrace [-I <include-path>] [-p <port>] [-cp <classpath>] <pid> <btrace-script> [<args>] 

4）收集了线上执行情况的日志后，接下来就是分析日志了。

根据我脚本里的格式，用grep找出那些运行时间超过1秒的方法和接口，同时也可以统计哪些接口调用多，哪些调用少，哪些接口参数特别长等信息，这里就不一一说明了