Spring AOP日志切面实战：从环绕通知到脱敏与失效排查

1. 先把概念掰开：AOP 究竟在解决什么麻烦

“日志”这两个字，写业务代码的人大概都有过某个瞬间：接口上线第三天，业务方反馈某条数据不对，你打开日志文件，发现只有一行“请求进入”和一行“请求结束”，中间发生了什么完全是空白。于是你回去往每个 Service 方法的第一行塞log.info，塞到第十个方法的时候开始怀疑人生——这些代码和业务逻辑一点关系都没有，却占了屏幕的三分之一。面向切面编程（AOP）就是为了处理这类“横切关注点”才被提出来的编程范式，而日志记录几乎是它最经典、也最容易讲清楚的落地场景。这篇内容我会从项目里反复出现的重复日志现场讲起，把切面、切点、通知、织入这几个概念用大白话拆开，再手写一个能往生产环境放的日志切面，覆盖入参采集、耗时统计、异常记录、链路 ID 注入、敏感字段脱敏这几件事，最后把“切面为什么没生效”这类高频坑逐个复盘。适合已经能写增删改查、但还没系统用过 AOP 的开发者，也适合用过注解式切面却总被失效问题绕晕的人对照排查。

1.1 从一个重复代码现场说起

我印象最深的一次是在一个订单履约模块里做排查。那个模块有十来个 Service 方法，每个方法的开头都是三行：记录入参、打一个开始时间戳、记录当前登录用户；结尾又是三行：记录返回值、算出耗时、把耗时打出来。中间夹着真正的业务逻辑，只有两行。也就是说，一个方法六行日志代码包着两行业务，比例是三比一。当时的直接后果不是难看，而是维护成本：某次要求把日志里的手机号改脱敏，我和另外两个同事分别改了自己负责的那批方法，改完还有人漏了两个，因为那两个方法是用 IDE 模板生成的，格式跟别的不一样。

这类代码有个共同特征：它们横着切过了所有业务方法，跟“下单”“扣库存”“生成流水”这些纵向的业务功能没有关系，但每个业务方法都躲不掉。业内把这叫横切关注点，日志、权限校验、事务控制、缓存、限流、埋点统计都属于这一类。AOP 的思路很直接：既然这些东西在每个方法里长得都差不多，那就别写在方法里了，把它抽出来，声明“我要贴在哪些方法上”，剩下的交给框架在运行时自动拼上去。

这么做的价值不在于代码短了几行，而在于关注点分离。业务方法只管业务，日志格式要改的时候只改一个地方，脱敏规则要调整的时候只动一处，新加一个接口忘了写日志这种事从根上就不会再发生。

1.2 五个名词一次讲透

AOP 的概念词不多，但第一次看文档容易被绕晕，我用一个寄快递的类比把它们串起来。

这里最容易混的是连接点和切点。连接点在 Spring AOP 里其实只有一个类型——方法执行，理论上每个方法执行都是连接点，但你不能对所有方法都织入，所以要写切点表达式去筛。比如execution(* com.example.order.service..*.*(..))就是一句话：“order 包下 service 子包里所有类的所有方法，参数不限，返回值不限”。切点表达式写得好不好，直接决定了切面是精准打击还是误伤一片。

通知的类型要记清楚，一共五种：@Before在目标方法前执行，@After在方法返回或抛异常后都执行，@AfterReturning只在正常返回后执行，@AfterThrowing只在抛异常后执行，@Around则把目标方法整个包起来，可以自己决定调不调用、什么时候调用、要不要改返回值。做日志和耗时统计，基本只用@Around，因为只有它能同时拿到“方法开始前”和“方法结束后”两个时刻，还能捕获异常不算破坏原有调用链。

1.3 AOP 补的是 OOP 的哪块短板

总有人问 AOP 是不是要取代 OOP。不是，也取代不了。OOP 解决的是“纵向”的抽象问题——把订单、库存、用户这些实体建模成类，用继承和多态来组织结构；AOP 解决的是“横向”的重复问题——把散落在各个类里的同一段逻辑收拢。一个系统里纵向的分层（Controller、Service、DAO）是 OOP 的功劳，而穿越这三层的东西，比如链路追踪 ID，就适合用 AOP 处理。

