很多人在学 Java 反射的时候,都绕不过“动态代理”这一块。但反射的概念、Proxy 类的用法背得再熟,一落到真实业务里还是不知道从哪下手。我之前在一个模拟订单系统里正好做了一次动态代理日志记录的改造,把原本散落在各个业务方法里的日志输出全部收敛到了一个统一代理层里。那次改造做完之后,我对动态代理的理解才算真正从“会读代码”变成了“会写设计”。这篇文章就把这次实践完整拆开讲一遍,从为什么用动态代理做日志,到 JDK 代理和 CGLIB 代理的选型,再到完整的可复现代码和我在实际里踩过的坑,一步一步说清楚。
如果你正准备在项目里引入统一的日志埋点、权限校验或者事务控制,又不想改动业务代码本身,那动态代理几乎是性价比最高的切入点。理解了这个场景,你对反射、代理模式、AOP 底层原理的理解都会跟着上一个台阶。
1. 为什么偏偏用动态代理做日志记录
1.1 日志散落在业务代码里的真实痛点
我们最开始的需求其实特别简单:每次调用核心业务方法时,能自动记录一下方法名、入参、耗时、有没有抛异常。听起来没什么特别的,但真正的问题是——这些核心方法分散在十几个 Service 类里,每个类有七八个方法,加起来上百个方法。如果在每个方法里手动加上日志逻辑,那就是一百多处的重复代码。改一个格式,就要全局搜索替换;漏改一处,日志就对不齐。
更麻烦的是,日志代码和业务逻辑搅在一起。比如一个处理订单状态的方法,本来逻辑就够复杂了,你还得在里面理清楚哪一行是业务逻辑,哪一行是日志输出。时间一长,代码的可读性会变得非常差。我见过有些项目里,方法里一半以上的行数都在做日志和参数拼接,真正的业务逻辑反而被淹没了。
当时的诉求很明确:能不能做到业务代码保持原样,日志自动出现在方法调用的前后?这就是动态代理的典型使用场景。
1.2 代理模式在这里解决的本质问题
代理模式的核心思路是在访问真实对象之前加一层中间层。调用者只面向代理对象,代理对象拦截了本次调用,可以在调用前、调用后、异常时插入统一逻辑。动态代理则意味着这个代理对象不需要手写,而是在运行时通过 JDK 或者字节码生成库自动创建出来的。
回到我们这个场景里看一下:日志逻辑是横切关注点,业务逻辑是核心关注点。动态代理把横切关注点从核心关注点里剥离出来,让业务方法只关心一件事——做它自己的业务。日志、统计、异常监控这些,统一交给了代理层。
这其实和装修房子是一个道理——你不会让水电工顺手把墙也刷了,每一类工作应该有明确的边界。动态代理就是帮你把日志这些“装修工人”和业务逻辑这些“主体工程”彻底分开。
1.3 动态代理与 AOP 剖面的关系
很多人看到这里会想:这不就是 AOP 的事吗,用个注解就搞定了,何必手写动态代理?
从结果看确实相似,但理解手写动态代理的价值在于它是 AOP 的底层基础。Spring AOP 内置了对于 JDK 动态代理和 CGLIB 代理的封装,你要明白它在容器里到底帮你做了什么,才能在你真正需要自定义拦截逻辑的时候不至于两眼一抹黑。
而且,轻量级的场景其实根本不需要引入一套完整的 AOP 框架。我这次的目标只是日志记录,代理的类也就十几个,手动实现一个代理切面完全可控,而且整个过程透明,出了任何问题都能迅速定位到具体是代理层写的还是业务层写的。
2. JDK 动态代理和 CGLIB 代理的选型对比
2.1 两种代理的底层机制差异
Java 里实现动态代理有两条主流路线。
第一条是 JDK 自带的方式,要求目标对象必须实现接口。它的原理是在运行时通过反射机制生成一个实现了相同接口的代理类,所有对接口方法的调用都会被转发到 InvocationHandler 的 invoke 方法里。你可以把 JDK 动态代理理解成“按接口签约”——代理对象只要签了这套接口的“合同”,就能代替真实对象出场。
第二条是 CGLIB,它不要求目标对象实现接口。它的原理是在运行时直接生成目标类的一个子类,子类里覆盖了父类的所有非 final 方法,然后通过方法拦截器拦截调用。这个你可以理解成“继承家业”——代理类直接继承目标类,把目标类的方法重写一遍,在重写逻辑前后塞入代理逻辑。
这两种路线不是谁取代谁的关系,而是适用对象不同的互补关系。如果你的类没实现接口,或者你希望代理的是类本身而没有现成的接口抽象层,那 CGLIB 几乎是唯一选择。
2.2 这里为什么优先选 JDK 动态代理
我们这次日志记录的目标对象是 Service 层的核心业务类。在设计分层架构的时候,Service 层本身就是面向接口编程的——我这边每个 Service 都先定义了接口,然后才有对应实现类。比如订单服务和用户服务都有清晰的接口定义。
这样的结构下,使用 JDK 动态代理就非常顺畅了。接口本身就是天然的门面,代理对象只需要实现同样的接口,就能在方法调用链路上插入日志逻辑。不需要额外引入任何第三方依赖,JVM 原生支持,反射调用的成本在绝大多数业务场景下都完全可接受。
如果你维护的代码里有些类没有接口,或者接口体系很混乱,再考虑引入 CGLIB。但一个接口都懒得定义的系统,硬要套代理模式其实也意义不大,那种代码往往结构本身就需要优先梳理。
2.3 两种代理的性能与兼容性细节
性能上,JDK 代理在方法调用时需要经过反射,CGLIB 因为直接生成了子类字节码,方法调用上会比 JDK 代理快一些。但是记住,这个快也是相对的。对于一个方法内部要做数据库查询、外部接口调用、复杂计算的场景来说,反射损耗的那一点点时间比例小到可以忽略不计。
需要注意的反而是另一个细节:CGLIB 是通过生成子类来工作的,如果目标类是 final 的,或者某个方法是 final 的、static 的,那 CGLIB 就无能为力了。JDK 代理也有它的边界,只有接口方法会被拦截,如果业务代码里有接口之外自己单独加的方法,那么代理对象根本看不到这个方法的调用。
我把两种方式的关键区别整理成了表格,方便直接对照。我在做技术选型时习惯把这类对比放到一起,也方便团队新成员快速掌握:
| 对比维度 | JDK 动态代理 | CGLIB 代理 |
|---|---|---|
| 底层机制 | 运行时生成接口实现类 | 运行时生成目标类的子类 |
| 目标要求 | 目标必须实现接口 | 目标类不能是 final 类 |
| 方法要求 | 仅拦截接口中定义的方法 | 非 final 非 static 的方法均可 |
| 第三方依赖 | 无需额外依赖 | 需要引入 cglib 库(或通过 Spring 内置) |
| 调用性能 | 基于反射,相对较慢 | 字节码增强,相对较快 |
| 维护成本 | 结构简单,链路清晰 | 生成逻辑复杂,调试定位难度更高 |
2.4 这次方案选型的取舍理由
这次改造我选了 JDK 动态代理,理由有四个。第一,目标 Service 全部有接口,完全贴合 JDK 动态代理的适用条件。第二,整个项目还没引入任何额外字节码库,没必要为日志记录引入 CGLIB 这个第三方依赖。第三,代理调用链路要足够的简单透明,方便团队里成员直接顺着代码阅读下去就懂。第四,日志记录对性能的要求并不极端,反射开销在可以接受的范围之内,如果哪天真的对性能有严苛要求了,再升级也不迟。
有些项目组喜欢不论什么场景都默认上 CGLIB,理由是 Spring Boot 内置了它就顺手用起来了。但我要提醒一句,别人的默认未必适合你的场景。技术选型的第一原则永远是匹配现有代码结构,先看看自己手里的牌再决定打法。
3. 完整日志记录代理的设计与实现
3.1 需要被代理的业务接口与实现类
先说清楚我们的目标形态。订单服务是我们系统的核心业务服务之一,它定义了查询订单和创建订单两个核心方法。我拿这个接口作为演示示例,你的业务里换成自己的模块就好。
createOrder 方法接收一个订单参数,返回值是一个包含订单号和结果的 Map。queryOrder 方法按订单号查询订单信息。这两个方法将来都要被代理层拦截,分别记录调用信息。
为了更贴近真实项目,订单参数实体里也可以加一些字段。不过这里的前置代码重点还是接口的形态,字段本身不是关键,关键是接口的存在。没有接口的话,后面 JDK 动态代理的第一步就玩不转了。
我们给这个订单服务定义一个接口:
public interface OrderService { /** * 创建订单 * * @param order 订单信息 * @return 创建结果 */ Map<String, Object> createOrder(Map<String, Object> order); /** * 查询订单 * * @param orderId 订单编号 * @return 订单详情 */ Map<String, Object> queryOrder(String orderId); }对应的接口实现类里,我们把原先曾经出现过的日志输出语句全部去掉。这也是以后你引入这种改造方案时最容易出问题的一步——去掉日志的时候要格外小心,别再留下半行未闭合的字符串拼接或者多余的 System.out,不然编译期就直接报错了。
public class OrderServiceImpl implements OrderService { @Override public Map<String, Object> createOrder(Map<String, Object> order) { // 模拟业务处理耗时 try { Thread.sleep(300); } catch (InterruptedException e) { Thread.currentThread().interrupt(); } Map<String, Object> result = new HashMap<>(8); result.put("orderId", "ORDER_" + System.currentTimeMillis()); result.put("status", "CREATED"); result.put("orderInfo", order); return result; } @Override public Map<String, Object> queryOrder(String orderId) { // 模拟业务查询耗时 try { Thread.sleep(150); } catch (InterruptedException e) { Thread.currentThread().interrupt(); } Map<String, Object> result = new HashMap<>(8); result.put("orderId", orderId); result.put("status", "QUERY_SUCCESS"); return result; } }3.2 日志记录 InvocationHandler 的核心代码
接下来就是整篇文章里最核心的东西——日志记录处理器。它实现了 InvocationHandler 接口,对所有接口方法的调用进行统一拦截。
invoke 方法接收到三个参数:第一个 proxy 是生成的代理对象本身,第二个 method 是被调用的目标方法在反射层面的对象,第三个 args 是本次调用的实际入参。
在方法真正执行之前,我们通过 method.getName() 和 method.getDeclaringClass().getName() 拼出“类名.方法名”的完整调用标志。再配合 Arrays.toString 把参数数组转换成可读的字符串。这一步为了防 NPE,推荐用 String.valueOf 进行安全包装,下面代码里就是这么处理的。
方法执行时用一个 startTime 记录开始时间,通过 method.invoke(target, args) 真正触发目标对象的业务逻辑。执行完成后计算耗时,并且对返回值做了安全处理——如果返回值是 null,就输出一段提示,否则输出 toString。
异常处理是这段代码里的关键设计。我在 catch 代码块里记录异常信息之后,没有把吞掉之后假装无事发生,而是重新 throw 抛给上层调用方。这个问题真实项目里经常被忽略。代理层如果吞掉了异常,业务方的 try-catch 等于白写了,整个异常链路就从这里断掉了。日志守护了“记录”的本分,但异常的处理义务还是应该由业务方法决定。
我写这个小工具的时候还额外做了一个实现:模拟一个带自定义注解的方法,通过 method.isAnnotationPresent 判断是否要记录日志。这样一来,日志记录不光是全量的,还能做到按注解精准控制范围。这一段代码内部的完整实现,放在 3.4 节里展示。
3.3 创建代理对象的工厂封装
有了 InvocationHandler,我们还需要一个工厂类,专门负责创建代理对象。这个类的作用是约定一个统一的入口,后续调用方只需要从这个工厂里拿到代理对象,不需要知道背后反射和 Proxy 的原理。
工厂方法的核心就一行:Proxy.newProxyInstance。第一个参数是目标对象的类加载器,第二个参数是目标对象实现的所有接口,第三个参数是我们自研的日志记录处理器。
类加载器这里要注意,不要随便用自定义的线程上下文加载器,而是要绝对保证和目标类使用的是同一个类加载器。我之前遇到过有人图省事直接传 ClassLoader.getSystemClassLoader(),结果目标类是委托给应用服务器加载的,两边类加载器不统一,运行期报了 ClassCastException,排查起来格外绕。这个细节看似简单,实际翻车率不低。
把工厂代码放出来,方便直接拿来用:
public class LogProxyFactory { /** * 创建日志代理对象 * * @param target 目标业务对象 * @param <T> 接口类型 * @return 代理对象 */ @SuppressWarnings("unchecked") public static <T> T createLogProxy(T target) { if (target == null) { throw new IllegalArgumentException("target object cannot be null"); } return (T) Proxy.newProxyInstance( target.getClass().getClassLoader(), target.getClass().getInterfaces(), new LogInvocationHandler(target) ); } }3.4 完整日志记录处理器代码详解
下面这段代码就是承载这次核心日志记录能力的处理器完成体,我加上了一些注释方便阅读:
public class LogInvocationHandler implements InvocationHandler { private static final Logger log = LoggerFactory.getLogger(LogInvocationHandler.class); /** 目标业务对象 */ private final Object target; public LogInvocationHandler(Object target) { this.target = target; } @Override public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { // 如果是 Object 类自身的通用方法,直接放行,避免无意义的日志干扰 if (method.getDeclaringClass() == Object.class) { return method.invoke(target, args); } String methodName = method.getDeclaringClass().getSimpleName() + "#" + method.getName(); long startTime = System.currentTimeMillis(); // 方法进入时,记录入参信息 log.info("[PROXY] {} start, params: {}", methodName, String.valueOf(args)); try { Object result = method.invoke(target, args); long costTime = System.currentTimeMillis() - startTime; // 方法正常返回时,记录出参信息和耗时 log.info("[PROXY] {} finish, cost: {}ms, result: {}", methodName, costTime, String.valueOf(result)); return result; } catch (InvocationTargetException e) { // 反射调用会把业务异常包装成 InvocationTargetException,这里必须取出真实的异常 long costTime = System.currentTimeMillis() - startTime; Throwable cause = e.getTargetException(); log.error("[PROXY] {} error, cost: {}ms, exception: ", methodName, costTime, cause); throw cause; } catch (Exception e) { // 代理层自身的其它异常,同样记录并抛出 long costTime = System.currentTimeMillis() - startTime; log.error("[PROXY] {} exception, cost: {}ms, exception: ", methodName, costTime, e); throw e; } } }这段代码里有几个值得注意的细节我需要单独说明一下。
第一个是 method.getDeclaringClass() == Object.class 的判断。这个判断非常讲究。代理对象除了业务接口的方法之外,从 Object 继承来的 toString、hashCode、equals 也会被拦截,因为 JVM 在传递方法调用的时候,并不自动区分哪些方法是接口定义、哪些是 Object 类固有方法。如果不提前放行,每次打印代理对象时都会跑一遍日志逻辑,打出来的日志又乱又蠢。
第二个是 InvocationTargetException 的处理。反射调用 method.invoke 的时候,如果目标业务方法内部抛了异常,JVM 会把这个异常包装成 InvocationTargetException 往外抛。如果你直接 catch Exception 然后记日志,打出来的异常堆栈全是反射内部的包装痕迹,真正的业务异常堆栈就被埋掉了。所以必须调用 getTargetException() 或者 getCause() 取出真实异常,再重新抛出。
第三个是 String.valueOf(args) 的细节。很多人习惯写 Arrays.toString(args),但 args 可能为 null,JDK 的 Arrays.toString 就会抛 NPE。String.valueOf 内部会做 null 判断,输出 null 字样,日志照样打,程序不会断。
三个细节分别对应了程序的稳定、可读、健壮,少了任何一个都会在后续的运行里暴露出问题。
4. 实操过程与核心环节实现
4.1 从普通调用改成代理调用的具体步骤
改造其实没有那么多玄虚的步骤,核心就是把原先 new 实现类的地方,改成经过工厂类获取代理对象。我们模拟项目最开始在主程序里直接构造了 OrderServiceImpl,然后调用了两次方法。现在要改成通过 LogProxyFactory 拿代理对象。
这里的改造等于引出了“面向接口而非面向实现”的落地姿势。因为我这里已经把接口定义好了,调用方只需要持有 OrderService 这个类型,具体背后是真实实现类还是代理对象,调用方根本不关心,也感知不到。
修改后的入口主程序如下:
public class ProxyLogDemo { public static void main(String[] args) { // 1. 创建目标业务对象 OrderService target = new OrderServiceImpl(); // 2. 通过代理工厂创建代理对象 OrderService proxy = LogProxyFactory.createLogProxy(target); // 3. 调用代理对象的方法,触发日志记录 Map<String, Object> order = new HashMap<>(8); order.put("productId", "P-1001"); order.put("quantity", 2); Map<String, Object> createResult = proxy.createOrder(order); System.out.println("下单结果: " + createResult); Map<String, Object> queryResult = proxy.queryOrder("ORDER_20250101_001"); System.out.println("查询结果: " + queryResult); } }运行这段代码后的输出是这样的(我保留关键日志语义,仅供趋势参考,具体时间戳等信息以运行时打印为准):
[INFO ] [PROXY] OrderServiceImpl#createOrder start, params: [{productId=P-1001, quantity=2}] [INFO ] [PROXY] OrderServiceImpl#createOrder finish, cost: 301ms, result: {orderId=ORDER_1735660800000, status=CREATED, orderInfo={productId=P-1001, quantity=2}} 下单结果: {orderId=ORDER_1735660800000, status=CREATED, orderInfo={productId=P-1001, quantity=2}} [INFO ] [PROXY] OrderServiceImpl#queryOrder start, params: [ORDER_20250101_001] [INFO ] [PROXY] OrderServiceImpl#queryOrder finish, cost: 152ms, result: {orderId=ORDER_20250101_001, status=QUERY_SUCCESS} 查询结果: {orderId=ORDER_20250101_001, status=QUERY_SUCCESS}日志里清清楚楚地记录了什么方法被调用、入参是什么、耗时多少、返回结果是什么。而 OrderServiceImpl 内部完全看不到任何日志代码的痕迹。业务实现类保持纯净,这就是这次改造最终要达到的效果。
4.2 日志切面里精确控制记录范围的扩展
有朋友看完会说,现在的设计是每个方法都记录日志,但我的业务系统里并不是每个方法都需要记日志。比如有些纯查询方法,日志价值不大;有些高频方法,日志打太频繁反而影响性能。这个扩展点我来补上。
我在处理器里加入了一个自定义注解 @LogRecord,只有标了该注解的方法,代理层才执行日志记录逻辑。没标注解就只做普通转发,不记任何日志。
注解定义很简单:
@Retention(RetentionPolicy.RUNTIME) @Target(ElementType.METHOD) public @interface LogRecord { String value() default ""; }然后修改一下 OrderService 接口,希望 createOrder 方法记录日志,queryOrder 暂时不记:
public interface OrderService { @LogRecord("创建订单日志") Map<String, Object> createOrder(Map<String, Object> order); Map<String, Object> queryOrder(String orderId); }对应的 LogInvocationHandler 里的 invoke 逻辑也要跟着调整:
@Override public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { if (method.getDeclaringClass() == Object.class) { return method.invoke(target, args); } boolean needLog = method.isAnnotationPresent(LogRecord.class); if (!needLog) { // 无注解,直接放行 return method.invoke(target, args); } String methodName = method.getDeclaringClass().getSimpleName() + "#" + method.getName(); long startTime = System.currentTimeMillis(); LogRecord logRecord = method.getAnnotation(LogRecord.class); String bizDesc = logRecord.value(); log.info("[PROXY] {}, desc: {}, start, params: {}", methodName, bizDesc, String.valueOf(args)); try { Object result = method.invoke(target, args); long costTime = System.currentTimeMillis() - startTime; log.info("[PROXY] {}, desc: {}, finish, cost: {}ms, result: {}", methodName, bizDesc, costTime, String.valueOf(result)); return result; } catch (InvocationTargetException e) { long costTime = System.currentTimeMillis() - startTime; Throwable cause = e.getTargetException(); log.error("[PROXY] {}, desc: {}, error, cost: {}ms, exception: ", methodName, bizDesc, costTime, cause); throw cause; } catch (Exception e) { long costTime = System.currentTimeMillis() - startTime; log.error("[PROXY] {}, desc: {}, exception, cost: {}ms, exception: ", methodName, bizDesc, costTime, e); throw e; } }这样改造后,日志记录范围的控制从代理类的全局拦截,下放到了注解层面。谁想记录日志,就在对应接口方法上打个标签,代码里一看就知道。团队协作的时候,这个方案的可读性比逻辑判断拦截方式要好很多。
4.3 方法耗时统计里隐藏的坑
耗时统计看起来就是 startTime 和 endTime 相减,非常简单。但这里实际上藏着几个容易忽略的细节。
第一个坑是 System.currentTimeMillis() 获取的是 wall-clock 时间,也就是墙上时钟时间。如果系统时间服务器做了时间校准,导致系统时间往前跳或者往后跳,测出来的耗时就会忽大忽小。对于做日志记录来说这个误差可以接受,但如果你要拿这个数据做性能基准,建议换成 System.nanoTime() 来测。它获取的是 JVM 内部的单调时钟,不受系统时间调整影响。
第二个坑是耗时数字的类型。我用的是 long 类型,这在绝大多数场景下是够用的。如果你要用这个耗时做排序、告警阈值判断,建议保留为 long,不要因为方便展示就转化成 int,一旦方法耗时超过 int 上限你就要额外做溢出了。
第三个坑是代理层测的耗时包含了什么。它包含了反射调用本身的损耗,也包含了业务方法内部的所有时间消耗。如果你想知道纯业务方法的耗时,最简单的方式是在业务方法内部单独埋点,但那就和动态代理的目的背离了。所以这里要接受一个误差:代理层的耗时永远稍微大于业务方法真实耗时,偏差通常只有微妙级别,对日志记录这不重要。
4.4 反射调用的异常链路如何保持完整
前面已经强调了 InvocationTargetException 的处理,这一节再展开说说它背后涉及到的反射机制。
当目标方法内部抛出了一个业务异常,比如订单库存不足,你把它抛成自定义的 BusinessException。这个异常会被反映到 method.invoke 的调用栈上,因为 invoke 底层通过 native 方法调用了目标方法,JVM 不会直接把异常原样传出来,而是统一包装成 InvocationTargetException。
很多新手第一次写代理都会在这里栽跟头。他们就直接捕获 InvocationTargetException 然后 log.error 记一下,一行 toString 了事,跑起来之后发现业务方根本接不住原来的异常类型。整个调用方预期的是抛 BusinessException,结果收到的是 InvocationTargetException,类型体系全乱了。
正确的处理方式是取出 cause 再重新抛出,并且在方法签名上声明 throws Throwable。InvocationHandler 接口本身就是这么设计——允许实现类往外抛任意异常。这个签名设计也是给代理层处理异常留下了最大程度的自由度。
在你的业务代码里,当调用方 catch 住异常的时候,拿到的异常类型和堆栈就能恢复成目标方法抛出的原样信息,日志排查链路也不会断。
5. 常见问题与排查技巧实录
5.1 生成的代理对象类型转换失败
这个问题最常见的诱因有三个:目标类没有实现任何接口;类加载器使用混乱;代理对象转换到了错误的目标类型。
如果你拿一个没有实现任何接口的类传给 Proxy.newProxyInstance,第二个参数传 getClass().getInterfaces() 拿到的就是空数组,代理类生成阶段直接抛 IllegalArgumentException。这种情况要考虑改用 CGLIB。
类加载器方面,要保证代理类所在模块能看见目标接口。最简单的做法就是用目标对象的类加载器,几乎不会出错。乱用底层类加载器或者业务侧自定义类加载器,很容易在运行时生成出来的代理类无法对接口定义做链接验证,结果就是 ClassCastException。
排查这类问题时第一步就是打印目标对象的类型和接口数组,先定位是哪一段链路出了问题,再顺着编译器的错误信息一个个验证。
5.2 业务方法事务不回滚
这是动态代理应用到一个项目里之后最容易引发的连锁反应。如果你的事务是通过 Spring 的事务管理器控制的,而你的动态代理在事务控制外层又包了一层,就可能出现事务不生效的情况。
底层原因其实不复杂:事务切面本身也是通过动态代理在工作。当你的代理对象先于事务管理器创建的代理对象出现时,事务管理器看到的可能不是经过代理增强的对象,或者是代理的顺序不对,导致注解上配置的传播行为没有被正确识别。
在我这个简单日志代理场景里问题不大,因为我没有引入任何事务控制,代理链路非常简单。但如果你准备在一个已经使用事务注解的项目里叠加自定义代理,就要特别注意增强顺序的问题。最好的实践是不要随意在一个被 Spring 托管并且已经使用 AOP 的类上再手动包一层 JDK 动态代理,这会让代理嵌套层数剧增,排查成本成倍上升。
5.3 日志中把敏感信息打出来了
日志记录最容易被忽略的就是安全问题。如果你直接打印参数的 toString,而参数对象里有银行卡号、手机号、密码字段,那这些明文信息就会进入日志系统。一旦日志文件被同步到第三方平台或者被低权限人员查询,就是一次数据泄露事故。
我在实现时留了一个可配置的开关,也可以在处理器里增加字段过滤。最简单的过滤方式是不打印全部参数,而是打印参数全类名加参数个数,比如 paramTypes=[OrderQueryRequest], paramCount=1。如果需要追踪指定的定位信息,再额外提取订单号或者用户 ID 这样的非敏感字段。
关键的原则是,日志不是越详细越好,而是越安全越有用。没有敏感字段的日志,才可以放心流转到各类日志采集分析系统。
5.4 代理对象调用开销被低估
很多人以为反射调用很慢、慢到不能商用,但实际没有这么夸张。在今天的 JVM 上,反射调用是经过了高度优化的,随着 HotSpot 版本升级,反射调用的性能已经接近普通方法调用的性能。真正影响性能的是方法调用过于频繁且方法本身特别简单,导致反射开销占比变得明显。
如果某个高频方法只是简单的取值计算,比如每秒被调用几十万次,再追加一层动态代理日志,那确实可能成为热点。但如果你代理的是 Service 层、方法内部要查询数据库、调用远程接口,这个开销比例就完全不值一提了。
不过我还是加了一个优化思路:高频且纯查询的方法,可以通过注解控制不记录日志,返回结果也不打印,只记录方法名和耗时。这个思路在 4.2 的代码里已经给出了实现方向。
5.5 异常日志打印不完整
有经验的排查人员会注意到一个细节:日志里出现的异常只打印了异常消息,缺少完整的堆栈——这种情况十有八九是你调用了 e.getMessage(),而不是把整个异常对象打进去。
我们的代码里用的是 log.error("...exception: ", cause),这种方式把异常对象作为最后一个参数传入,日志框架会自动把异常堆栈完整渲染出来。如果这里少了堆栈信息,排查线上问题时只能看到“NullPointerException”六个字,然后完全不知道发生在哪一行,排查效率会断崖式下降。
我还遇到过一种极端情况:某些异常对象的 message 为空,但堆栈里有丰富信息。更说明完整堆栈的重要性了,别贪省事只打 getMessage()。
5.6 代理类内部方法互相调用时日志失效
这是动态代理和 AOP 体系里一个非常经典的问题。假设 OrderServiceImpl 的 createOrder 方法里直接调用了 this.queryOrder("内部查询"),这个内部调用是一个普通 Java 方法调用,完全不会经过代理对象。因为动态代理的拦截机制只对代理对象的外部调用生效。
因此,如果你在代理层做了日志记录,你会看到外部调用 createOrder 时有日志,但 createOrder 内部调用的 queryOrder 却没有日志。这会导致日志记录不完整,排查链路时中间缺了一段。
这个问题的解法从设计层面来说分两种。一种是你明确要求业务方法内部不要自调用,把公共查询逻辑抽取到独立的支撑服务里,让两个 Service 对外分别被代理。另一种就是接受这种现状向团队说明清楚,日志记录是面向外部调用链的,内部 this 调用不在这层管控范围内。
我个人的建议是优先接受现状并把它写进团队技术规范。强行设计一套自调用也能拦截的方案,付出的复杂度远超收益,除非你真的面临严格到每个内部调用都必须审计的场景,否则没必要过度设计。
6. 这次实践给我的几个额外体会
代码之外我再说一点从实际操练里得来的经验。动态代理这套工具,真正上手用起来之后,会让你对框架底层的理解发生一次质的改变。以前 JVM 生成代理类、反射调用方法这些概念都是散的,做过一个完整日志代理之后,它们就被组装成了一条完整的链路,再去看 Spring AOP 的源码也能看出门道来,不再是一堆抽象概念在脑子里飞来飞去。
日志记录只是动态代理的最小场景之一。同样的拦截思路再往前延伸一点,你可以实现接口调用的耗时监控、参数校验、权限过滤、幂等控制、缓存旁路。每一次扩展都用同一套代理模式去思考,代码的组织方式会慢慢形成一种反射式设计的肌肉记忆。
对于团队里基础比较薄弱的新同事,我会建议他先把这篇文章里这个几十行代码的日志代理跑通,仔细理解每一行的含义,然后就着它去阅读 Spring 里 ProxyFactory 的实现。由小到大出来的知识,比直接扑向庞大框架要扎实很多很多。
最后分享一个小细节:那次改造做完,我顺手在代理处理器里加了一个静态开关,生产环境默认开启,压测环境可以直接关闭全部日志输出,为的是在压测的时候排除一切 IO 干扰。后来这个开关在两次大促压测里帮了大忙——压测报告里的耗时曲线干净了很多,没有日志写入抖动带来的毛刺。像这样的开关,建议你以后自己写代理增强层时也考虑一个。