上个月接了个有点“刁钻”的需求:把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-class=true,因为让所有业务类都去实现接口在今天已经不太现实。这个机制的副作用也要心里有数:被代理的类,它的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> <groupId>org.springframework.boot</groupId> <artifactId>spring-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根本不会把它扫描成Bean,@Aspect不会生效。
第二步,确认切入表达式里的包路径和实际业务类的包路径一致。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拦截虽然方便,但维护成本会随项目膨胀而增大。一个更优雅的演进方向是定义自己的监控注解,比如@Timed:
@Target(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或者耗时操作的地方,要么异步,要么挪出主链路。环绕通知是把双刃剑,用得巧妙,它就是系统的透视镜;用得太随意,它就是暗藏在调用链下的性能陷阱。希望这篇文章能让你拿到这把剑的时候,知道该往哪儿挥。