spring AOP的方式监控方法的执行时间

前段时间有几个同行跟我吐槽说系统响应越来越慢，优化不知道从何入手！今天写写使用spring的aop来实现方法级的执行时间的记录监控，以此来评估方法的性能以及针对性的对已存在的方法进行优化。

对于监控，我们比较关注监控的可靠性和性能，准确，高效，这才能在不影响整体性能的情况下对我们的系统性能有个较准确的认识。

对于spring aop这个我就不多介绍了，网上一搜一大把，使用过spring的人都知道spring的ioc和aop。ioc我们常用，但在我们自己的系统中，aop的使用几乎为零，除了这个监控的小功能应用到了，其他的基本上没有使用到。

我们使用BeanNameAutoProxyCreator，指定bean的名称，以及被通知bean的名称，指定名称时可以使用通配符自动代理它们，配置如下

<bean class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">  
        <property name="proxyTargetClass">  
            <value>true</value>  
        </property>  
        <property name="interceptorNames">  
            <list>  
                <idref bean="profilerInterceptor"/>  
            </list>  
        </property>  
        <property name="beanNames">  
            <list>  
                <value>*Service</value>  
                <value>*ServiceImpl</value>  
                <value>*Manager</value>  
                <value>*ManagerImpl</value>  
                <value>*Dao</value>  
            </list>  
        </property>  
    </bean>

上面的配置文件我们配置了一个idref bean，这个就是我们需要写的监控逻辑的代码。interceptor是个拦截器，上面的这个配置的所反应出来的内容是，写自己的一个拦截器来拦截后缀为Service,ServiceImpl,Manager,ManagerImpl,Dao的类，至于是类拦截还是方法级别的拦截，那就要看我们的拦截器的逻辑和代码了。

说说拦截器的实现。我们希望拦截器在对方法的执行时间进行记录的同时，还要进行日志的输出，如，执行时间超过500ms的方法，我们要打印出内部执行每个方法的耗时，这样我们可以对执行的慢的方法一目了然，优化时也不需要耗很多的时间去logger到底是哪里执行的慢了。所以在拦截器中，我们增加一个整形的属性，这个属性用来配置需要打印到日志中超过配置时间的执行方法的耗时情况。得到像下面一样的一个日志输出:

[4359, 2, 100%, 0]com.profile.service.impl.OrderServiceImpl.findRecentlyProfile  
+---[4357, 4357, 99%, 1]com.profile.dao.GenericMybatisDao.queryPage

第一行表示整个方法执行的总耗时，下一行表示在这个方法中存在的其他受监控的方法耗时。这就很容易让我们知道，是执行SQL所耗的时间，需要对SQL进行优化。

那到底该怎么样去实现，展示拦截器中的部分代码。拦截器继承AbstractMonitoringInterceptor类，它是一个方法级别的拦截器，实现了 MethodInterceptor 接口。

protected Object invokeUnderTrace(MethodInvocation invocation, Log logger) throws Throwable {  
        String name = createInvocationTraceName(invocation);  
        //是否委托了注解的拦截  
        boolean isExistsPrintProfiler = PrintProfilerHelper.isMethodExistsPrintProfiler(invocation.getMethod());  
        try {  
            if (!isExistsPrintProfiler) {  
                Profiler.start(name, monitorTime);  
            }  
            return invocation.proceed();  
        } finally {  
            if (!isExistsPrintProfiler) {  
                Profiler.stop(name);  
            }  
        }  
    }  
  
    public int getMonitorTime() {  
        return monitorTime;  
    }  
  
    public void setMonitorTime(int monitorTime) {  
        this.monitorTime = monitorTime;  
    }

拦截器中的代码非常简单，简单到10几行代码。这对我们来说是件好事。在Profiler这个类中，我们进行了一些监控，鉴于我们输出上面所描述的日志的tree格式的日志文件，我们在Profiler中使用了TheadLocal来对执行的方法进行管理，这样会将代码变的非常简单。Profiler的start方法也就10行代码

private final static ThreadLocal<ExecData> dataHolder = new ThreadLocal<ExecData>();  
  
  
public static void start(String logName) {  
    start(logName, ELAPSE_TIME_MS_TO_LOG);  
}  
  
public static void start(String logName, int elapseTimeMsToLog) {  
    ExecData execData = dataHolder.get();  
    ExecNode currentNode = new ExecNode(logName, System.currentTimeMillis(), elapseTimeMsToLog);  
    if (execData == null) {  
        execData = new ExecData();  
        execData.root = currentNode;  
        dataHolder.set(execData);  
    } else {  
        ExecNode parent = execData.currentNode;  
        currentNode.setParent(parent);  
        parent.getChildList().add(currentNode);  
    }  
    execData.currentNode = currentNode;  
    execData.level++;  
}

这样，我们就把方法的层级关系记录下来了，在执行完被监控的方法之后，我们使用stop的方法来记录执行结束时间，并对符合条件的方法进行日志的输出。就这么几十行代码，我们非常简单的把这个监控写完了，部署到我们自己的应用中来监控方法的性能，从此，我们不用再去猜到底是哪个方法执行太慢了，到底是哪一步慢了。性能，监控，尽在掌握中。