打个比方，一栋楼的承重墙、房间隔断是 OOP，而贯穿所有楼层的电梯井、水管、电路就是横切关注点。你可以选择在每间房里单独装一套水管，也可以选择集中走一套管道系统。前者一定能用，但越往后维护越要命。

需要提前说清一点：AOP 不是只有日志这一种用途。事务的@Transactional、方法级权限的@PreAuthorize、异步的@Async、缓存的@Cacheable，底层都是同一套代理机制。理解了日志切面，这几个注解“为什么在有些情况下失效”的问题就一起通了。

2. 技术选型：日志场景为什么落在 Spring AOP 上

决定用 AOP 之后，下一个问题是怎么实现。可选的路其实有三条：手写静态代理、用 JDK 动态代理、用 Spring AOP。这三条不是随便挑，各有明确的适用边界。

2.1 三条路的对比

静态代理最笨但也最可控：为每个目标类写一个包装类，在包装类里调日志再调真实方法。缺点是类会翻倍，接口一改代理也要跟着改，二十个 Service 就是二十个代理类，很快就没人愿意维护了。它适合那种只有两三个类、又完全不想引三方库的极端场景。

JDK 动态代理在运行时生成代理类，不用手写，但有个硬性要求：目标类必须实现接口，而且只能代理接口里声明的方法。如果人家写的是个没有接口的类，JDK 代理直接没辙。

Spring AOP 是第三种，它在上面两者之上又包了一层，根据目标类是否实现接口自动在 JDK 动态代理和 CGLIB 之间切换。Spring Boot 2.x 之后默认统一走 CGLIB，所以类没有接口也能代理。加上@Aspect注解声明式写法，业务代码零侵入，代价只是一点点代理开销，对绝大多数业务系统完全可以忽略。

我的判断很简单：只要是 Spring 体系里的业务项目，日志切面就选 Spring AOP，没有第二个答案。除非你在做的是框架层、连 Spring 都不想引，那才回去考虑后两者。

2.2 代理机制决定了它的能力边界

Spring AOP 的本质是在运行时生成一个代理对象放在容器里，你从容器里getBean拿到的那玩意儿，类型上写着OrderServiceImpl，实际上可能是 CGLIB 生成的子类。调用方拿到的是代理，代理在转发给真实对象之前和之后，才有机会执行切面逻辑。

这个“运行时代理”的实现方式带来两个绕不开的后果，也是后面所有失效问题的根因：

第一，方法必须是外部调用进来的。《Effective Java》里那句“优先使用组合”在这里换个角度理解：如果对象内部用this.methodB()调自己，这个this是真实对象而不是代理对象，请求根本没经过代理，切面自然不会触发。这在事务注解上表现得最明显——同类内部调用@Transactional方法，事务不生效，很多人第一次遇到以为是配置错了，其实是代理没被路过。

第二，被代理的方法不能是 final、private、static 的。CGLIB 靠继承生成子类并覆写方法，final 方法覆写不了；private 方法子类看不见，覆写无从谈起；static 方法属于类本身而不是实例，代理对象对它没有任何拦截能力。这三个限制在写切面之前就该心里有数，避免写完发现“某个方法就是不出日志”。

2.3 切面负责采集，落盘交给日志框架

这里有个容易被新手混淆的点：切面不负责“写文件”。日志最终落到哪、用什么格式、是否异步、是否按天滚动，全部是 SLF4J + 具体实现（Logback 或 Log4j2）的活。切面的职责是在正确的时机、把正确的上下文塞进日志调用。

所以我给切面的定位是“数据采集器”：它只负责拿到方法名、入参、返回值、耗时、异常这几类信息，然后log.info(...)交给日志框架。真正要调格式的时候，比如统一加个[traceId]前缀，应该在logback-spring.xml的pattern里干，而不是在切面里拼字符串。这个分工一旦理清，后面无论换日志实现还是调整输出格式，都不用动切面代码。

顺带提一句性能上的门道。日志调用本身有开销，即使级别被过滤掉，参数字符串拼接也已经做了；所以一定用 SLF4J 的占位符写法log.info("args={}", json)，别用字符串加号拼接，更别在切面里对入参做“反正都要拼”的无条件 JSON 序列化——这个话题后面单独讲，它是个实打实的性能坑。

