有时候我们要跟踪方法的执行时间,来观察系统的性能、时间分布。特别是要找出那些十分耗时的操作。如果是在每个方法中起始和结束位置记下时间相减,那是不太现实的,对代码的侵入性太过份,而且在产品环境中又得屏闭那部份代码。
幸好现在有了 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
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>
-
- <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;
-
-
-
-
-
- public class MethodTimeAdvice implements MethodInterceptor {
- protected final Log log = LogFactory.getLog(MethodTimeAdvice.class);
-
-
-
-
- public Object invoke(MethodInvocation invocation) throws Throwable {
-
- 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;
-
-
-
-
- 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;
-
-
-
-
-
- public class Main {
-
-
-
-
- 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>
上面的配置方式需为每个应用方法执行时间记录的 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
- class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">
- <property name="interceptorNames">
- <list>
- <value>methodTimeAdvisor</value>
- </list>
- </property>
- <property name="beanNames">
- <list>
-
- <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;
-
-
-
-
-
-
- public aspect MethodTimeAdviceRecipe {
-
- protected final Log log = LogFactory.getLog(MethodTimeAdvice.class);
-
-
- pointcut callServicePointCut() : call(* *..*Service.*(..))
- && !within(MethodTimeAdviceRecipe +);
-
-
-
-
- Object around() : callServicePointCut(){
-
- 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;
-
-
-
-
-
- public class Main {
-
-
-
-
- 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