性能监控

   spring，真是一个好东西；性能，真是个让人头疼又不得不面对的问题。如何排查出项目中性能瓶颈？如何迅速定位系统的慢查询？在这我就不说spring自带的性能监控器了，实在是有些简陋。下面就说说我自己写的这个性能监控器。先看看效果：

2013-07-07 19:19:50,440 WARN  [main] [aop.PerformanceInterceptor]
|-144 ms; [HelloService.hellpAop]
|+---10 ms; [AnotherService.childMehhod]
|+---21 ms; [AnotherService.childMehhod3]
|+---+---8 ms; [HelloService.parentMehtod]
|+---12 ms; [AnotherService.childMehhod2]

 其实，利用spring AOP，任何人都可以写一个定制的监控，但大体思路是一样的，就是在被调用方法的开始之前，记录一下开始时间，在调用方法结束之后，记录结束时间，然后，在调用栈退出前，将日志打印出来。光说不练假把式，下面一步一步构建一个性能监控器。

step1.构造拦截器。

直接上代码，拦截器核心代码：

 

public Object invoke(MethodInvocation invocation) throws Throwable {
       try {
        String name = extractLogName(invocation);
        //记录开始时间
           start(name);
           return invocation.proceed();
       } finally {
        //记录方法结束时间
           stop();
       }
}

 

 

因为最终要打印出来，因此，打印的名称必须在记录时间时把被调用方法的名称也记录下来。方法extractLogName就是干这个的。

 

step2.构造数据结构

首先，我们需要一个线程变量，存储AOP拦截的每个方法的开始时间及结束时间。就用threadLocal变量了，本人还没想到更好的方法。其次，调用过程其实是在一个方法栈（Stack）中旅行了一遍，被调用的方法总是后进先出。每进一个方法，都要记录一个开始时间，每当退出一个方法，都要记录这个方法运行的结束时间。最终，我们将得到一个类似树形的结构。我们需要定义这个结构，以便我们在退出方法栈时能够将每一个方法所耗费的时间都打印出来。

 

/**
     * 保存监控信息变量
     * @author [e-mail]
     */
    private static class StackData {
        /**
         * 记录根根节点
         */
        public StackEntry root;
        /**
         * 当前正在调用方法节点
         */
        public StackEntry currentEntry;
        /**
         * 堆栈树高度
         */
        public int level;
    }

    /**
     * aop方法性能统计实体
     * @author [e-mail]
     */
    private static class StackEntry {
        public String logName ;
        public long beginTime;
        public long endTime;
        /**
         * 节点所处高度
         */
        public int level;
        /**
         * 调用的子方法
         */
        public List<StackEntry> child;
        /**
         * 上级节点
         */
        public StackEntry parent ;
        public StackEntry(String logName, long currentTimeMillis) {
            this.logName = logName;
            this.beginTime = currentTimeMillis;
            this.child = new ArrayList<StackEntry>(3);
        }
    }

 StackData定义了根节点的结构，StackEntry存储每个方法的开始结束时间，另外在StackData和StackEntry加入level字段，方便后面打印日志。StackData和StackEntry都是作为一个内部类引入的，因为这两个类为了性能，都没有提供一些封装方法，不宜暴露出去（出去多丢人啊）。

 

好了，结构和拦截器都写好了。只需两步，大工基本就告成了，在拦截器中，在调用方法的前面及后面，记录一个StackEntry对象就可以了。start和stop的代码如下：

 

public static void start(String logName) {
        StackData data = dataHolder.get();
        StackEntry currentEntry = new StackEntry(logName, System.currentTimeMillis());
        if (data == null) {
            data = new StackData();
            data.root = currentEntry;
            data.level = 1;
            dataHolder.set(data);
        } else {
            StackEntry parent = data.currentEntry;
            currentEntry.parent=parent;
            parent.child.add(currentEntry);
        }
        data.currentEntry = currentEntry;
        currentEntry.level=data.level;
        data.level++;
    }
    public static void stop() {
        StackData data = dataHolder.get();
        StackEntry self = data.currentEntry;
        self.endTime = System.currentTimeMillis();
        data.currentEntry = self.parent;
        data.level--;
        printStack(data);
    }
       /**
     * 此处还可以进行改进，可以将超时的数据放入一个有界队列
     * 里，在另一个线程进行打印。
     * @param data
     */
    private static void printStack(StackData data) {
        if(logger.isWarnEnabled()){
            StringBuilder sb = new StringBuilder("\r\n");
            StackEntry root = data.root;
            appendNode(root,sb);
            logger.warn(sb.toString());
        }
    }

    private static void appendNode(StackEntry entry, StringBuilder sb) {
        long totalTime = entry.endTime-entry.beginTime ;
        if(entry.level ==1){
            sb.append("|-");
        }
        sb.append(totalTime);
        sb.append(" ms; [");
        sb.append(entry.logName);
        sb.append("]");

        for(StackEntry cnode : entry.child){
            sb.append("\r\n|");
            for(int i=0,l=entry.level;i<l;i++){
                sb.append("+---");
            }
            appendNode(cnode,sb);
        }

    }

 

等等，还有需求？

1、我们只想找出慢查询，而不想把所有的方法的运行时间都打印出来

2、希望有一个开关，平常不需要监控，在出现问题的时候，才把这个监控打开。

好吧，程序员都是被这些需求给搞死的。

在拦截器中增加一个开关switchOn和一个阈值threshold，当switchOn==true的时候，才进行监控，否则不监控。在监控时，如果整个方法的运行时间小于threshold，不打印日志，因为打印日志会IO，会给方法增加额外的开销。改进后代码如下：

      /**
 * 性能监控开关
 * 可以在运行时动态设置开关
 */
private volatile boolean switchOn = true;
/**
 * 方法执行阈值
 */
private volatile int threshold = 100;
public Object invoke(MethodInvocation invocation) throws Throwable {
    if(switchOn){
        String name = extractLogName(invocation);
        try {
                start(name);
            return invocation.proceed();
        } finally {
                stop(threshold);
        }
    }
    else {
         return invocation.proceed();
    }
}

 打印日志阈值：

      /**
 * @param threshold 打印日志的阈值
 */
public static void stop(int threshold) {
    StackData data = dataHolder.get();
    StackEntry self = data.currentEntry;
    self.endTime = System.currentTimeMillis();
    data.currentEntry = self.parent;
    data.level--;
    if(data.root == self && (self.endTime -self.beginTime) > threshold){
        printStack(data);
    }
}

 

到此，这个性能监控器几乎算完美了。

但这个监控器是运行在spring AOP上面的，并且，监控的方法必须都是通过interface调用的。所以，如果你要使用这个方法，还要确保你是使用的面向接口的编程。不过，如果你的项目没有使用面向接口，可以利用eclipse自带的工具，将公用方法Extract成interface。

 spring怎么配置？拦截器怎么配置？下载附件，自己看吧，lib包都在里面。