3. 动手实现：一个可以往生产放的日志切面

下面这套代码我在两个项目里用过并调整过几轮，核心思路是“注解声明 + 环绕通知 + 可配置采集粒度”。注解让你能精细控制哪个方法打详细日志、哪个方法只打耗时；环绕通知把整个方法的生命周期包住；配置项用来防住大对象序列化这种事故。

3.1 依赖与工程骨架

Maven 里需要三样东西：spring-boot-starter-aop（它会把 AspectJ 的注解解析器和 AOP 自动配置带进来）、一个日志实现、一个 JSON 库。注意不要引 AspectJ 的完整aspectjweaver之外的东西去手动配置，Spring Boot 的自动配置已经够用。

<dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-aop</artifactId> </dependency> <dependency> <groupId>com.fasterxml.jackson.core</groupId> <artifactId>jackson-databind</artifactId> </dependency>

目录结构我习惯这么放，把“注解”和“切面”分开，后面别的模块要复用注解，只引注解所在的包就行：

com.example.demo ├── log │ ├── OpLog.java // 自定义注解 │ ├── OpLogAspect.java // 切面实现 │ └── LogUtils.java // 序列化、脱敏、截断工具 └── service └── OrderService.java // 业务类，方法上打 @OpLog

3.2 自定义注解：把采集粒度做成开关

为什么不直接用切点表达式匹配所有 Service 方法？因为那样你没法按方法控制输出内容。查询接口要打印返回值，删除接口只关心成功了没，有的方法入参里带着一整张图片的 Base64，如果统一处理，日志体积会失控。所以注解上带几个参数，让调用方自己决定。

@Target({ElementType.METHOD, ElementType.TYPE}) @Retention(RetentionPolicy.RUNTIME) @Documented public @interface OpLog { /** 业务模块，用于日志检索 */ String module() default ""; /** 动作描述，为空时用方法名 */ String action() default ""; /** 是否打印入参 */ boolean printArgs() default true; /** 是否打印返回值 */ boolean printResult() default true; /** 单个参数序列化后的最大长度，超出截断 */ int maxLength() default 1000; }

注释里的@Target同时支持方法和类，是有意为之：很多时候整块 Service 都想要日志，那就在类上打一个，方法上不用重复标注。@Retention(RUNTIME)是硬要求，运行时可读才能被切面反射到。maxLength给默认值 1000，是个经验数字——绝大多数业务对象的 JSON 都在 500 字符以内，超过 1000 的基本都是列表或者大字段，这时候截断比全量输出更有价值，因为你要找的关键信息往往在开头。

3.3 切面主体：环绕通知的完整骨架

先看完整代码，然后逐段拆解。

@Aspect @Component @Order(1) public class OpLogAspect { private static final Logger log = LoggerFactory.getLogger(OpLogAspect.class); private static final ObjectMapper MAPPER = new ObjectMapper(); @Pointcut("@annotation(com.example.demo.log.OpLog) || @within(com.example.demo.log.OpLog)") public void opLogPointcut() { } @Around("opLogPointcut()") public Object around(ProceedingJoinPoint pjp) throws Throwable { MethodSignature signature = (MethodSignature) pjp.getSignature(); Method method = AopUtils.getMostSpecificMethod(signature.getMethod(), pjp.getTarget().getClass()); OpLog opLog = AnnotatedElementUtils.findMergedAnnotation(method, OpLog.class); if (opLog == null) { opLog = AnnotatedElementUtils.findMergedAnnotation(pjp.getTarget().getClass(), OpLog.class); } String module = opLog == null ? "" : opLog.module(); String action = (opLog == null || opLog.action().isEmpty()) ? method.getName() : opLog.action(); long start = System.nanoTime(); try { Object result = pjp.proceed(); long cost = (System.nanoTime() - start) / 1_000_000; log.info("[{}] {}.{} 完成, cost={}ms, args={}, result={}", module, pjp.getTarget().getClass().getSimpleName(), action, cost, opLog != null && opLog.printArgs() ? LogUtils.safeJson(pjp.getArgs(), opLog.maxLength()) : "hidden", opLog != null && opLog.printResult() ? LogUtils.safeJson(result, opLog.maxLength()) : "hidden"); return result; } catch (Throwable t) { long cost = (System.nanoTime() - start) / 1_000_000; log.error("[{}] {}.{} 异常, cost={}ms, args={}", module, pjp.getTarget().getClass().getSimpleName(), action, cost, opLog != null && opLog.printArgs() ? LogUtils.safeJson(pjp.getArgs(), opLog.maxLength()) : "hidden", t); throw t; } } }

