用 AOP 回记录每个方法的执行时间(Spring 或直接 AspectJ)
有时候我们要跟踪方法的执行时间，来观察系统的性能、时间分布。特别是要找出那些十分耗时的操作。如果是在每个方法中起始和结束位置记下时间相减，那是不太现实的，对代码的侵入性太过份，而且在产品环境中又得屏闭那部份代码。 幸好现在有了 AOP，通过配置方式再加上外部辅助代码就能达到我们的要求，正式上线时只需要简单改个配置项拆卸下来即可。 下面介绍三种方式来打印每个方法的执行时间，分别是： 1. Spring 2.0 用 AspectJ 实现 AOP 1. Spring 2.0 用 AspectJ 实现 AOP 这个实例由五个文件构成，两个配置文件和三个类文件。需要在项目中引用 Spring 2.0 以上版本的相关包，还要日志包。 1) log4j.properties 放在 src 目录下 2) applicationContext.xml 放在 src 目录下 3) MethodTimeAdvice.java 记录时间的类 4) HelloService.java 被拦截的业务类 5) Main.java 主程序类 执行 Main 后输出的结果是： Hello Unmi(1) 如果不需要这个功能，只要在 applicationContext.xml 中把 id="methodTimeLog" 和 id="methodTimeAdvice" 配置项注释掉就行了。 2. Spring 通用的方法拦截 Spring 1.x 因为不能用 AspectJ 来对方法进行拦截，要用到 ProxyFactoryBean 使用 AOP，具体操作方法只需要更换以上例子中的 applicationContext.xml 文件就行，内容如下： 上面的配置方式需为每个应用方法执行时间记录的 Bean 在外层包一个 ProxyFactoryBean，原来的 Bean 设为一个 Target 实在时麻烦了。 下面用一种应用自动代理的配置方式，指定 BeanNameAutoProxyCreator 的 beanNames 匹配模式即可，如果写成 <value>*Service,*Manager</value>，逗号分隔开，以 Service 或 Manager 结层类的方法都被拦截，这样方便许多。 3. 直接用 AspectJ 实现 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 就派不上用场了，可删去) 再就是因为无需用到 Spring 了，不需要 IOC 了，相应的 Main.java 的内容如下： Main.java (以前如何创建 HelloService，现在还是怎么做) OK，现在就可以在 Eclipse 中开始运行 Main 类了，对 methodTimeAdviceRecipe.aj 的编译工作由插件 AJDT 自动帮你作了(实质是相匹配的类中插入了代码)。运行 Main 的结果如下： Hello Unmi(1) 用 AspectJ 可以很灵活的定义方面，局限就是对方面的改变须重新编译相关类，而非配置方式。
2. Spring 通用的方法拦截
3. 直接用 AspectJ 实现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
<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>
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.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;
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");
}
}
2008-01-18 13:41:25,593 [DEBUG] MethodTimeAdvice.invoke(34)
Takes:516 ms [com.unmi.service.HelloService.sayHello(int,String)]<?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="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>
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 编译你的方面，不容易习惯的。 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;
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");
}
}
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)]