Spring AOP实践-统计Action层方法执行时间

发表于 | 分类于 | |

1.目标

  • 背景：
    基于Spring+Strust2+Ibatis 的JAVA Web项目，后台实现分传统的3层结构，dao层，service层，action层。业务调用链一般为 action层–> service层 –> dao层。

  • 目标：
    统计Action层某个方法的执行时间，只需要在该方法上加入一个注解便可以打印出该方法的执行时间。（通过Action层统计方法，基本能粗略统计从客户发起到完成请求反馈给前台页面的总时间。）

2.项目环境

基于Spring Strust2 Ibatis JAVA Web项目

  • spring-XXX-3.0.5.RELEASE.jar
  • aspectjrt-1.6.8.jar
  • struts2-core-2.3.24.jar
  • log4j-1.2.17.jar
    （等）

3.通过Spring AOP 实现

3.1 注解类（为统计方法上加入该注解）

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
package com.rocklei123.annotaion;

import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

/**
 * @Title: rocklei123 用于记录方法耗时
 * @Description:
 * @Author: rocklei123
 * @Date: 2018/8/10 17:59
 * @Version: 1.0
 */
@Target({ElementType.METHOD, ElementType.TYPE})
@Retention(RetentionPolicy.RUNTIME)
@Documented
public @interface MethodPerformanceLog {
    String module() default "";  //功能模块
    String remark() default ""; // 操作备注
    String operateType() default ""; // 操作类型：Add/Update/Delete/Search/Login等
}

3.2 log4j 配置（单独生成文件并按日期滚动）

%l 表示：输出日志事件的发生位置，包括类目名、发生的线程，以及在代码中的行数

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
loglevel=DEBUG
log4j.rootLogger=${loglevel},stdout,perfile
log4j.logger.com.mchange=ERROR
log4j.logger.org.apache=ERROR
log4j.logger.org.springframework=ERROR
log4j.logger.org.apache.catalina=ERROR
log4j.logger.org.apache.struts2=ERROR
log4j.logger.org.apache.struts2.util.StrutsTypeConverter=ERROR
log4j.logger.com.opensymphony.xwork2=ERROR
log4j.logger.org.quartz=ERROR
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=[sqlrobe] %d{yyyy-MM-dd HH:mm:ss SSS} [%-5p] %t(%c:%L) - %m%n
log4j.appender.perfile=org.apache.log4j.DailyRollingFileAppender
log4j.appender.perfile.File=${catalina.base}/logs/sqlrobe/sqlrobe.log
log4j.appender.perfile.layout.ConversionPattern=[sqlrobe] %d{yyyy-MM-dd HH:mm:ss SSS} [%-5p] %t(%c:%L) - %m%n
log4j.appender.perfile.layout=org.apache.log4j.PatternLayout
log4j.appender.perfile.threshold=DEBUG
log4j.appender.perfile.DatePattern='.'yyyy-MM-dd
log4j.appender.perfile.BufferedIO=true
log4j.appender.perfile.BufferSize=8192

##middleware
log4j.logger.middleware=${loglevel},middleware    
log4j.appender.middleware=org.apache.log4j.DailyRollingFileAppender   
log4j.appender.middleware.File=${catalina.base}/logs/sqlrobe/middleware.log
log4j.appender.middleware.DatePattern='.'yyyy-MM-dd
log4j.appender.middleware.layout=org.apache.log4j.PatternLayout  
log4j.appender.middleware.layout.ConversionPattern=[middleware] %d{yyyy-MM-dd HH:mm:ss SSS} [%-5p] %t(%l) - %m%n
log4j.additivity.middleware=false

3.3 利用 Spring AOP的思想来统计方法执行时间并打印

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
package com.rocklei123.aop;

import org.apache.log4j.Logger;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;

/**
 * @Title: sqlrobe
 * @Description:
 * @Author: rocklei123
 * @Date: 2018/8/10 17:59
 * @Version: 1.0
 */
@Aspect
public class PerformanceMonitorMiddleware {
    //日志记录
    private static final Logger logger = Logger.getLogger("middleware");

    // 一分钟，即60000ms。为超过一分钟的方法统计到日志中
    private static final long ONE_MINUTE = 60000;

    //定义切点
    @Pointcut("@annotation(com.approbe.annotaion.MethodPerformanceLog)")
    public void methodCachePointcut() {

    }

    /**
     * 统计方法执行耗时Around环绕通知
     *
     * @param joinPoint
     * @return
     */
    @Around("methodCachePointcut()")
    public Object timeAround(ProceedingJoinPoint joinPoint) {
        // 定义返回对象、得到方法需要的参数
        Object obj = null;
        Object[] args = joinPoint.getArgs();
        long startTime = System.currentTimeMillis();

        try {
            obj = joinPoint.proceed(args);
        } catch (Throwable e) {
            e.printStackTrace();
            logger.error("统计某方法执行耗时环绕通知出错", e);
        }

        // 获取执行的方法名
        long endTime = System.currentTimeMillis();
        MethodSignature signature = (MethodSignature) joinPoint.getSignature();
        String methodName = signature.getDeclaringTypeName() + "." + signature.getName();

        // 打印耗时的信息
        this.printExecTime(methodName, startTime, endTime);
        return obj;
    }

