Spring AOP 切面编程记录日志和接口执行时间

最近客户现在提出系统访问非常慢,需要优化提升访问速度,在排查了nginx、tomcat内存和服务器负载之后,判断是数据库查询速度慢,进一步排查发现是因为部分视图和表查询特别慢导致了整个系统的响应时间特别长。知道了问题之后,就需要对查询比较慢的接口进行优化,但哪些接口需要优化、哪些不需要呢?只能通过日志里的执行时间来判断,那么如何才能知道每一个接口的执行时间呢?

如果想学习Java工程化、高性能及分布式、深入浅出。微服务、Spring,MyBatis,Netty源码分析的朋友可以加我的Java高级交流:854630135,群里有阿里大牛直播讲解技术,以及Java大型互联网技术的视频免费分享给大家。


对于这个问题,想到了使用动态代理的方式统一记录方法的执行时间并打印日志,这样就能很直观、方便的看到每个接口的执行时间了。

由于使用的是spring框架,对象都是由spring统一管理的,所以最后使用的是 Spring AOP 切面编程来统一记录接口的执行时间,具体代码如下(基于注解的方式):

@Component

@Aspect

public class AopLoggerAspect {

    private static final Logger logger = Logger.getLogger(AopLoggerAspect.class);

    @Pointcut("execution(public * com.iflytek.credit.platform.*.service.impl.*Impl.*(..)) || execution(public * com.iflytek.credit.platform.*.controller.*Controller.*(..))")

    public void pointCut() {

    }

    @Before("pointCut()")

    public void boBefore(JoinPoint joinPoint) {

        String methodName = joinPoint.getSignature().getName();

        logger.info("Method Name : [" + methodName + "] ---> AOP before ");

    }

    @After("pointCut()")

    public void doAfter(JoinPoint joinPoint) {

        String methodName = joinPoint.getSignature().getName();

        logger.info("Method Name : [" + methodName + "] ---> AOP after ");

    }

    @AfterReturning(pointcut = "pointCut()",returning = "result")

    public void afterReturn(JoinPoint joinPoint, Object result) {

        String methodName = joinPoint.getSignature().getName();

        logger.info("Method Name : [" + methodName + "] ---> AOP after return ,and result is : " + result.toString());

    }

    @AfterThrowing(pointcut = "pointCut()",throwing = "throwable")

    public void afterThrowing(JoinPoint joinPoint, Throwable throwable) {

        String methodName = joinPoint.getSignature().getName();

        logger.info("Method Name : [" + methodName + "] ---> AOP after throwing ,and throwable message is : " + throwable.getMessage());

    }

    @Around("pointCut()")

    public Object around(ProceedingJoinPoint joinPoint) {

        String methodName = joinPoint.getSignature().getName();

        try {

            logger.info("Method Name : [" + methodName + "] ---> AOP around start");

            long startTimeMillis = System.currentTimeMillis();

            //调用 proceed() 方法才会真正的执行实际被代理的方法

            Object result = joinPoint.proceed();

            long execTimeMillis = System.currentTimeMillis() - startTimeMillis;

            logger.info("Method Name : [" + methodName + "] ---> AOP method exec time millis : " + execTimeMillis);

            logger.info("Method Name : [" + methodName + "] ---> AOP around end , and result is : " + result.toString());

            return result;

        } catch (Throwable te) {

            logger.error(te.getMessage(),te);

            throw new RuntimeException(te.getMessage());

        }

    }

}

首先,需要创建一个类,然后在类名上加上两个注解

@Component

@Aspect

@Component 注解是让这个类被spring当作一个bean管理,@Aspect 注解是标明这个类是一个切面对象

类里面每个方法的注解含义如下:

@Pointcut  用于定义切面的匹配规则,如果想要同事匹配多个的话,可以使用 || 把两个规则连接起来,具体可以参照上面的代码

@Before  目标方法执行前调用

@After  目标方法执行后调用

@AfterReturning  目标方法执行后调用,可以拿到返回结果,执行顺序在 @After 之后

@AfterThrowing  目标方法执行异常时调用

@Around  调用实际的目标方法,可以在目标方法调用前做一些操作,也可以在目标方法调用后做一些操作。使用场景有:事物管理、权限控制,日志打印、性能分析等等

以上就是各个注解的含义和作用,重点的两个注解就是 @Pointcut 和 @Around 注解,@Pointcut用来指定切面规则,决定哪些地方使用这个切面;@Around 会实际的去调用目标方法,这样就可以在目标方法的调用前后做一些处理,例如事物、权限、日志等等。

需要注意的是,这些方法的执行顺序:

执行目标方法前: 先进入 around ,再进入 before 

目标方法执行完成后: 先进入 around ,再进入 after ,最后进入 afterreturning 

实际的日志信息如下,可以看出各个方法的执行顺序:


另外,使用spring aop 需要在spring的配置文件加上以下这行配置,以开启aop :

<aop:aspectj-autoproxy/>

同时,maven中需要加入依赖的jar包:

<dependency>

  <groupId>org.aspectj</groupId>

  <artifactId>aspectjrt</artifactId>

  <version>1.6.12</version>

</dependency>

<dependency>

  <groupId>org.aspectj</groupId>

  <artifactId>aspectjweaver</artifactId>

  <version>1.6.12</version>

</dependency>

总结一下,Spring AOP 其实就是使用动态代理来对切面层进行统一的处理,动态代理的方式有:JDK动态代理和 cglib 动态代理,JDK动态代理基于接口实现, cglib 动态代理基于子类实现。spring默认使用的是JDK动态代理,如果没有接口,spring会自动的使用cglib动态代理。

如果想学习Java工程化、高性能及分布式、深入浅出。微服务、Spring,MyBatis,Netty源码分析的朋友可以加我的Java高级交流:854630135,群里有阿里大牛直播讲解技术,以及Java大型互联网技术的视频免费分享给大家

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 203,772评论 6 477
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,458评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,610评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,640评论 1 276
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,657评论 5 365
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,590评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,962评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,631评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,870评论 1 297
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,611评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,704评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,386评论 4 319
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,969评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,944评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,179评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 44,742评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,440评论 2 342

推荐阅读更多精彩内容