ARTICLE DETAIL

资讯详情

深耕网站建设与运营推广的一线实战洞察。

Spring AOP环绕通知实战:统计所有带参方法耗时,业务代码零侵入

Spring AOP环绕通知实战:统计所有带参方法耗时,业务代码零侵入 上个月接了个有点“刁钻”的需求把Service层所有带参数方法的执行时间一个不落地统计出来线上每隔一段时间出一份报表而且业务代码一行都不能改。当时我的第一反应是“这不就是给每个方法前后加日志嘛”但真让我手工去加看着上百个Service方法改完代码基本就废了后面维护成本更吓人。后来切到Spring AOP用环绕通知把整套统计逻辑收敛到一个切面类里十几行代码解决了问题。这篇文章就顺着这个场景展开把环绕通知从原理到落地完整拆一遍包括切入点表达式怎么匹配“所有带参方法”、为什么我们需要调用proceed()、生产环境里会遇到哪些坑以及这套能力还能延伸到什么方向。适合正在学Spring Boot AOP、或者工作中真要搞方法级监控的同学直接参考。1. 先把需求理解透这是要给Service层装一台“秒表”1.1 这个需求到底在解决什么问题“统计所有带参方法的执行时间”听起来很简单但真正落地的时候有几个隐性要求。第一范围限定在Service层因为Controller层方法数量少但Service层是整个业务逻辑的核心地带方法数量多、调用频繁性能问题往往也藏在这里。第二它说的是“带参方法”说明需求方对无参方法不感兴趣一般是希望把入参、耗时、方法名关联起来看这样一旦出现慢接口能立刻定位是哪组参数触发了性能瓶颈。第三要求不修改业务代码这意味着任何埋点都不能侵入原有方法体。这种需求的本质是在一个固定的业务逻辑之外横向切出一条“计时通道”。每个方法调用时记录调用前的时间点执行完后再记录一次两者做差就是方法耗时。这里最合适的工具就是AOP因为它天生就是为了处理“横切关注点”设计的。日志、事务、权限校验、性能统计这些和业务逻辑没有直接关系但又必须存在的动作就是典型的横切关注点。1.2 为什么不用手动埋点大概三年前我做第一个性能统计需求时也是从手动埋点开始的。工具类写好后在每个要统计的方法开头和结尾各加一行代码long start System.currentTimeMillis(); // 业务逻辑 long cost System.currentTimeMillis() - start; log.info(method {} cost {} ms, doBiz, cost);这个方法在小范围内完全可行可一旦扩展到几十个、上百个方法问题就开始暴露了。首先是代码污染每加一个统计点业务方法里就多出几行跟业务无关的逻辑别说代码review自己看久了都难受。其次是容易遗漏人不是机器写了二十个方法还能记得把统计点加上写到第五十个必然漏漏了的还不好查。最后是关闭成本如果哪天上线后发现问题需要临时关闭这些统计你得把所有业务方法再动一遍这个操作本身又引入了新的风险。手动埋点的致命伤是统计逻辑和业务逻辑搅在一起违反了单一职责原则。用AOP来搞统计逻辑只存在于切面类里业务方法保持干净需要调整统计策略的时候只需要改切面完全不用碰业务代码这才是维护性更好的方案。1.3 为什么“环绕通知”是这场需求的唯一正解Spring AOP一共提供了五类通知前置通知Before、后置返回通知AfterReturning、后置异常通知AfterThrowing、后置最终通知After、环绕通知Around。前四类想完成耗时统计会撞上一个硬问题计时开始和结束的“状态”无法跨通知共享。前置通知里记录了开始时间后置通知里想拿到这个时间得用ThreadLocal或者往类成员变量里放单线程还好高并发下一旦变量互相覆盖统计的数据全是乱的。环绕通知不一样它是把“整个方法调用”包在一个方法体里开始、执行、结束、异常全在一个逻辑块里完成。你可以这样理解前置通知像是进门时按一下秒表后置通知像是出门时按一下秒表但这两个动作之间隔着一整段业务逻辑秒表上的数据要跨过这段逻辑传递中间不可控因素太多。环绕通知则像是把这个方法装进一个密封的实验室你在外面挂一个计时器什么时候开始、什么时候暂停、什么时候看结果全程都由你掌控。这也决定了环绕通知的灵活度是最高的。你不仅能在方法执行前后做统计还能在中途修改方法的参数、篡改返回结果、捕获异常后做降级处理。比如某些场景下你可以在环绕通知里判断入参如果参数不合法干脆不执行目标方法直接返回一个兜底数据。这是其他几类通知做不到的。2. 环绕通知背后的运行机制代理、切点与proceed()2.1 五类通知的定位对比先把五类通知放一张表里方便对照记忆通知类型触发时机能否访问方法前后状态典型场景Before目标方法执行前只能看到方法执行前状态权限校验、参数校验AfterReturning目标方法正常返回后只能拿到返回值返回值加工、日志记录AfterThrowing目标方法抛出异常后只能拿到异常对象统一异常处理、告警After目标方法结束后无论正常还是异常拿不到方法执行结果资源清理、释放连接Around目标方法执行全过程前后状态都能掌握耗时统计、事务控制、熔断限流Around是唯一一个能同时掌控“调用前”、“执行过程”、“返回结果”、“异常情况”的通知类型。其他通知像是给方法设置的几个不同观察窗口环绕通知则是你把整个方法握在手里。2.2 Spring AOP的代理机制不是魔法是“替身”很多初学者会把Spring AOP和AspectJ混为一谈。Spring AOP的底层是动态代理它不是在编译阶段修改字节码而是在运行时为目标Bean生成一个代理对象然后把切面逻辑编织在代理对象的调用过程里。调用方真正拿到手的是代理对象代理替代目标对象运行所以Spring AOP也叫“基于代理的AOP”。这里有两个分支JDK动态代理和CGLIB代理。JDK动态代理要求目标类实现接口它生成的代理对象是目标接口的实现类。CGLIB则通过生成目标类的子类来完成代理不要求接口。Spring Boot 2.x之后默认使用CGLIB也就是spring.aop.proxy-target-classtrue因为让所有业务类都去实现接口在今天已经不太现实。这个机制的副作用也要心里有数被代理的类它的final方法没法被拦截private方法也没法被拦截因为CGLIB生成子类时根本没法覆盖final方法private方法根本不参与代理调用链。理解“代理”这个本质对排查问题帮助很大。后面我们会遇到“同一个类里方法互相调用切面不生效”这个经典问题原因就是用this.method()这种内部调用走的是原始对象根本没经过代理对象切面自然无从谈起。2.3ProceedingJoinPoint.proceed()整个环绕通知的心脏环绕通知的方法签名里有一个特殊参数ProceedingJoinPoint它继承了JoinPoint接口并把目标方法的所有信息带进来方法签名、参数数组、目标对象。其中最核心的方法就是proceed()。Object result joinPoint.proceed();这行代码是环绕通知中的关键一步。proceed()的意思是“继续执行”调用链它会沿着拦截器链依次调用后续的切面逻辑最终通过反射执行真正的目标方法。所以凡是写了环绕通知就必须调用proceed()否则目标方法根本不会执行。我习惯把proceed()类比成“接力棒的传递”。环绕通知就像站在跑到中段的接力手你拿到了棒子调用权得继续往前传业务方法才能跑起来。如果你拿着棒子站在那儿不动后面的运动员全都晾着整个业务链路就是死的。不是所有场景都需要立刻调用proceed()这正是环绕通知灵活的地方。比如你想实现一个简单的限流功能可以在环绕通知里检查当前并发数如果超过阈值就直接返回一个降级结果压根不调用proceed()。但作为耗统计这类需求proceed()必须被调用而且要放在我们计时的核心区间内。3. 实操统计所有带参方法耗时的完整实现3.1 依赖准备与工程前提我默认你手上已经有一个能正常启动的Spring Boot项目如果是第一次接触Spring Boot先把基础工程跑通再来看这一部分。要给项目加入AOP能力需要在pom.xml里添加如下依赖dependency groupIdorg.springframework.boot/groupId artifactIdspring-boot-starter-aop/artifactId /dependency这个依赖会帮我们引入spring-aop和aspectjweaver前者是Spring AOP的核心库后者提供了AspectJ的注解解析能力。Spring Boot的自动配置会在检测到Aspect类时自动创建代理不需要额外手动开启EnableAspectJAutoProxy。如果你不是Spring Boot项目用纯Spring框架才需要手动加EnableAspectJAutoProxy。另外一个前提是要确保目标类被Spring容器管理。切面只会拦截Spring容器中的Bean如果某个Service类是用new直接创建的根本没进容器AOP对它无能为力。实际项目中我确实遇过这类问题排查了很久最后发现是一个工具类没有交给容器管理而是在某个类加载时手动实例化的。3.2 第一个可运行的环绕通知切面先写一个最简单版本把所有方法的耗时统计出来包括带参和无参的Component Aspect Slf4j public class MethodTimerAspect { Around(execution(* com.example.blog.service..*.*(..))) public Object logMethodTime(ProceedingJoinPoint joinPoint) throws Throwable { MethodSignature signature (MethodSignature) joinPoint.getSignature(); String methodName signature.getDeclaringTypeName() . signature.getName(); long start System.nanoTime(); Object result joinPoint.proceed(); long cost System.nanoTime() - start; log.info(方法[{}]耗时[{}]ns, methodName, cost); return result; } }逐行拆解这段代码。Aspect和Component标记这个类是一个切面组件交给Spring容器托管。Around注解里的字符串就是切入点表达式execution(* com.example.blog.service..*.*(..))的含义是匹配com.example.blog.service包及其子包下所有类的所有方法。表达式中*第一次出现的位置表示返回值类型这里用通配符代表任意返回类型..代表任意包的子包最后的(..)代表任意参数列表。方法名字可以随便起关键是第一个参数必须是ProceedingJoinPoint。我通过MethodSignature拿到方法签名拼出完整的方法名然后调用proceed()执行目标方法最后用System.nanoTime()计算耗时。这段代码执行后控制台会打印出所有方法的执行时间。3.3 只匹配“带参方法”切入点表达式的进阶玩法需求里明确要求“统计所有带参方法”我的第一个版本会把无参方法也统计进来。想精确匹配“只带参数的方法”切入点表达式这样写Around(execution(* com.example.blog.service..*.*(..)) !args())这里args()在AspectJ表达式里是一个特殊匹配条件它只匹配运行时参数个数为0的方法执行连接点。前面加了一个!取反也就是说方法的执行连接点必须满足execution(...)条件同时不能是零参数方法。组合起来的效果就是匹配所有参数个数大于等于1的方法。这个表达式里的args()大家容易绕晕我展开说明一下。args()括号为空表示“零参数”注意它和(..)是两回事。(..)是execution里面用来匹配“方法签名支持任意参数列表”的符号是静态签名层面的匹配。而args()是动态运行时参数层面的匹配它关注的是“实际调用这个连接点的时候传了几个参数”。所以!args()就等价于“实际调用时至少传了一个参数”。我不建议用args(*, ..)这种写法因为它的语义是“第一个参数必须是某种具体类型”需要指定类型名比如args(String, ..)只匹配第一个参数是String的方法这显然不是我们想要的“所有带参方法”。有些资料里会用args(..)来匹配但它其实等价于不限制参数数量无参方法照样会被匹配进去。验证这个表达式是否生效很简单在切面里打一个初始化日志然后启动项目观察控制台。如果观察到的拦截方法确实都有参数说明表达式正确如果还有无参方法被拦到检查一下是不是表达式里的包名路径写宽了或者项目里存在多个切面对同一方法进行了重复拦截。3.4 完整版异常也要统计时间精度要用纳秒第一个版本有个隐患如果目标方法抛出异常joinPoint.proceed()这一行会中断后面的耗时计算代码根本执行不到。这就意味着你只能统计到“成功执行”的方法耗时而线上性能分析最需要关注的恰恰是那些出错的方法。用try...finally修复Component Aspect Slf4j public class MethodTimerAspect { private static final Logger log LoggerFactory.getLogger(MethodTimerAspect.class); Around(execution(* com.example.blog.service..*.*(..)) !args()) public Object logMethodTime(ProceedingJoinPoint joinPoint) throws Throwable { MethodSignature signature (MethodSignature) joinPoint.getSignature(); String methodName signature.getDeclaringTypeName() . signature.getName(); Object[] args joinPoint.getArgs(); long start System.nanoTime(); try { return joinPoint.proceed(); } finally { long cost System.nanoTime() - start; log.info(方法[{}]入参[{}]耗时[{}]ns, methodName, Arrays.toString(args), cost); } } }这里finally块保证了不管目标方法正常返回还是抛出异常耗时统计都能执行。需要注意finally块中的代码不能吞掉异常所以不能在finally里做try之外的大动作原异常会沿着调用链继续抛出去交给上层处理。为什么用System.nanoTime()而不是System.currentTimeMillis()因为currentTimeMillis返回的是墙上时钟时间它可能被系统的时钟调整影响而且毫秒精度对于多数方法来说不够用。一个方法耗时几百微秒currentTimeMillis根本测不出来差异。nanoTime是专门用来测量时间间隔的高精度时钟虽然它的起点不确定但两个时间点之间的差值精度在纳秒级做性能统计更合适。不过纳秒换算成毫秒时要注意单位我一般在落库或展示时统一除以1000000转换成毫秒。3.5 参数记录注意事项上面代码里我用了Arrays.toString(args)直接打印参数数组这在本地调试完全够用但上生产环境要谨慎。第一是敏感信息泄露问题用户手机号、身份证、密码这类数据一旦打进日志就是重大安全事故。我实际项目里会把参数序列化成JSON然后对敏感字段做脱敏处理。第二是参数对象如果没有重写toString()方法默认输出是对象哈希值啥也看不出来。要让日志有排障价值我会在入参对象里重写toString()或者通过JSON序列化工具统一处理。第三是参数过多、对象过大的情况比如某个方法传了一个大文件或大列表全量打印日志会把磁盘打爆日志系统也会被拖垮。这种情况下我建议只记录参数的长度、数量、关键ID而不是打印完整参数内容。4. 生产环境里最常遇到的五类坑和排查思路4.1 切面写了日志一条都不出这是我在社群里看到问得最多的问题也是排查链条最长的问题。日志不出现意味着切入点压根没有匹配到任何方法或者切面本身就没有被Spring加载。排查步骤一般这样走第一步确认切面类上有Component注解。没有这个注解Spring根本不会把它扫描成BeanAspect不会生效。第二步确认切入表达式里的包路径和实际业务类的包路径一致。com.example.blog.service..*这里的..表示匹配任意子包但service这个单词如果拼错了或者实际类在service.impl子包下表达式会直接落空。第三步确认目标类是Spring容器中的Bean。如果Spring Boot启动没有报错业务方法也能正常调用但切面不生效可以在切面构造器里打一条初始化日志看启动时有没有打印。没打印就说明切面没加载。第四步检查Spring Boot版本。2.x和3.x虽然都支持spring-boot-starter-aop但3.x基于Java 17和Jakarta命名空间如果你的项目里有大量老第三方库不兼容可能连启动都过不去。再往前排查一点有些老项目会手动加EnableAspectJAutoProxy和Spring Boot自动配置叠加后偶尔出现异常删掉手动配置往往就好了。4.2 方法执行了但结果不对或者方法压根没执行这种问题多半出在proceed()调用本身。最常见的错误是切面里写了条件分支if (someCondition) { return joinPoint.proceed(); } // 忘了else里的 proceed() return null;条件不满足时方法直接被短路返回了一个空值业务数据当然不对。我在实现限流逻辑时也干过这种事当时想的是“超过阈值就拦截”结果判断条件写反了正常流量全被挡掉业务方反馈“接口返回空空如也”排查了半天才发现是条件分支的逻辑反了。另一个新手容易犯的错是在环绕通知里直接return joinPoint.proceed()但代码里手动把proceed()的结果强转成了某个具体的返回类型而实际返回值类型不匹配运行期就抛ClassCastException。稳妥的做法是环绕通知的返回类型声明为Object业务层需要强转时由调用方去转。4.3 方法执行了两遍遇到这种情况先深呼吸查查是不是这个类的切面表达式被匹配了两次。一个很隐蔽的坑是切入表达式写得太宽同一个方法被两个不同的通知织入了。比如你在切面里写了两个Around一个用execution(* com.example.service..*.*(..))另一个用annotation(SomeTimed)而目标方法恰好既在子包范围内、又加了注解它就会被两套逻辑先后包裹看起来像是执行了两遍。真正的方法重复执行更常见的原因是同一个类里方法自调用。比如ServiceA里有方法a()内部调用this.b()而b()是一个有切面的方法。因为this.b()调用发生在目标对象内部不经过Spring代理所以切面对b()是不会生效的。但如果你在a()上也配置了环绕通知并且拦截成功后手动调了两次proceed()那就真的会重复执行。谁会把proceed()调两次我只见过一次是新同事在两边代码里各放了一个return joinPoint.proceed()分支老代码没删干净。排查方法执行两次最直接的方式是在切面里打印调用栈Thread.currentThread().getStackTrace()看看两次调用分别从哪个入口发起的很快就能锁定位。4.4 统计出来的耗时不准确这里有一个从系统时间到业务逻辑的常见陷阱。第一如果你用currentTimeMillis这个时间本身受系统NTP校准影响线上环境偶尔会出现时钟跳变一瞬间统计出来的耗时可能变成负数或者异常大。nanoTime没有这个问题。第二第一次调用某个方法时JVM需要完成类加载、即时编译热点识别、动态代理初始化耗时会明显偏高这会让第一次统计数据和后续数据差距巨大。我通常会在统计模块里加一个“暖机”过滤项目启动后前N次调用不统计或者至少在心里有个数不要被首调数据误导。第三环绕通知本身也有开销。你写的切面逻辑越重对方法耗时的扰动就越大。如果切面里做了日志序列化、磁盘IO、数据库写入那统计出来的数字本身就包含了这些额外开销性能数据失真。真正线上监控时我会把切面里的日志输出做成异步化或者把统计数据先暂存在内存队列里批量刷入监控系统。4.5 事务和切面的执行顺序问题Transactional在Spring中的底层机制也是AOP所以同一个方法上如果既有事务注解、又有环绕通知两个“代理逻辑”会形成一个调用链。执行顺序决定了一切。我踩过一个经典的坑环绕通知里把异常吞了然后返回一个兜底值结果Transactional事务拦截器看到的是“正常返回”事务提交了但底层数据库操作已经因为前面的异常回滚了一部分导致数据不一致。看起来业务正常完成实际上数据库里的数据是残缺的。解决办法是环绕通知不要轻易吞异常。就像我们上面的完整版代码一样让异常通过throws Throwable继续抛出。Spring的事务拦截器会根据抛出的异常决定是否需要回滚。如果确实需要控制多个切面的执行顺序用Order注解或者实现Ordered接口数字越小优先级越高。比如Order(1)的环绕通知会先于Order(2)的执行。5. 从“统计耗时”延伸出的三种实用组合5.1 把参数日志做成线上排障的“黑匣子”统计耗时只是环绕通知的起点。我后来在这个切面上加了一层增强把关键方法的入参、出参、异常信息全部记录到独立的日志文件里单独设置日志滚动策略。业务方反馈“某个订单查不到”时我可以直接去日志文件里搜订单号马上能看到当时的完整调用链省去了让业务方反复复现问题的痛苦。这个做法的核心可控点是日志量。全量打印所有方法的出入参会把日志系统撑爆所以我只针对有AuditLog注解的方法开启这个功能。配合annotation切入点表达式把这些方法挑选出来单独织入逻辑。5.2 做成可配置开关随时下线生产环境里的性能统计不能永远开着因为AOP的反射调用本身有性能成本。我通常把统计开关做成配置项在application.yml里放一个字段切面内部读取配置判断是否开启。用ConditionalOnProperty也是不错的选择它能在配置关闭时连切面Bean都不创建。Component Aspect ConditionalOnProperty(name app.method-time-stat.enabled, havingValue true) public class MethodTimerAspect { // ... }这样切面的存在与否完全由配置控制。需要排查问题时开启问题排查完关闭全程不需要动业务代码。如果你们用的是Apollo或Nacos这类配置中心还能做到动态启停灵活性更强。5.3 结合自定义注解做定点监控全量AOP拦截虽然方便但维护成本会随项目膨胀而增大。一个更优雅的演进方向是定义自己的监控注解比如TimedTarget(ElementType.METHOD) Retention(RetentionPolicy.RUNTIME) public interface Timed { }然后在环绕通知里通过annotation(timed)绑定这个注解只在显式标记了Timed的方法上做统计。这个策略相当于从“把所有方法都纳入监控”过渡到“监控那些真正需要关注的方法”既融合了AOP的便捷又不至于因为切入面过宽而引发性能波动。这篇文章里我主要用的是execution表达式和!args()组合但它只覆盖了场景的一小角。AOP切入点表达式还有within、annotation、args、bean等多种玩法掌握了这些组合之后能做的就不只是统计耗时还有接口鉴权、多租户数据隔离、操作审计、缓存处理等等。如果你正在做“第一个Spring Boot程序”到“带参方法耗时统计”这类的实训项目最简单的验证路径就是先把Spring Boot工程跑起来再引入spring-boot-starter-aop写一个环绕通知切面然后启动项目看日志输出。这个流程走通AOP对你来说就不再是停留在文档里的概念了。最后说点私货。我初次用环绕通知时觉得它不过是一个“能拿到前后时间点”的注解直到有一次在真线上环境排查一个诡异的性能抖动发现是同事在环绕通知里对参数做了JSON序列化后写到日志文件硬生生把一个本来只要2毫秒的方法拖到了200毫秒。从那次以后我给自己定了条规矩任何切面代码逻辑复杂度绝不允许超过十行凡是要做IO或者耗时操作的地方要么异步要么挪出主链路。环绕通知是把双刃剑用得巧妙它就是系统的透视镜用得太随意它就是暗藏在调用链下的性能陷阱。希望这篇文章能让你拿到这把剑的时候知道该往哪儿挥。
返回列表