    /**
     * 打印方法执行耗时的信息，如果超过了一定的时间，才打印
     *
     * @param methodName
     * @param startTime
     * @param endTime
     */
    private void printExecTime(String methodName, long startTime, long endTime) {
        long diffTime = endTime - startTime;
        //超过1分钟的方法单独打印
        if (diffTime > ONE_MINUTE) {
            logger.warn("-----" + methodName + " 方法执行耗时：" + diffTime + " ms");
        }
        logger.info("--------------------------------------------" + methodName + " 方法执行耗时：" + diffTime + " ms");
        System.out.println("--------------------------------------" + methodName + " 方法执行耗时：" + diffTime + " ms");
    }
}

3.4 Spring 配置文件配置

1
2
3
4
5
6
7
<aop:config>
    <aop:aspect id="performenceMonitorMiddlewareAop" ref="performenceMonitorMiddleware"/>
</aop:config>
  <!-- 注入bean-->
<bean id="performenceMonitorMiddleware" class="com.approbe.aop.PerformanceMonitorMiddleware"></bean>
<!-- 强制使用cglib代理-->
<aop:aspectj-autoproxy proxy-target-class="true"/>

为什么强制使用cglib代理呢？

spring的动态代理如果不指定，他会根据类的信息来进行代理，如果类有接口的会使用JDK的动态代理，如果类没有接口的就会使用cglib，因为struts2的ActionSupport是有实现接口的，所以他用了JDK的动态代理，那样你类中自己的属性自然就没有了。而你指定了使用cglib，那他就会动态生成一个继承你这个Action的子类，自然你Action类中可供子类访问的属性都有了。 不过struts2有自己的拦截器没必要也是不建议用spring的AOP 出处：http://bbs.csdn.net/topics/390630278

3.5 Struts2 配置文件配置

分析：一般struts2+spring应用中，spring的插件只负责action的ioc部分，但并没有进行功能加强，即采用代理的机制，所有的action还是使用struts2进行管理，在使用AOP后，这些action需要由spring进行管理，如果没有被spring进行呢代理，将出现注入失败。

1
2
  <!-- 让struts2始终先考虑spring的自动装箱-->
<constant name="struts.objectFactory.spring.autoWire.alwaysRespect" value="true" />

故如果不增加这句话，Action 中的service方法为空。会报空指针异常：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

java.lang.NullPointerException
	at com.approbe.middlware.action.WlsServerInfoAction.updateWlsBySystemId(WlsServerInfoAction.java:92)
	at com.approbe.middlware.action.WlsServerInfoAction$$FastClassByCGLIB$$2291828.invoke(<generated>)
	at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:191)
	at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:688)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:91)
	at com.approbe.aop.PerformanceMonitorMiddleware.timeAround(PerformanceMonitorMiddleware.java:46)
	at sun.reflect.GeneratedMethodAccessor543.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)

3.6 实现效果

  • 在希望统计的方法上加注释
1
2
3
4
5
6
7
8
9

@RequestMapping("updateWlsBySystemId")
@MethodPerformanceLog(module = "中间件批量修改/中间件树结构管理", remark = "更新功能", operateType = "更新")
@Transactional
public void updateWlsBySystemId() throws IOException {
    System.out.println("更新系统------------------------");
    middlewareLogger.info("更新系统----------------");
    String remoteAddr = GetRemoteAddrUtil.getRemoteIpAddr(request);
    String requestUserName = HttpSessionUtil.getSessionUserName(request);
  • 执行方法打印执行时间
1
--------------------------------------com.approbe.middlware.action.WlsServerInfoAction.updateWlsBySystemId 方法执行耗时：6853 ms

4.参考

京东jinnianshilongnian 《java开发常见问题分析》 http://jinnianshilongnian.iteye.com/category/283252

京东jinnianshilongnian 《请不要再使用低级别的AOP API》 http://jinnianshilongnian.iteye.com/blog/1901694

《spring aop拦截action配置》 https://blog.csdn.net/unei66/article/details/9422339

5.欢迎关注米宝窝，持续更新中，谢谢！

米宝窝 https://rocklei123.github.io/

-------------本文结束感谢您的阅读-------------
欢迎持续关注米宝窝，定期更新谢谢！ https://rocklei123.github.io/
欢迎持续关注我的CSDN https://blog.csdn.net/rocklei123
rocklei123的技术点滴
熬夜写博客挺辛苦的，生怕猝死，所以每当写博客都带着听诊器，心脏一有异响，随时按Ctrl+S。
rocklei123 微信支付

微信支付

rocklei123 支付宝

支付宝