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

chw0

2012-05-11

关注关注

[转载]用AOP来记录每个方法的执行时间

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

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

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

1.Spring2.0用AspectJ实现AOP

2.Spring通用的方法拦截

3.直接用AspectJ实现

1.Spring2.0用AspectJ实现AOP

这个实例由五个文件构成，两个配置文件和三个类文件。需要在项目中引用Spring2.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目录下

<beansxmlns="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/beanshttp://www.springframework.org/schema/beans/spring-beans-2.0.xsd

http://www.spridngframework.org/schema/aophttp://www.springframework.org/schema/aop/spring-aop-2.0.xsd">

<aop:config>

<aop:advisorid="methodTimeLog"advice-ref="methodTimeAdvice"pointcut="execution(**..service..*(..))"/>

</aop:config>

<beanid="methodTimeAdvice"class="com.unmi.util.MethodTimeAdvice"/>

<beanid="helloService"class="com.unmi.service.HelloService"/>

</beans>

<beansxmlns="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/beanshttp://www.springframework.org/schema/beans/spring-beans-2.0.xsd

http://www.spridngframework.org/schema/aophttp://www.springframework.org/schema/aop/spring-aop-2.0.xsd">

<aop:config>

<aop:advisorid="methodTimeLog"advice-ref="methodTimeAdvice"pointcut="execution(**..service..*(..))"/>

</aop:config>

<beanid="methodTimeAdvice"class="com.unmi.util.MethodTimeAdvice"/>

<beanid="helloService"class="com.unmi.service.HelloService"/>

</beans>

3)MethodTimeAdvice.java记录时间的类

packagecom.unmi.util;

importorg.aopalliance.intercept.MethodInterceptor;

importorg.aopalliance.intercept.MethodInvocation;

importorg.apache.commons.lang.StringUtils;

importorg.apache.commons.lang.time.StopWatch;

importorg.apache.commons.logging.Log;

importorg.apache.commons.logging.LogFactory;

