AOP 来记录每个方法的执行时间

[转载]用 AOP 来记录每个方法的执行时间
有时候我们要跟踪方法的执行时间，来观察系统的性能、时间分布。特别是要找出那些十分耗时的操作。如果是在每个方法中起始和结束位置记下时间相减，那是不太现实的，对代码的侵入性太过份，而且在产品环境中又得屏闭那部份代码。

幸好现在有了 AOP，通过配置方式再加上外部辅助代码就能达到我们的要求，正式上线时只需要简单改个配置项拆卸下来即可。

下面介绍三种方式来打印每个方法的执行时间，分别是：

1. Spring 2.0 用 AspectJ 实现 AOP
2. Spring 通用的方法拦截
3. 直接用 AspectJ 实现

1. Spring 2.0 用 AspectJ 实现 AOP

这个实例由五个文件构成，两个配置文件和三个类文件。需要在项目中引用 Spring 2.0 以上版本的相关包，还要日志包。

1) log4j.properties  放在 src 目录下



log4j.rootLogger=DEBUG,stdout   
  
log4j.appender.stdout=org.apache.log4j.ConsoleAppender    
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout    
  
log4j.appender.stdout.layout.ConversionPattern=%d [%5p] %c{1}.%M(%L) %n%m%n   
log4j.rootLogger=DEBUG,stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d [%5p] %c{1}.%M(%L) %n%m%n
2) applicationContext.xml   放在 src 目录下


<beans xmlns="http://www.springframework.org/schema/beans"  
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"  
      xmlns:aop="http://www.springframework.org/schema/aop"  
      xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-2.0.xsd   
http://www.spridngframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-2.0.xsd">  
  
    <aop:config>  
        <!-- Spring 2.0 可以用 AspectJ 的语法定义 Pointcut，这里拦截 service 包中的所有方法 -->  
        <aop:advisor id="methodTimeLog" advice-ref="methodTimeAdvice" pointcut="execution(* *..service..*(..))"/>  
    </aop:config>  
  
    <bean id="methodTimeAdvice" class="com.unmi.util.MethodTimeAdvice"/>  
    <bean id="helloService" class="com.unmi.service.HelloService"/>  
</beans>  
<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:aop="http://www.springframework.org/schema/aop"
xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-2.0.xsd
http://www.spridngframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-2.0.xsd">
<aop:config>
<!-- Spring 2.0 可以用 AspectJ 的语法定义 Pointcut，这里拦截 service 包中的所有方法 -->
<aop:advisor id="methodTimeLog" advice-ref="methodTimeAdvice" pointcut="execution(* *..service..*(..))"/>
</aop:config>
<bean id="methodTimeAdvice" class="com.unmi.util.MethodTimeAdvice"/>
<bean id="helloService" class="com.unmi.service.HelloService"/>
</beans>
3) MethodTimeAdvice.java 记录时间的类


package com.unmi.util;   
  
import org.aopalliance.intercept.MethodInterceptor;   
import org.aopalliance.intercept.MethodInvocation;   
import org.apache.commons.lang.StringUtils;   
import org.apache.commons.lang.time.StopWatch;   
import org.apache.commons.logging.Log;   
import org.apache.commons.logging.LogFactory;   
  
/**  
* 记录方法的执行时间  
* @author Unmi  
*/  
public class MethodTimeAdvice implements MethodInterceptor {   
    protected final Log log = LogFactory.getLog(MethodTimeAdvice.class);   
  