几个地方值得单独说。

第一，@Order(1)。切面默认顺序是Ordered.LOWEST_PRECEDENCE，也就是最低优先级。如果你项目里还有事务切面、权限切面，顺序会直接影响日志内容。举个具体的例子：如果日志切面在事务提交之前就执行完了，那么你在日志里看到的“成功”其实只代表方法返回了，事务晚一点回滚了你也看不出来。把日志切面放在最外层（数值小）通常更合理，因为它能完整地包住整个调用链，异常也能被它先捕获到。

第二，@annotation和@within两个切点用||连起来。@annotation匹配“方法上有注解”，@within匹配“类上有注解”，两者是互补的。只写@annotation，类级别标注就失效了；只写@within，方法级别标注又管不到。两个都写，用起来才符合直觉。

第三，AopUtils.getMostSpecificMethod这行不是多余的。这里踩过坑：如果你的方法定义在接口里、注解打在实现类上，signature.getMethod()拿到的是接口方法，接口方法上没有注解，getAnnotation直接返回 null，切面就静默不生效了。用这个方法把“接口方法 + 实现类”解析成实现类上的真实方法，再去找注解才稳。

第四，异常要throw t。环绕通知里捕获了异常不抛出去，等于把业务异常吞了，上层还以为是正常返回，这个 bug 比没有日志严重一百倍。日志记完必须原样抛出，保持调用链语义不变。

3.4 用System.nanoTime而不是currentTimeMillis

耗时统计用什么计时，很多人不在意，随手System.currentTimeMillis()就上了。单体应用里大部分时候看不出问题，但线上机器做 NTP 校时的时候，系统时钟可能回拨，这时候算出来的耗时是负数，日志里出现一个cost=-37ms，排查的人会一头雾水。

System.nanoTime()返回的是单调时钟，只用于测量时间间隔，不受系统时间调整影响，精度也更高（纳秒级）。除以1_000_000转毫秒，以long存储，数字不会溢出。这条经验值不了几个字，但能帮你少一次半夜被叫起来看负数的经历。

顺便说个副产物：这个耗时是包括代理调用、参数序列化在内的全链路时间，比方法内部的耗时略大一点点。如果你需要更精确的方法内耗时，得配合字节码增强工具或者 Micrometer 的@Timed，对绝大多数业务排查来说衰减到毫秒级的这个数字完全够用。

3.5 入参序列化：坑最多的一段代码

日志切面里最容易被低估的就是参数转字符串这一步。我总结下来有四个必须处理的问题。

问题一：循环引用。对象之间有双向关联是常事，比如订单持有用户引用、用户又持有订单列表。Jackson 默认序列化无限递归，直接StackOverflowError。解法是给ObjectMapper打开特定配置，或者在实体上加@JsonIgnore，但后者侵入业务代码，不太优雅。我倾向于在全局配置里关掉失败抛异常并开启循环引用检测。

问题二：不可序列化的类型。InputStream、MultipartFile、HttpServletRequest、byte[]，这些扔给 Jackson 要么报错要么吐出一堆乱码。这几个类型极其常见——只要你的方法带了文件上传参数，切面就会挂。所以序列化之前必须做类型白名单/黑名单过滤。

问题三：懒加载异常。如果用 JPA/Hibernate，从ProceedingJoinPoint拿到的入参可能是代理对象，序列化时触发懒加载，抛LazyInitializationException，而这个异常会让本来正常的业务方法直接失败。这个坑最阴，因为日志切面把业务搞挂了，属于典型的“辅助代码反噬主流程”。

问题四：大对象拖慢响应。一个返回 5000 条记录的列表接口，序列化成 JSON 再拼进日志，可能耗时几十毫秒甚至上百毫秒，日志文件一天涨几个 GB。

下面是我用的工具方法，思路是“全部 try-catch 兜住，出任何问题返回一个可读的占位符，绝不影响主流程”：