/**

*记录方法的执行时间

*@authorUnmi

publicclassMethodTimeAdviceimplementsMethodInterceptor{

protectedfinalLoglog=LogFactory.getLog(MethodTimeAdvice.class);

/**

*拦截要执行的目标方法

publicObjectinvoke(MethodInvocationinvocation)throwsThrowable{

//用commons-lang提供的StopWatch计时，Spring也提供了一个StopWatch

StopWatchclock=newStopWatch();

clock.start();//计时开始

Objectresult=invocation.proceed();

clock.stop();//计时结束

//方法参数类型，转换成简单类型

Class[]params=invocation.getMethod().getParameterTypes();

String[]simpleParams=newString[params.length];

for(inti=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,",")+")]");

returnresult;

}

packagecom.unmi.util;

importorg.aopalliance.intercept.MethodInterceptor;

importorg.aopalliance.intercept.MethodInvocation;

importorg.apache.commons.lang.StringUtils;

importorg.apache.commons.lang.time.StopWatch;

importorg.apache.commons.logging.Log;

importorg.apache.commons.logging.LogFactory;

/**

*记录方法的执行时间

*@authorUnmi

publicclassMethodTimeAdviceimplementsMethodInterceptor{

protectedfinalLoglog=LogFactory.getLog(MethodTimeAdvice.class);

/**

*拦截要执行的目标方法

publicObjectinvoke(MethodInvocationinvocation)throwsThrowable{

//用commons-lang提供的StopWatch计时，Spring也提供了一个StopWatch

StopWatchclock=newStopWatch();

clock.start();//计时开始

Objectresult=invocation.proceed();

clock.stop();//计时结束

//方法参数类型，转换成简单类型

Class[]params=invocation.getMethod().getParameterTypes();

String[]simpleParams=newString[params.length];

for(inti=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,",")+")]");

returnresult;

}

4)HelloService.java被拦截的业务类

packagecom.unmi.service;

/**

*@authorUnmi

publicclassHelloService{

publicvoidsayHello(intid,Stringname){

try{

Thread.sleep(512);

}catch(InterruptedExceptione){

e.printStackTrace();

}

System.out.println("Hello"+name+"("+id+")");

}

packagecom.unmi.service;

/**

*@authorUnmi

publicclassHelloService{

publicvoidsayHello(intid,Stringname){

try{

Thread.sleep(512);

}catch(InterruptedExceptione){

e.printStackTrace();

}

System.out.println("Hello"+name+"("+id+")");

}

5)Main.java主程序类

packagecom.unmi;

importorg.springframework.beans.factory.BeanFactory;

importorg.springframework.context.support.ClassPathXmlApplicationContext;

importcom.unmi.service.HelloService;

/**

*测试主类

*@authorUnmi

publicclassMain{

/**

*@paramargs

publicstaticvoidmain(String[]args){

BeanFactoryfactory=newClassPathXmlApplicationContext("applicationContext.xml");

HelloServicehelloService=(HelloService)factory.getBean("helloService");

helloService.sayHello(1,"Unmi");

}

packagecom.unmi;

importorg.springframework.beans.factory.BeanFactory;

importorg.springframework.context.support.ClassPathXmlApplicationContext;

importcom.unmi.service.HelloService;

/**

*测试主类

*@authorUnmi

publicclassMain{

/**

*@paramargs

publicstaticvoidmain(String[]args){

BeanFactoryfactory=newClassPathXmlApplicationContext("applicationContext.xml");

HelloServicehelloService=(HelloService)factory.getBean("helloService");

helloService.sayHello(1,"Unmi");

}

执行Main后输出的结果是：

HelloUnmi(1)

2008-01-1813:41:25,593[DEBUG]MethodTimeAdvice.invoke(34)

Takes:516ms[com.unmi.service.HelloService.sayHello(int,String)]

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

2.Spring通用的方法拦截

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

<?xmlversion="1.0"encoding="UTF-8"?>

<!DOCTYPEbeansPUBLIC"-//SPRING//DTDBEAN//EN"

"http://www.springframework.org/dtd/spring-beans.dtd">

<beans>

<beanid="methodTimeAdvice"class="com.unmi.util.MethodTimeAdvice"/>

<beanid="helloServiceTarget"class="com.unmi.service.HelloService"/>

<beanid="methodTimeAdvisor"

class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">

<propertyname="advice">

<refbean="methodTimeAdvice"/>

</property>

<propertyname="patterns">

</property>

</bean>

<beanid="helloService"class="org.springframework.aop.framework.ProxyFactoryBean">

<propertyname="interceptorNames">

<list>

<value>methodTimeAdvisor</value>

</list>

</property>

<propertyname="target">

<refbean="helloServiceTarget"/>

</property>

</bean>

</beans>

<?xmlversion="1.0"encoding="UTF-8"?>

<!DOCTYPEbeansPUBLIC"-//SPRING//DTDBEAN//EN"

"http://www.springframework.org/dtd/spring-beans.dtd">

<beans>

<beanid="methodTimeAdvice"class="com.unmi.util.MethodTimeAdvice"/>

<beanid="helloServiceTarget"class="com.unmi.service.HelloService"/>

<beanid="methodTimeAdvisor"

class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">

<propertyname="advice">

<refbean="methodTimeAdvice"/>

</property>

<propertyname="patterns">

</property>

</bean>

<beanid="helloService"class="org.springframework.aop.framework.ProxyFactoryBean">

<propertyname="interceptorNames">

<list>

<value>methodTimeAdvisor</value>

</list>

</property>

<propertyname="target">

<refbean="helloServiceTarget"/>

</property>

</bean>

</beans>

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

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

<?xmlversion="1.0"encoding="UTF-8"?>

<!DOCTYPEbeansPUBLIC"-//SPRING//DTDBEAN//EN"

"http://www.springframework.org/dtd/spring-beans.dtd">

<beans>

<beanid="methodTimeAdvice"class="com.unmi.util.MethodTimeAdvice"/>

<beanid="helloService"class="com.unmi.service.HelloService"/>

<beanid="methodTimeAdvisor"

class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">

<propertyname="advice">

<refbean="methodTimeAdvice"/>

</property>

<propertyname="patterns">

</property>

</bean>

<bean

class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">

<propertyname="interceptorNames">

<list>

<value>methodTimeAdvisor</value>

</list>

</property>

<propertyname="beanNames">

<list>

<value>*Service</value>

</list>

</property>

</bean>

</beans>

<?xmlversion="1.0"encoding="UTF-8"?>

<!DOCTYPEbeansPUBLIC"-//SPRING//DTDBEAN//EN"

"http://www.springframework.org/dtd/spring-beans.dtd">

<beans>

<beanid="methodTimeAdvice"class="com.unmi.util.MethodTimeAdvice"/>

<beanid="helloService"class="com.unmi.service.HelloService"/>

<beanid="methodTimeAdvisor"

class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">

<propertyname="advice">

<refbean="methodTimeAdvice"/>

</property>

<propertyname="patterns">

</property>

</bean>

<bean

class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">

<propertyname="interceptorNames">

<list>

<value>methodTimeAdvisor</value>

</list>

</property>

<propertyname="beanNames">

<list>

<value>*Service</value>

</list>

</property>

</bean>

</beans>

3.直接用AspectJ实现

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

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

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

packagecom.unmi.util;

importorg.apache.commons.lang.time.StopWatch;

importorg.apache.commons.logging.Log;

importorg.apache.commons.logging.LogFactory;

/**

*记录方法的执行时间

*@authorUnmi

publicaspectMethodTimeAdviceRecipe{

protectedfinalLoglog=LogFactory.getLog(MethodTimeAdvice.class);

//拦截所有以Service结尾类的方法

pointcutcallServicePointCut():call(**..*Service.*(..))

&&!within(MethodTimeAdviceRecipe+);

/**

*在方连接点(业务类方法)周围执行的通知

Objectaround():callServicePointCut(){

//用commons-lang提供的StopWatch计时，Spring也提供了一个StopWatch

StopWatchclock=newStopWatch();

clock.start();//计时开始

Objectresult=proceed();

clock.stop();//计时结束

//显示出方法原型及耗时

log.debug("Takes:"+clock.getTime()+"ms["+thisJoinPoint.getSignature()+"("+

thisJoinPoint.getSourceLocation().getLine()+")]");

returnresult;

}

packagecom.unmi.util;

importorg.apache.commons.lang.time.StopWatch;

importorg.apache.commons.logging.Log;

importorg.apache.commons.logging.LogFactory;

/**

*记录方法的执行时间

*@authorUnmi

publicaspectMethodTimeAdviceRecipe{

protectedfinalLoglog=LogFactory.getLog(MethodTimeAdvice.class);

//拦截所有以Service结尾类的方法

pointcutcallServicePointCut():call(**..*Service.*(..))

&&!within(MethodTimeAdviceRecipe+);

/**

*在方连接点(业务类方法)周围执行的通知

Objectaround():callServicePointCut(){

//用commons-lang提供的StopWatch计时，Spring也提供了一个StopWatch

StopWatchclock=newStopWatch();

clock.start();//计时开始

Objectresult=proceed();

clock.stop();//计时结束

//显示出方法原型及耗时

log.debug("Takes:"+clock.getTime()+"ms["+thisJoinPoint.getSignature()+"("+

thisJoinPoint.getSourceLocation().getLine()+")]");

returnresult;

}

再就是因为无需用到Spring了，不需要IOC了，相应的Main.java的内容如下：

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

packagecom.unmi;

importcom.unmi.service.HelloService;

/**

*测试主类

*@authorUnmi

publicclassMain{

/**

*@paramargs

publicstaticvoidmain(String[]args){

HelloServicehelloService=newHelloService();

helloService.sayHello(1,"Unmi");

}

packagecom.unmi;

importcom.unmi.service.HelloService;

/**

*测试主类

*@authorUnmi

publicclassMain{

/**

*@paramargs

publicstaticvoidmain(String[]args){

HelloServicehelloService=newHelloService();

helloService.sayHello(1,"Unmi");

}

OK，现在就可以在Eclipse中开始运行Main类了，对methodTimeAdviceRecipe.aj的编译工作由插件AJDT自动帮你作了(实质是相匹配的类中插入了代码)。运行Main的结果如下：

HelloUnmi(1)

2008-01-2113:48:16,171[DEBUG]MethodTimeAdvice.sayHello_aroundBody1$advice(130)

Takes:515ms[voidcom.unmi.service.HelloService.sayHello(int,String)(16)]

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

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

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

aop log4j xmlns schema

安科网

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

chw0

chw0

相关推荐

Spring学习六、AOP与整合Mybatis

你敢信？面试官竟然让我现场搭建一个AOP测试环境！

声明式事务

浅析Spring AOP术语

利用Spring AOP切面对用户访问进行监控

Spring入门到进阶 - Spring AOP

个人技术总结

Spring AOP

Spring基础之AOP

mybatis plus + AOP 多数据源自动切换

spring AOP

Spring-Lesson2

Mybatis 使用Spring boot AOP +自定义注解+PageHelper实现分页

AOP的定义和原理

Spring AOP面向切面编程3种实现方式

Spring中的AOP底层原理探讨

FluentAspects -- 基于 Fluent API 的 Aop

【Spring框架学习】AOP机制详解

spring面试题

支付宝支付

chw0