    /**  
     * 拦截要执行的目标方法  
     */  
    public Object invoke(MethodInvocation invocation) throws Throwable {   
        //用 commons-lang 提供的 StopWatch 计时，Spring 也提供了一个 StopWatch   
        StopWatch clock = new StopWatch();   
        clock.start(); //计时开始   
        Object result = invocation.proceed();   
        clock.stop();  //计时结束   
           
        //方法参数类型，转换成简单类型   
        Class[] params = invocation.getMethod().getParameterTypes();   
        String[] simpleParams = new String[params.length];   
        for (int i = 0; i < params.length; i++) {   
            simpleParams[i] = params[i].getSimpleName();   
        }   
           
        log.debug("Takes:" + clock.getTime() + " ms ["  
                + invocation.getThis().getClass().getName() + "."  
                + invocation.getMethod().getName() + "("+StringUtils.join(simpleParams,",")+")] ");   
        return result;   
    }   
}  
package com.unmi.util;
import org.aopalliance.intercept.MethodInterceptor;
import org.aopalliance.intercept.MethodInvocation;
import org.apache.commons.lang.StringUtils;
import org.apache.commons.lang.time.StopWatch;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
/**
* 记录方法的执行时间
* @author Unmi
*/
public class MethodTimeAdvice implements MethodInterceptor {
protected final Log log = LogFactory.getLog(MethodTimeAdvice.class);
/**
* 拦截要执行的目标方法
*/
public Object invoke(MethodInvocation invocation) throws Throwable {
//用 commons-lang 提供的 StopWatch 计时，Spring 也提供了一个 StopWatch
StopWatch clock = new StopWatch();
clock.start(); //计时开始
Object result = invocation.proceed();
clock.stop();  //计时结束
//方法参数类型，转换成简单类型
Class[] params = invocation.getMethod().getParameterTypes();
String[] simpleParams = new String[params.length];
for (int i = 0; i < params.length; i++) {
simpleParams[i] = params[i].getSimpleName();
}
log.debug("Takes:" + clock.getTime() + " ms ["
+ invocation.getThis().getClass().getName() + "."
+ invocation.getMethod().getName() + "("+StringUtils.join(simpleParams,",")+")] ");
return result;
}
}
4) HelloService.java 被拦截的业务类


package com.unmi.service;   
  
/**  
* @author Unmi  
*/  
public class HelloService {   
    public void sayHello(int id,String name){   
        try {   
            Thread.sleep(512);   
        } catch (InterruptedException e) {   
            e.printStackTrace();   
        }   
        System.out.println("Hello "+name+"("+id+")");   
    }   
}  
package com.unmi.service;
/**
* @author Unmi
*/
public class HelloService {
public void sayHello(int id,String name){
try {
Thread.sleep(512);
} catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println("Hello "+name+"("+id+")");
}
}
5) Main.java 主程序类


package com.unmi;   
  
import org.springframework.beans.factory.BeanFactory;   
import org.springframework.context.support.ClassPathXmlApplicationContext;   
  
import com.unmi.service.HelloService;   
  
/**  
* 测试主类  
* @author Unmi  
*/  
public class Main {   
  
    /**  
     * @param args  
     */  
    public static void main(String[] args) {   
        BeanFactory factory =new ClassPathXmlApplicationContext("applicationContext.xml");   
        HelloService helloService = (HelloService)factory.getBean("helloService");   
        helloService.sayHello(1,"Unmi");   
    }   
}  
package com.unmi;
import org.springframework.beans.factory.BeanFactory;
import org.springframework.context.support.ClassPathXmlApplicationContext;
import com.unmi.service.HelloService;
/**
* 测试主类
* @author Unmi
*/
public class Main {
/**
* @param args
*/
public static void main(String[] args) {
BeanFactory factory =new ClassPathXmlApplicationContext("applicationContext.xml");
HelloService helloService = (HelloService)factory.getBean("helloService");
helloService.sayHello(1,"Unmi");
}
}
执行 Main 后输出的结果是：

Hello Unmi(1)
2008-01-18 13:41:25,593 [DEBUG] MethodTimeAdvice.invoke(34)
Takes:516 ms [com.unmi.service.HelloService.sayHello(int,String)]


如果不需要这个功能，只要在 applicationContext.xml 中把 id="methodTimeLog" 和 id="methodTimeAdvice" 配置项注释掉就行了。

2. Spring 通用的方法拦截

Spring 1.x 因为不能用 AspectJ 来对方法进行拦截，要用到 ProxyFactoryBean 使用 AOP，具体操作方法只需要更换以上例子中的 applicationContext.xml 文件就行，内容如下：



<?xml version="1.0" encoding="UTF-8"?>  
<!DOCTYPE beans PUBLIC "-//SPRING//DTD BEAN//EN"   
     "http://www.springframework.org/dtd/spring-beans.dtd">  
<beans>  
  
    <bean id="methodTimeAdvice" class="com.unmi.util.MethodTimeAdvice"/>  
    <bean id="helloServiceTarget" class="com.unmi.service.HelloService"/>  
       
    <bean id="methodTimeAdvisor"  
        class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">    
        <property name="advice">  
            <ref bean="methodTimeAdvice"/>    
        </property>    
        <!--对指定类的任何方法有效-->  
        <property name="patterns">    
            <value>.*.*</value>    
        </property>    
    </bean>  
       
    <bean id="helloService" class="org.springframework.aop.framework.ProxyFactoryBean">  
        <property name="interceptorNames">  
            <list>  
                <value>methodTimeAdvisor</value>  
            </list>  
        </property>  
        <property name="target">  
            <ref bean="helloServiceTarget"/>  
        </property>  
    </bean>  
       
