使用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秒的方法和接口，同时也可以统计哪些接口调用多，哪些调用少，哪些接口参数特别长等信息，这里就不一一说明了