public class LogUtils { private static final ObjectMapper MAPPER = new ObjectMapper() .configure(SerializationFeature.FAIL_ON_EMPTY_BEANS, false) .configure(SerializationFeature.WRITE_DATES_AS_TIMESTAMPS, false) .setSerializationInclusion(JsonInclude.Include.NON_NULL); static { MAPPER.registerModule(new JavaTimeModule()); MAPPER.enable(SerializationFeature.WRITE_ENUMS_USING_TO_STRING); } public static String safeJson(Object target, int maxLength) { if (target == null) { return "null"; } if (target instanceof Object[]) { return safeJson(Arrays.asList((Object[]) target), maxLength); } if (isUnsafe(target)) { return target.getClass().getSimpleName() + "(skipped)"; } try { String json = MAPPER.writeValueAsString(target); return truncate(json, maxLength); } catch (Exception e) { return target.getClass().getSimpleName() + "(serialize-failed)"; } } private static boolean isUnsafe(Object o) { return o instanceof InputStream || o instanceof OutputStream || o instanceof MultipartFile || o instanceof ServletRequest || o instanceof ServletResponse || o instanceof byte[]; } private static String truncate(String s, int maxLength) { if (s == null) { return "null"; } return s.length() <= maxLength ? s : s.substring(0, maxLength) + "...(" + s.length() + ")"; } }

truncate后面的(...)里补上原始长度，是个小设计：你看到... (12876)就知道被截了，需要完整数据可以去别的途径找；如果只看到...你会以为日志就这些，误判成参数缺失。

3.6 敏感字段脱敏：别让日志变成隐患

这是很多团队上线之后才被要求补的一环。手机号、身份证号、银行卡号、密码、token，直接打进日志文件等于把用户隐私抄了一份放在服务器上。最省事的做法是在序列化之后对字符串做正则替换，虽然粗暴但足够覆盖绝大多数场景。

private static final Pattern PHONE = Pattern.compile("(1[3-9]\\d)\\d{4}(\\d{4})"); private static final Pattern ID_CARD = Pattern.compile("(\\d{6})\\d{8}(\\d{3}[0-9Xx])"); private static final Pattern PASSWORD_FIELD = Pattern.compile("(\"(?:password|pwd|token|secret)\"\\s*:\\s*\")([^\"]*)(\")", Pattern.CASE_INSENSITIVE); public static String desensitize(String json) { if (json == null) { return null; } json = PHONE.matcher(json).replaceAll("$1****$2"); json = ID_CARD.matcher(json).replaceAll("$1********$2"); json = PASSWORD_FIELD.matcher(json).replaceAll("$1******$3"); return json; }

注意PASSWORD_FIELD那条，必须大小写不敏感匹配字段名，否则Password、passWord各种写法都会漏。这种基于 JSON 字符串的正则方案有局限——如果字段值里本身就含有类似手机号的数字串，可能被误伤。有更高要求的场景可以做基于注解的字段级脱敏，用反射拿到字段上的@Sensitive标记，序列化前把值替换掉，代价是实现复杂度上升一个档次。我的建议是：默认用正则方案，等真出了脱敏不彻底的问题再升级。

还有一条硬规矩：异常堆栈里也可能带敏感信息。有些框架的异常信息会把 SQL 参数拼进去，log.error打完整堆栈的时候等于间接泄露。这个只能靠日志规约来卡，比如要求 DAO 层不要打印带参数的 SQL，或者对异常 message 也过一遍脱敏函数。

3.7 链路 ID：一个 MDC 就把日志串起来了

排查线上问题时，最痛苦的是日志混在一起。同一个接口被 200 个用户同时调，日志文件里 200 个请求的信息交错在一行行里，你根本分不清哪几行属于同一次调用。解法是给每次请求生成一个唯一 ID，塞进 MDC，然后在日志的 pattern 里引用它。

@Around("opLogPointcut()") public Object aroundWithTrace(ProceedingJoinPoint pjp) throws Throwable { boolean needClear = MDC.get("traceId") == null; if (needClear) { MDC.put("traceId", UUID.randomUUID().toString().replace("-", "").substring(0, 16)); } try { return around(pjp); } finally { if (needClear) { MDC.remove("traceId"); } } }