</beans>  
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE beans PUBLIC "-//SPRING//DTD BEAN//EN"
"http://www.springframework.org/dtd/spring-beans.dtd">
<beans>
<bean id="methodTimeAdvice" class="com.unmi.util.MethodTimeAdvice"/>
<bean id="helloServiceTarget" class="com.unmi.service.HelloService"/>
<bean id="methodTimeAdvisor"
class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">
<property name="advice">
<ref bean="methodTimeAdvice"/>
</property>
<!--对指定类的任何方法有效-->
<property name="patterns">
<value>.*.*</value>
</property>
</bean>
<bean id="helloService" class="org.springframework.aop.framework.ProxyFactoryBean">
<property name="interceptorNames">
<list>
<value>methodTimeAdvisor</value>
</list>
</property>
<property name="target">
<ref bean="helloServiceTarget"/>
</property>
</bean>
</beans>

上面的配置方式需为每个应用方法执行时间记录的 Bean 在外层包一个 ProxyFactoryBean，原来的 Bean 设为一个 Target 实在时麻烦了。

下面用一种应用自动代理的配置方式，指定 BeanNameAutoProxyCreator 的 beanNames 匹配模式即可，如果写成 <value>*Service,*Manager</value>，逗号分隔开，以 Service 或 Manager 结层类的方法都被拦截，这样方便许多。


<?xml version="1.0" encoding="UTF-8"?>  
<!DOCTYPE beans PUBLIC "-//SPRING//DTD BEAN//EN"   
     "http://www.springframework.org/dtd/spring-beans.dtd">  
<beans>  
  
    <bean id="methodTimeAdvice" class="com.unmi.util.MethodTimeAdvice" />  
    <bean id="helloService" class="com.unmi.service.HelloService" />  
  
    <bean id="methodTimeAdvisor"  
        class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">  
        <property name="advice">  
            <ref bean="methodTimeAdvice" />  
        </property>  
        <!--对指定类的任何方法有效-->  
        <property name="patterns">  
            <value>.*.*</value>  
        </property>  
    </bean>  
  
    <!-- 根据 Bean 的名字自动实现代理拦截 -->  
    <bean  
        class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">  
        <property name="interceptorNames">  
            <list>  
                <value>methodTimeAdvisor</value>  
            </list>  
        </property>  
        <property name="beanNames">  
            <list>  
                <!-- 添加到其中的 Bean 自动就被代理拦截了 -->  
                <value>*Service</value>  
            </list>  
        </property>  
    </bean>  
</beans>  
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE beans PUBLIC "-//SPRING//DTD BEAN//EN"
"http://www.springframework.org/dtd/spring-beans.dtd">
<beans>
<bean id="methodTimeAdvice" class="com.unmi.util.MethodTimeAdvice" />
<bean id="helloService" class="com.unmi.service.HelloService" />
<bean id="methodTimeAdvisor"
class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">
<property name="advice">
<ref bean="methodTimeAdvice" />
</property>
<!--对指定类的任何方法有效-->
<property name="patterns">
<value>.*.*</value>
</property>
</bean>
<!-- 根据 Bean 的名字自动实现代理拦截 -->
<bean
class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">
<property name="interceptorNames">
<list>
<value>methodTimeAdvisor</value>
</list>
</property>
<property name="beanNames">
<list>
<!-- 添加到其中的 Bean 自动就被代理拦截了 -->
<value>*Service</value>
</list>
</property>
</bean>
</beans>

3. 直接用 AspectJ 实现

AspectJ 提供了一套语法来定义切面，Spring 2.0 开始引入了 AspectJ 的部分功能，但如果要用上 AspectJ 更多强大完善的功能，诸如实例构造时，属性被访问时，动态改变类定义，滋生新的属性、方法，更强基于流程的控制时，恐怕非得显式的使用 AspectJ。当然，首先你得去 http://www.eclipse.org/aspectj/ 下载到 AspectJ 或者 AspectJ 的 Eclipse 插件。本人强烈建议使用 AspectJ 的 Eclipse 插件，请下载相应 Eclipse 版本的 AspectJ 插件，Eclipse 3.3 要搭配 AJDT: The AspectJ Development Tools 1.5。不要插件的话就得命令行下 ajc 编译你的方面，不容易习惯的。

