1. 先把概念掰开AOP 究竟在解决什么麻烦“日志”这两个字写业务代码的人大概都有过某个瞬间接口上线第三天业务方反馈某条数据不对你打开日志文件发现只有一行“请求进入”和一行“请求结束”中间发生了什么完全是空白。于是你回去往每个 Service 方法的第一行塞log.info塞到第十个方法的时候开始怀疑人生——这些代码和业务逻辑一点关系都没有却占了屏幕的三分之一。面向切面编程AOP就是为了处理这类“横切关注点”才被提出来的编程范式而日志记录几乎是它最经典、也最容易讲清楚的落地场景。这篇内容我会从项目里反复出现的重复日志现场讲起把切面、切点、通知、织入这几个概念用大白话拆开再手写一个能往生产环境放的日志切面覆盖入参采集、耗时统计、异常记录、链路 ID 注入、敏感字段脱敏这几件事最后把“切面为什么没生效”这类高频坑逐个复盘。适合已经能写增删改查、但还没系统用过 AOP 的开发者也适合用过注解式切面却总被失效问题绕晕的人对照排查。1.1 从一个重复代码现场说起我印象最深的一次是在一个订单履约模块里做排查。那个模块有十来个 Service 方法每个方法的开头都是三行记录入参、打一个开始时间戳、记录当前登录用户结尾又是三行记录返回值、算出耗时、把耗时打出来。中间夹着真正的业务逻辑只有两行。也就是说一个方法六行日志代码包着两行业务比例是三比一。当时的直接后果不是难看而是维护成本某次要求把日志里的手机号改脱敏我和另外两个同事分别改了自己负责的那批方法改完还有人漏了两个因为那两个方法是用 IDE 模板生成的格式跟别的不一样。这类代码有个共同特征它们横着切过了所有业务方法跟“下单”“扣库存”“生成流水”这些纵向的业务功能没有关系但每个业务方法都躲不掉。业内把这叫横切关注点日志、权限校验、事务控制、缓存、限流、埋点统计都属于这一类。AOP 的思路很直接既然这些东西在每个方法里长得都差不多那就别写在方法里了把它抽出来声明“我要贴在哪些方法上”剩下的交给框架在运行时自动拼上去。这么做的价值不在于代码短了几行而在于关注点分离。业务方法只管业务日志格式要改的时候只改一个地方脱敏规则要调整的时候只动一处新加一个接口忘了写日志这种事从根上就不会再发生。1.2 五个名词一次讲透AOP 的概念词不多但第一次看文档容易被绕晕我用一个寄快递的类比把它们串起来。术语英文大白话解释类比切面Aspect横切逻辑的封装单元一个类一套“寄件服务流程”连接点JoinPoint程序执行过程中可以被插入逻辑的点每一个可以揽件的时间点切点Pointcut用表达式筛出真正要插逻辑的连接点“只服务写字楼里的客户”通知Advice插入的具体动作分前置、后置、环绕等揽件、称重、贴单这些动作织入Weaving把切面代码合并进目标方法的过程把服务流程套到客户身上这里最容易混的是连接点和切点。连接点在 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注解声明式写法业务代码零侵入代价只是一点点代理开销对绝大多数业务系统完全可以忽略。方案是否需要接口代码侵入维护成本适用场景静态代理否高要写包装类随类数量线性上升类极少、依赖受限JDK 动态代理是中要写 InvocationHandler中有统一接口的框架层Spring AOP否默认 CGLIB低注解声明低业务系统日志、事务、权限我的判断很简单只要是 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 groupIdorg.springframework.boot/groupId artifactIdspring-boot-starter-aop/artifactId /dependency dependency groupIdcom.fasterxml.jackson.core/groupId artifactIdjackson-databind/artifactId /dependency目录结构我习惯这么放把“注解”和“切面”分开后面别的模块要复用注解只引注解所在的包就行com.example.demo ├── log │ ├── OpLog.java // 自定义注解 │ ├── OpLogAspect.java // 切面实现 │ └── LogUtils.java // 序列化、脱敏、截断工具 └── service └── OrderService.java // 业务类方法上打 OpLog3.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-referencestrue这个开关一开整个项目都会允许循环依赖属于为了一个方法放弃全局约束不太划算。三是用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数值越小越靠外。我一般的约定是切面类型建议 Order理由链路追踪、日志1 ~ 10最外层能包住全部行为权限校验20在日志之后拒绝操作也有记录限流、幂等30在权限之后避免无效请求占用名额事务100靠近业务方法控制范围最小缓存200最内层命中缓存就不必走事务这只是个参考基线具体项目要按业务语义调。改顺序之前先想清楚“我要在日志里看到哪一层的行为”答案基本就出来了。4.4 序列化性能一个列表接口的翻车现场有个列表查询接口5000 条记录P99 响应时间是 80 毫秒。加了日志切面之后变成 260 毫秒加了 3 倍多。查下来就是safeJson(result)这一个调用——5000 条记录序列化成 JSON 大概 150 毫秒再拼字符串、写文件加起来就是这个数。这个问题的本质是日志不该改变主流程的性能特征。解法有几层第一层给列表类返回值默认不打印。在注解上把printResult设为false或者切面里判断result instanceof Collection ((Collection?) result).size() 100超过阈值就只打印List(size5000)不打印内容。第二层异步写日志。Logback 配AsyncAppender加一个有界队列业务线程只负责把日志事件扔进队列就返回落盘交给后台线程。这个方案有个副作用要先知道队列满了会丢日志默认策略是丢弃也可以配成阻塞但会影响业务线程。丢日志和拖慢业务之间多数时候选前者。第三层采样。不是每次调用都打比如每 100 次打 1 次或者只在入参特定条件下打。排查偶发问题时这个方案不给力但对高频接口的常态监控够用。我的一般配置查询类接口printResultfalse写操作接口全打异步 Appender 必开队列长度 1024。4.5 异步日志带来的耗时偏差用了AsyncAppender之后有个细节要注意切面里算出来的cost是业务方法本身的耗时因为proceed()返回之后就算完了这个数字是准的不受日志异步影响。但如果你依赖日志文件里的时间戳来判断请求时间那就偏了——日志事件在队列里排队落盘的时间可能比真实发生时间晚几十毫秒。所以规矩是耗时、时间这些关键数据由切面采集好塞进日志内容里不要靠日志文件的写入时间戳推断。同理如果做基于日志的链路分析时间字段要用日志内容里的不能用文件行的前缀时间。5. 常见问题速查按现象找原因把上面这些经验整理成一张表遇到问题先对照现象定位能省不少时间。现象可能原因排查动作解决方式切面完全不生效类没被 Spring 管理检查有没有Service、Component补注解切面完全不生效切点表达式写错包名打开 debug 日志看Pointcut是否匹配修正表达式或改用注解式切点只有部分方法不生效方法被同类自调用看调用方是不是this.xxx()拆 Bean 或走代理调用只有部分方法不生效方法是private/final/static看方法签名去掉修饰符或拆分注解明明在getAnnotation返回 null注解在实现类getMethod()拿到接口方法打印signature.getMethod().getDeclaringClass()用AopUtils.getMostSpecificMethod日志里出现serialize-failed参数不可序列化或循环引用看参数类型加黑名单、配 Jackson 特性业务莫名其妙失败切面里抛了异常没兜住看异常栈是不是来自切面类序列化、反射全包 try-catch日志顺序乱多个切面Order冲突打印各切面的 order 值统一编排顺序异步方法日志 traceId 为空MDC 不跨线程传递看线程名线程池加 MDC 装饰器日志文件暴涨大对象全量输出看单条日志长度截断、关闭printResult耗时出现负数用了currentTimeMillis搜代码改nanoTime再说两条排查顺序上的经验。第一先确认方法有没有被调用再看切面。很多人一上来就怀疑切点写错结果发现是上游根本没调这个方法白折腾。第二打开logging.level.org.springframework.aopDEBUGSpring 会把代理的创建过程、切点的匹配情况打出来比猜快得多。6. 一些说不进文档里的实操体会写了这么多年代码关于 AOP 日志这块我最想说的其实是“别过度使用”。日志切面最大的诱惑是它太好用了加了注解就有日志于是有人把切点写成execution(* com.example..*.*(..))全项目所有方法全覆盖。结果呢日志文件一天几十 GB关键信息被淹没在海量的 getter、toString、工具方法调用里真正要查一个业务问题时grep 出来的结果比不查还乱。我现在的做法是只在业务入口打点Controller 层统一打一次请求级别的日志URI、方法、耗时、状态Service 层只给关键的业务动作打注解DAO 层完全不打。三层加起来日志量可控定位问题时从 Controller 那条能拿到 traceId然后顺着 traceId 就能筛出这个请求的全部日志效率比全量覆盖高得多。另一个体会是关于参数采集的取舍。新手容易把能打的全打上觉得信息越多越好。实际上日志的价值不在于“全”而在于“这一条日志本身就够判断问题”。一个只写了args[...]的日志你还要去对照代码才知道这是哪个方法而一条[order] OrderService.create 完成, cost43ms, args{orderId123, amount99.00}的日志扫一眼就知道发生了什么。所以module和action这两个字段一定要写别偷懒留空。最后一个建议切面代码写完给它自己写一个集成测试。Mock 一个带注解的 Service调一次断言日志里出现了预期的关键字。这个测试看起来没什么技术含量但它能在你后续调整切点表达式、换代理方式、升级框架版本的时候第一时间告诉你“日志采集挂了”。日志这种东西坏掉的时候是静默的——没有日志你不会收到任何告警只会在下一次线上排查时才发现自己已经瞎了很久。