needClear这个判断有讲究。如果上游（比如网关的 Filter）已经塞了 traceId，切面就不该覆盖，也不该清掉，否则一个请求在日志里会分成两段独立的链路。只有当前线程确实没有的时候才自己生成，用完自己清，用完不清的后果是线程池复用线程时脏数据会带进下一个请求，那个 traceId 就成了串线的元凶。

logback-spring.xml里的 pattern 加一个%X{traceId}：

<pattern>%d{HH:mm:ss.SSS} [%thread] [%X{traceId:-}] %-5level %logger{36} - %msg%n</pattern>

:-后面是默认值，当 MDC 里没有这个是就输出空，不会出现null这种噪音。

如果你项目里用了@Async或者自己的线程池，MDC 不会自动传递过去，得给线程池加一个装饰器把当前线程的 MDC 复制到执行线程。这个问题不做处理的话，异步方法里的日志 traceId 全部是空的，排查异步任务基本抓瞎。

4. 实测踩坑：那些文档不会写的细节

代码写完跑通只是第一步，真正花时间的是那些“看着对但就是不出日志”的时刻。下面五个是我遇到频率最高的。

4.1 同类内部调用，切面凭空消失

这个坑我已经数不清踩过几次了。写法是这样的：

@Service public class OrderService { @OpLog(module = "order", action = "创建订单") public void create(Order order) { // ... 业务 this.audit(order); // 内部调用 } @OpLog(module = "order", action = "审计订单") public void audit(Order order) { // ... 审计逻辑 } }

调create的时候，日志里能看到“创建订单”，但“审计订单”那条永远不出现。原因前面提过：this是真实对象，没经过代理。这是 Spring AOP 的机制决定的，不是 bug，改不了。

三个解法，各有取舍：

一是把方法拆到另一个 Bean 里，通过注入的方式调用。最干净，也是我最推荐的，顺便还符合单一职责。缺点是类会变多，如果原来那个类很大，拆起来是个不小的工程。

二是自己注入自己，@Autowired private OrderService self;，然后self.audit(order)。能用，但 Spring 从 2.6 版本开始默认禁止循环依赖，自注入可能报启动失败，需要在配置里放开spring.main.allow-circular-references=true，这个开关一开，整个项目都会允许循环依赖，属于为了一个方法放弃全局约束，不太划算。

三是用AopContext.currentProxy()拿到当前代理再调，需要类上开@EnableAspectJAutoProxy(exposeProxy = true)。这个方案改动最小，但代码里出现((OrderService) AopContext.currentProxy())这种强转，可读性差，新人接手要问半天。

我的实际选择：小改动用第三种，大重构用第一种，第二种基本不用。不管选哪个，排查的时候先在方法里打一行log.info("in")确认真进去了，有时候问题根本不是切面失效，而是那个方法压根没被调用到。

4.2 方法签名上的三个地雷

private方法切不到，这个好理解。但final和static容易被忽略，特别是当你用 Lombok 或者 IDE 自动生成方法的时候。

final的情况：CGLIB 是通过继承目标类生成子类的，final方法不允许覆写，代理里那一份还是父类的原始实现，拦截不到。有些老代码里习惯给 Service 方法加final表达“不允许子类改”，加了切面之后就是无效的。遇到这个只能去掉final。

static的情况：静态方法属于类，不属于实例，代理对象是实例层面的东西，对它没有拦截能力。工具类里的静态方法想加日志，老老实实手写。

还有一个隐蔽的：protected方法在同类内部调用时也失效，因为它跟private、final一样走的是this调用，只不过原因不同。判断标准统一成一句话：只要调用没经过容器里的代理对象，切面就不会执行。

4.3 多个切面撞在一起，顺序会咬人

项目一大，切面就不止一个。事务、权限、日志、限流、幂等，五六个切面叠在同一个方法上，顺序稍微不对，行为就变了。

举个具体的：日志切面在权限切面之前执行，那么一个没权限的请求，日志里会记一条“开始处理”，然后权限切面抛异常，日志里再记一条“异常”。看起来没问题，但如果日志切面在权限之后，没权限的请求连日志都不会留一条，事后排查“这个用户到底调没调这个接口”就抓不到证据。显然前者更合理。

控制顺序就靠@Order，数值越小越靠外。我一般的约定是：

这只是个参考基线，具体项目要按业务语义调。改顺序之前先想清楚“我要在日志里看到哪一层的行为”，答案基本就出来了。

4.4 序列化性能：一个列表接口的翻车现场

有个列表查询接口，5000 条记录，P99 响应时间是 80 毫秒。加了日志切面之后变成 260 毫秒，加了 3 倍多。查下来就是safeJson(result)这一个调用——5000 条记录序列化成 JSON 大概 150 毫秒，再拼字符串、写文件，加起来就是这个数。

这个问题的本质是：日志不该改变主流程的性能特征。解法有几层：

第一层，给列表类返回值默认不打印。在注解上把printResult设为false，或者切面里判断result instanceof Collection && ((Collection<?>) result).size() > 100，超过阈值就只打印List(size=5000)，不打印内容。

第二层，异步写日志。Logback 配AsyncAppender加一个有界队列，业务线程只负责把日志事件扔进队列就返回，落盘交给后台线程。这个方案有个副作用要先知道：队列满了会丢日志（默认策略是丢弃，也可以配成阻塞但会影响业务线程）。丢日志和拖慢业务之间，多数时候选前者。

第三层，采样。不是每次调用都打，比如每 100 次打 1 次，或者只在入参特定条件下打。排查偶发问题时这个方案不给力，但对高频接口的常态监控够用。

我的一般配置：查询类接口printResult=false，写操作接口全打，异步 Appender 必开，队列长度 1024。

4.5 异步日志带来的耗时偏差

用了AsyncAppender之后，有个细节要注意：切面里算出来的cost是业务方法本身的耗时（因为proceed()返回之后就算完了），这个数字是准的，不受日志异步影响。但如果你依赖日志文件里的时间戳来判断请求时间，那就偏了——日志事件在队列里排队，落盘的时间可能比真实发生时间晚几十毫秒。

所以规矩是：耗时、时间这些关键数据由切面采集好塞进日志内容里，不要靠日志文件的写入时间戳推断。同理，如果做基于日志的链路分析，时间字段要用日志内容里的，不能用文件行的前缀时间。

5. 常见问题速查：按现象找原因

把上面这些经验整理成一张表，遇到问题先对照现象定位，能省不少时间。

再说两条排查顺序上的经验。第一，先确认方法有没有被调用，再看切面。很多人一上来就怀疑切点写错，结果发现是上游根本没调这个方法，白折腾。第二，打开logging.level.org.springframework.aop=DEBUG，Spring 会把代理的创建过程、切点的匹配情况打出来，比猜快得多。

6. 一些说不进文档里的实操体会

写了这么多年代码，关于 AOP 日志这块，我最想说的其实是“别过度使用”。日志切面最大的诱惑是它太好用了，加了注解就有日志，于是有人把切点写成execution(* com.example..*.*(..))，全项目所有方法全覆盖。结果呢？日志文件一天几十 GB，关键信息被淹没在海量的 getter、toString、工具方法调用里，真正要查一个业务问题时，grep 出来的结果比不查还乱。

我现在的做法是只在业务入口打点：Controller 层统一打一次请求级别的日志（URI、方法、耗时、状态），Service 层只给关键的业务动作打注解，DAO 层完全不打。三层加起来日志量可控，定位问题时从 Controller 那条能拿到 traceId，然后顺着 traceId 就能筛出这个请求的全部日志，效率比全量覆盖高得多。

另一个体会是关于参数采集的取舍。新手容易把能打的全打上，觉得信息越多越好。实际上日志的价值不在于“全”，而在于“这一条日志本身就够判断问题”。一个只写了args=[...]的日志，你还要去对照代码才知道这是哪个方法；而一条[order] OrderService.create 完成, cost=43ms, args={orderId=123, amount=99.00}的日志，扫一眼就知道发生了什么。所以module和action这两个字段一定要写，别偷懒留空。

最后一个建议：切面代码写完，给它自己写一个集成测试。Mock 一个带注解的 Service，调一次，断言日志里出现了预期的关键字。这个测试看起来没什么技术含量，但它能在你后续调整切点表达式、换代理方式、升级框架版本的时候，第一时间告诉你“日志采集挂了”。日志这种东西，坏掉的时候是静默的——没有日志，你不会收到任何告警，只会在下一次线上排查时才发现自己已经瞎了很久。