AJDT 安装成功后，你可以新建 AspectJ 项目，或者把前面项目转换成 AspectJ 项目。从项目的上下文菜单中可以看到 AspectJ Tools -> Convert to Aspectj Project。然后在包 com.unmi.util 中新建一个方面，包 com.unmi.util 的上下文菜单中 New -> Aspect，输入名字 MethodTimeAdviceRecipe，然后 Finish，这时就会在包 com.unmi.util 中产生一个文件 MethodTimeAdviceRecipe.aj，内容如下：

MethodTimeAdviceRecipe.aj (那么 MethodTimeAdvice.java 就派不上用场了，可删去)


package com.unmi.util;   
import org.apache.commons.lang.time.StopWatch;   
import org.apache.commons.logging.Log;   
import org.apache.commons.logging.LogFactory;   
  
  
/**  
* 记录方法的执行时间  
* @author Unmi  
*/  
public aspect MethodTimeAdviceRecipe {   
       
    protected final Log log = LogFactory.getLog(MethodTimeAdvice.class);   
       
    //拦截所有以 Service 结尾类的方法   
    pointcut callServicePointCut() : call(* *..*Service.*(..))   
                                        && !within(MethodTimeAdviceRecipe +);   
       
    /**  
     * 在方连接点(业务类方法)周围执行的通知  
     */  
    Object around() : callServicePointCut(){   
        //用 commons-lang 提供的 StopWatch 计时，Spring 也提供了一个 StopWatch   
        StopWatch clock = new StopWatch();   
        clock.start(); //计时开始   
        Object result = proceed();   
        clock.stop();  //计时结束   
           
        //显示出方法原型及耗时   
        log.debug("Takes: " + clock.getTime() + " ms ["+thisJoinPoint.getSignature()+"("+   
                thisJoinPoint.getSourceLocation().getLine()+")]");   
           
        return result;   
    }   
}  
package com.unmi.util;
import org.apache.commons.lang.time.StopWatch;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
/**
* 记录方法的执行时间
* @author Unmi
*/
public aspect MethodTimeAdviceRecipe {
protected final Log log = LogFactory.getLog(MethodTimeAdvice.class);
//拦截所有以 Service 结尾类的方法
pointcut callServicePointCut() : call(* *..*Service.*(..))
&& !within(MethodTimeAdviceRecipe +);
/**
* 在方连接点(业务类方法)周围执行的通知
*/
Object around() : callServicePointCut(){
//用 commons-lang 提供的 StopWatch 计时，Spring 也提供了一个 StopWatch
StopWatch clock = new StopWatch();
clock.start(); //计时开始
Object result = proceed();
clock.stop();  //计时结束
//显示出方法原型及耗时
log.debug("Takes: " + clock.getTime() + " ms ["+thisJoinPoint.getSignature()+"("+
thisJoinPoint.getSourceLocation().getLine()+")]");
return result;
}
}
再就是因为无需用到 Spring 了，不需要 IOC 了，相应的 Main.java 的内容如下：

Main.java (以前如何创建 HelloService，现在还是怎么做)


package com.unmi;   
  
import com.unmi.service.HelloService;   
  
/**  
* 测试主类  
* @author Unmi  
*/  
public class Main {   
  
    /**  
     * @param args  
     */  
    public static void main(String[] args) {   
        HelloService helloService = new HelloService();   
        helloService.sayHello(1,"Unmi");   
    }   
}  
package com.unmi;
import com.unmi.service.HelloService;
/**
* 测试主类
* @author Unmi
*/
public class Main {
/**
* @param args
*/
public static void main(String[] args) {
HelloService helloService = new HelloService();
helloService.sayHello(1,"Unmi");
}
}
OK，现在就可以在 Eclipse 中开始运行 Main 类了，对 methodTimeAdviceRecipe.aj 的编译工作由插件 AJDT 自动帮你作了(实质是相匹配的类中插入了代码)。运行 Main 的结果如下：

Hello Unmi(1)
2008-01-21 13:48:16,171 [DEBUG] MethodTimeAdvice.sayHello_aroundBody1$advice(130)
Takes: 515 ms [void com.unmi.service.HelloService.sayHello(int, String)(16)]

用 AspectJ 可以很灵活的定义方面，局限就是对方面的改变须重新编译相关类，而非配置方式。

参考：一个用Spring AOP实现异常处理和记录程序执行时间的实例




FORM:http://www.blogjava.net/Unmi/archive/2008/01/18/165849.html