首页 / 资讯中心 / 文章详情

MyBatis源码解析:日志模块中的适配器模式与代理模式实践

MyBatis源码解析:日志模块中的适配器模式与代理模式实践 ★ FEATURED ARTICLE
设计模式的书我翻过好几遍适配器模式代理模式的定义都能背但真正觉得自己会用了是某天耐着性子把 MyBatis 的 logging 包源码从头到尾过了一遍。这个包不大满打满算也就二十来个类却把两个看起来抽象得要命的设计模式落到了实处而且落得干净、克制、一点都不炫技。这篇文章想把我在源码里看到的东西拆开讲清楚MyBatis 为什么非要自己定义一套日志接口、每个 Impl 类到底在桥接什么、LogFactory 是怎么用 try-catch 完成依赖探测的、以及打印 SQL 的那条代理链是怎么一层层包装起来的。如果你正在学设计模式但觉得教材例子太假或者写后端几年了想从源码里学点真东西这篇应该适合你。1. 一个 Log 接口五套实现logging 包最初要解决的事1.1 为什么持久层框架非要自己定义日志接口先说结论MyBatis 作为一个会被塞进各种应用里的框架不能强制绑定任何一个日志框架。你的项目可能用 Log4j他的项目可能用 SLF4J 加 Logback还有人什么日志框架都没配就靠 JDK 自带的 java.util.logging 兜底。如果 MyBatis 在编译期直接依赖其中某一个问题马上就来了。最典型的就是依赖冲突。框架一旦把自己的日志依赖传递到使用方的 classpath 里就会跟使用方已有的日志框架打架轻则日志重复输出重则版本冲突直接启动失败。另一个问题是输出不可控使用方已经用统一的配置管好了所有日志结果 MyBatis 自己拉了一套日志配置进来完全游离在体系之外。所以 MyBatis 的做法是自己定义一个极简的日志接口然后给每种主流日志框架写一个实现类。这个接口就是org.apache.ibatis.logging.Log代码很简单public interface Log { boolean isDebugEnabled(); boolean isTraceEnabled(); void error(String s, Throwable e); void error(String s); void debug(String s); void trace(String s); void warn(String s); }接口只有 7 个方法。这个极简本身就是设计意图——接口越小适配每一种框架的成本就越低任何一个实现类都只需要做简单的转发不需要处理复杂的生命周期。后面你会看到这套定义的第一个受益人就是那些实现类自己。1.2 从包结构看设计意图两条线各管各的打开 logging 包目录结构其实已经把事情说了一半。org.apache.ibatis.logging顶层放着Log接口和LogFactory工厂类往下是log4j、log4j2、slf4j、commons、jdk14、stdout、nologging这样一组子包每个子包对应一种日志框架的适配实现另外还有一个单独的jdbc子包里面是BaseJdbcLogger、ConnectionLogger、PreparedStatementLogger、ResultSetLogger这几个类。这两块正好对应我们要讲的两个模式。前一块是适配器模式无论底层是 Log4j 还是 SLF4J对外都统一成Log接口。后一块是代理模式连接、语句、结果集都被动态代理包了一层用来拦截 JDBC 调用、打印 SQL 和参数。而LogFactory是这两条线的交汇点——它决定到底用哪个Log实现然后把这个Log实例交给代理类去打印信息。一句话概括适配器线解决日志往哪儿打的问题代理线解决什么时候打、打什么内容的问题。两条线互相不知道对方的细节只通过Log接口通信。先看适配器线。2. 适配器模式的真身每个 Impl 都是一座单向桥2.1 从 Log4jImpl 拆解三角色适配器模式之所以难理解是因为教材总爱拿插座转换头打比方但代码里到底谁是 Target、谁是 Adaptee、谁是 Adapter没人点透。放到 MyBatis 里其实很清楚目标接口TargetLog被适配者AdapteeLog4j 自带的org.apache.log4j.Logger适配器AdapterLog4jImplLog4jImpl的代码是最标准的适配器写法这里我把它简化示意一下public class Log4jImpl implements Log { private final Logger log; public Log4jImpl(String clazz) { log Logger.getLogger(clazz); } Override public boolean isDebugEnabled() { return log.isDebugEnabled(); } Override public void error(String s, Throwable e) { log.error(s, e); } Override public void debug(String s) { log.debug(s); } // 其余方法同理全是转发 }看到没适配器的本质就是实现目标接口 持有被适配对象的引用 方法全部转发。它自己没有业务逻辑它的存在价值就是把Log接口的调用翻译成 Log4j 的调用。error(String, Throwable)调log.error(s, e)isDebugEnabled()调log.isDebugEnabled()机械但正确。2.2 为什么选对象适配器而不是类适配器设计模式教材里还会提一种类适配器通过继承被适配类来实现。MyBatis 这里全部用的是对象适配器也就是组合方式。原因其实很实际。第一org.apache.log4j.Logger是类不是接口而 Java 只有单继承Log4jImpl一旦继承了 Logger 就没法再继承任何东西了。第二不同的日志框架的 Logger 类之间没有任何继承关系你不可能写一个能同时适配 Log4j 和 Logback 的基类。第三组合比继承更灵活适配器想换底层框架时只需要替换持有的引用不需要动类结构。这个选择也提醒我一点设计模式的选择往往不是美学问题是语言约束和现实约束逼出来的。不要因为书上画了类适配器的 UML 图就去用继承看看你的被适配对象到底是啥再决定。2.3 Slf4jImpl、StdOutImpl、NoLoggingImpl 三个特殊样本光看 Log4jImpl 还不够另几个实现类里藏着更细的讲究。Slf4jImpl是适配器里最有意思的一个。SLF4J 本身也是个门面它底下还能再挂 Logback 或其他实现。所以 MyBatis 适配 SLF4J 时会更进一步拿到 SLF4J 的Logger之后还要判断它是不是LocationAwareLogger。如果是就用一个专门子类来自动定位调用方的类和行号如果不是才退回普通的Slf4jLoggerImpl。这就是所谓适配器里面的适配器——Slf4jImpl是外面一层真正干活的是里面再细分出来的两个小适配器。再往下看StdOutImpl它甚至都不算适配框架而是直接把日志打到System.errpublic class StdOutImpl implements Log { public StdOutImpl(String clazz) { } Override public boolean isDebugEnabled() { return true; } Override public void debug(String s) { System.err.println(s); } // ... }这个类看着傻但它是 MyBatis 的兜底方案如果使用方的环境里一个日志框架都找不到那么至少还有这么个实现保证 SQL 日志不会无声无息地消失。注意它的isDebugEnabled()永远返回 true因为标准输出不需要开关。还有个NoLoggingImpl所有方法都是空的。这就是空对象和适配器模式的叠加不以空指针崩溃但也不做任何事。当你显式把 MyBatis 的logImpl配成NoLoggingImpl时整个日志链路还在只是变成空转。这三个实现放到一起看适配器模式的一个优点就浮现了它把差异关在了每个类内部上层代码从来不需要关心底层是 Log4j、SLF4J 还是标准输出。我用下面这个表格总结一下几个核心实现类的差异实现类底层依赖特点Log4jImplLog4j 1.x最经典的适配器写法Log4j2ImplLog4j 2.x基于 API 的 LoggerSlf4jImplSLF4J API内部分出 LocationAware 逻辑Jdk14LoggingImpljava.util.loggingJDK 自带无需额外依赖StdOutImpl无永远可用输出到 System.errNoLoggingImpl无空实现关闭日志2.4 一个值得留意的细节Log 接口里为什么没有 info 方法如果你看过其他日志框架的门面接口多半会条件反射地找info()。MyBatis 的Log接口里偏偏没有。为什么因为适配器模式的代价是每多一个接口方法所有适配器都要多写一个转发方法。如果加了info七个实现类全要跟着动。而 MyBatis 对日志的实际需求里根本没有 info 这个级别——SQL 语句在 debug 级别输出参数细节在 trace 级别输出错误在 error 级别输出够用了。这个取舍的本质是不为臆想的需求扩大适配成本。接口设计不是功能越多越好而是恰好覆盖真实需求才最好。3. LogFactory 的自动探测用 try-catch 替代依赖清单3.1 静态初始化块的试探顺序适配器都写好了那 MyBatis 怎么知道该用哪一个答案是在LogFactory的静态代码块里逐个试探。public final class LogFactory { private static Constructor? extends Log logConstructor; static { tryImplementation(new Runnable() { Override public void run() { useSlf4jLogging(); } }); tryImplementation(new Runnable() { Override public void run() { useCommonsLogging(); } }); // 依次尝试 log4j2、log4j、jdk 日志…… tryImplementation(new Runnable() { Override public void run() { useNoLogging(); } }); } }tryImplementation的逻辑很简单先调用某个useXxxLogging()方法如果成功就把对应的构造函数缓存到logConstructor如果方法内部抛了异常就静默吞掉继续试下一个。这一串方法本身也很直接比如public static synchronized void useLog4J2Logging() { setImplementation(org.apache.ibatis.logging.log4j2.Log4j2Impl.class); }这里面最关键的哲学是MyBatis 判断一个日志框架是否存在不是去读配置文件、不是去查某个注册表而是直接尝试实例化对应的适配器类。类能被加载、构造器能被调用说明框架在类加载失败抛出ClassNotFoundException或NoClassDefFoundError说明不在跳过即可。3.2 setImplementation 的反射缓存真正干活的setImplementation也值得看两眼private static void setImplementation(Class? extends Log implClass) { try { Constructor? extends Log candidate implClass.getConstructor(String.class); Log log candidate.newInstance(LogFactory.class.getName()); logConstructor candidate; } catch (Throwable t) { throw new LogException(Error setting Log implementation..., t); } }这里有个细节容易被忽略它不仅拿到了构造函数还立刻用这个构造函数new了一个 Log 实例出来。为什么要多此一举因为类能被加载不等于构造函数能被正常调用适配器类的构造函数里往往会做真实框架的初始化比如Log4jImpl构造时会执行Logger.getLogger(clazz)。这一步必须现在验证不然等真正执行 SQL 时才发现日志框架有问题那就太晚了。验证通过后的构造函数被缓存下来以后每次LogFactory.getLog(xxx.class)都是直接反射newInstance不会再重新探测。也就是说探测只在类加载时做一次运行时零成本。3.3 这个设计带来的运维便利“运行时手动指定”是这套设计里我个人用得最多的能力。LogFactory暴露了一批静态方法理论上在应用启动早期可以显式调用LogFactory.useSlf4jLogging()或LogFactory.useLog4J2Logging()来覆盖自动探测的结果。实际场景里这招很好使。我之前维护过一个老项目classpath 里同时存在 commons-logging 和 log4j自动探测的顺序导致 MyBatis 走了 commons-logging而这个 commons-logging 底层又没绑定好实现日志死活出不来。后来直接在启动初始化里显式指定 Log4j问题立刻解决一行源码都没改。这就是适配器模式给调用方留下的后门——因为它不跟任何具体框架耦合所以切换永远只需要一步。4. 代理模式的主战场JDBC 调用链上的三层动态代理4.1 代理从哪里来Connection 被包一层再进 Mapper适配器线讲完接下来是打印 SQL 的代理线。你在项目里看 MyBatis 打印的Preparing: select ...这种日志不是某个类里硬编码的输出而是一条动态代理链逐层包装出来的。MyBatis 在从数据源拿到Connection之后、把它交给后续 JDBC 操作之前会先看一眼日志开关// 简化示意实际在 BaseExecutor 里 Connection connection dataSource.getConnection(); if (log.isDebugEnabled() || log.isTraceEnabled()) { connection ConnectionLogger.newInstance(connection, statementLog, queryStack); }只要 debug 或 trace 级别开了拿到的Connection就不再是原始的Connection而是一个 JDK 动态代理。这个代理的InvocationHandler就是ConnectionLogger。想看懂这条链先得搞懂 JDK 动态代理的基本套路Proxy.newProxyInstance接收三个参数——类加载器、要实现的接口数组、InvocationHandler。之后所有对代理对象的方法调用都会先进InvocationHandler.invoke由你决定是拦截还是放行。4.2 ConnectionLogger 的 invoke拦截并包装返回值ConnectionLogger.invoke的骨架我把关键部分列出来public Object invoke(Object proxy, Method method, Object[] params) throws Throwable { try { if (Object.class.equals(method.getDeclaringClass())) { return method.invoke(this, params); } if (prepareStatement.equals(method.getName()) || prepareCall.equals(method.getName())) { if (isDebugEnabled()) { statementLog.debug( Preparing: removeBreakingWhitespace((String) params[0]), true); } Statement stmt (Statement) method.invoke(connection, params); return PreparedStatementLogger.newInstance(stmt, statementLog, queryStack); } else if (createStatement.equals(method.getName())) { Statement stmt (Statement) method.invoke(connection, params); return StatementLogger.newInstance(stmt, statementLog, queryStack); } return method.invoke(connection, params); } catch (InvocationTargetException e) { throw e.getCause(); } }这段代码信息量很大我拆成三点讲。第一Object.class.equals(method.getDeclaringClass())这个判断是防呆用的。如果调用的是equals、hashCode、toString这几个从 Object 继承来的方法就直接走this不做任何拦截。否则代理对象在打印、比较、进集合的时候会产生一堆莫名其妙的副作用。这个习惯我后来写任何自定义 InvocationHandler 都会带上。第二它只拦截创建语句的几个方法。close()、commit()、setAutoCommit()之类的常规方法直接method.invoke(connection, params)透传给真正的 Connection。第三也是最有意思的一点它拦截到prepareStatement之后把自己持有的 SQL 字符串打印出来然后调用真实的prepareStatement拿到PreparedStatement但这个 Statement 又被PreparedStatementLogger包了一层再返回。这就是所谓代理套代理。你从连接代理手里拿到的语句对象不是裸的 JDBC 对象而是下一层代理。这个模式在后面还会再套一层到ResultSet上。4.3 PreparedStatementLogger参数值是怎么进日志的连接层的代理只负责打印 SQL 骨架真正的参数和耗时在PreparedStatementLogger里。它的invoke简化的样子是这样的public Object invoke(Object proxy, Method method, Object[] params) throws Throwable { try { if (Object.class.equals(method.getDeclaringClass())) { return method.invoke(this, params); } if (execute.equals(method.getName()) || executeQuery.equals(method.getName()) || executeUpdate.equals(method.getName())) { if (isDebugEnabled()) { statementLog.debug( Parameters: getParameterValueString(), true); } long start System.currentTimeMillis(); Object result method.invoke(statement, params); if (isDebugEnabled()) { statementLog.debug( Updates: result , Time: (System.currentTimeMillis() - start), true); } if (result instanceof ResultSet) { return ResultSetLogger.newInstance((ResultSet) result, statementLog, queryStack); } return result; } return method.invoke(statement, params); } catch (InvocationTargetException e) { throw e.getCause(); } }参数值打印依赖的是BaseJdbcLogger里维护的三个列表列名列表、列类型列表、参数值列表。setXxx方法每被调用一次参数就会被记录进列表真正执行的时候getParameterValueString()把这些值拼出来所以我们能看到 Parameters: 1(Integer), 张三(String), 2(Integer)这种日志。注意几个细节。第一日志里出现的Time:字段就是这个代理计时算出来的。执行前取一个时间戳执行后再取一个差值就是单条 SQL 耗时排查慢 SQL 时特别有用。第二返回的ResultSet也被包了一层ResultSetLogger但那一层只统计命中行数不会把结果集内容全量打印否则生产环境的日志能被打爆。第三SQL 里的换行会被removeBreakingWhitespace替换掉保证一行 SQL 就是一整条日志肉眼可读。4.4 queryStack 与缩进为什么日志看起来有层级还有一个容易被忽略的字段是queryStack。这个计数器在每一层代理构造时都会加一BaseJdbcLogger格式化日志时根据它的值决定前缀缩进。于是你看到的日志会是这种效果 Preparing: select * from user where id ? Parameters: 1(Integer) Total: 1当你在一个 Mapper 方法里嵌套调用另一个 Mapper 方法时内层语句的缩进会更深一眼就能分辨执行层级。这个设计属于典型的日志体验打磨不是必须的但就是这点细节让日志在排错时格外好用。4.5 为什么用 JDK 动态代理而不是 CGLIBConnection、Statement、ResultSet 都是标准 JDK 接口JDK 动态代理正好只认接口所以不需要引入 CGLIB、ASM 这类字节码增强库。这是选型上的天然顺位。性能上JDK 代理每次调用都有反射开销但 MyBatis 在打印任何东西之前都会先查isDebugEnabled()/isTraceEnabled()。日志级别没开的时候代理链甚至根本不会被创建——前面那段if (log.isDebugEnabled())已经短路掉了。就算日志开了反射开销跟 SQL 本身的执行时间比也完全可以忽略。这就是用设计把性能成本控制在真正需要的场景里的典型做法。5. 模式叠加之后的工程启示从 MyBatis logging 反推自己的代码5.1 两条线是怎么汇合的前面分开讲了两条线现在收拢看一下它们怎么协作。当 MyBatis 决定输出一条 SQL 日志时调用路径是这样的应用执行 Mapper 方法拿到的是ConnectionLogger代理出来的 Connection。调用prepareStatement时代理拦截到 SQL用statementLog.debug()打印。这个statementLog是什么是LogFactory.getLog(...)创建出来的对象本质上是某个适配器实例。statementLog.debug()被适配器转发给底层框架最终落到 Logback、Log4j2 或标准输出。所以整条链路是业务调用 → JDBC 动态代理 → Log 接口 → 适配器 → 具体日志框架 → 输出。代理层完全不关心底层日志是谁它只面向Log接口编程适配器层完全不关心 SQL 长什么样它只负责方法转发。两边各自只依赖一个接口这就是面向接口编程在真实项目里的形态。5.2 值得带走的三个设计习惯第一个习惯是接口要小。Log接口只有 7 个方法这就是刻意控制适配成本的结果。反过来想想我们平时写 Service 接口动不动十几个方法每一个实现类都要臃肿一遍。接口每多一个方法所有实现方都多一份负担所以加方法之前应该先质疑它是否真的必要。第二个习惯是依赖探测放到运行时。MyBatis 没有在编译期绑死任何日志框架而是用 try-catch 的方式在运行时探明环境。这种思路很适合写框架、写公共组件你不知道使用方完整的 classpath 长什么样就不要替别人做决定。第三个习惯是职责严格分离。代理只负责拦截、转发、计时日志内容的拼装放在BaseJdbcLogger底层输出交给适配器。任何一个环节想改动都不需要动另外两个环节。这种边界感看着简单想长期守住不容易。5.3 什么情况下别抄这份设计也要泼一盆冷水不是所有项目都适合复刻这套设计。如果你写的只是一个普通业务应用日志框架早就定死了那直接用框架的门面注解就行完全没必要自己包一层Log接口。适配器模式的价值在于被适配对象不确定且会变化你的应用里如果没有这种不确定性抽象就是负资产。代理线同理。自己写的类如果不存在在调用前后统一打点、且不方便改源码的场景也不需要上动态代理。我见过一些项目拿 JDK 动态代理把所有 Service 都包了一层最后排查问题时光来回追代理就追得头疼。设计模式是解决问题的工具不是 KPI。6. 实操中绕不开的坑与调试思路6.1 动态代理下的 equals / hashCode / toString 陷阱自己写 InvocationHandler 最容易踩的坑就是忘了处理 Object 的三个方法。如果你不拦它们一旦业务代码把代理对象放进Set、打印出来、或者用 debug 工具观察就会得到完全看不懂的结果——比如日志输出一个ConnectionLogger$...xxxx这种类名加地址的字符串而且每次都不一样。MyBatis 的处理方式我已经说过了就是那句Object.class.equals(method.getDeclaringClass())。这里多说一句拦截到这些方法后method.invoke(this, params)里的this是 InvocationHandler 本身不是代理对象。这样hashCode和equals就会以 handler 的身份参与计算行为稳定可预期。这个习惯我建议直接抄进自己的代码。6.2 ClassLoader 不一致导致的类型转换异常JDK 动态代理有个隐形的坑Proxy.newProxyInstance的第一个参数是类加载器这个加载器必须能同时加载你要实现的接口和被代理的真实对象类型。在普通 Spring Boot 应用里一个全应用共享的 AppClassLoader 通常没问题但在老式容器部署、或者你自己搞了自定义类加载器的时候接口可能由父加载器加载实现类由子加载器加载这时候代理类生成不了或者生成了却强转失败报各种ClassCastException。踩过这个坑之后我的习惯是取接口的类加载器来创建代理而不是取实现类的。因为接口的加载器通常是更上层、更稳定的那个用它生成的代理才能对所有使用该接口的代码可见。6.3 日志看起来没生效的排查链路遇到 MyBatis 日志打不出来先别怀疑 bug按顺序查这几项基本都能定位第一确认代理链是否真的创建了。isDebugEnabled()是 false 的时候MyBatis 直接把原生 Connection 交出去压根不走代理所以把日志级别调到 debug 是第一步。第二确认LogFactory最终选中了哪个实现。MyBatis 启动时通常会打出类似 Logging initialized using slf4j ... 的提示看它就能知道走了哪个适配器。第三检查你当前日志框架自己的配置里对应 logger 的级别是不是被压住了。很多情况是 MyBatis 这边没问题是 logback.xml 或 log4j2.xml 里某个 logger 的 level 设成了 error。第四看有没有显式配置logImpl这个配置会覆盖自动探测的结果优先级最高。排查顺序其实就是先确认代理线通再确认适配线通最后看底层配置。把链路按层拆开问题从来不会同时在两层出现。6.4 我的实际体会这套设计在什么时候帮了大忙最后说一个实际经历。去年排查一个老系统的慢 SQL这个系统用的日志框架非常混乱业务代码里各种日志混着打。我打开 MyBatis 的 debug 日志后立刻就能看到每条 SQL 的Time:字段再配合queryStack的缩进一眼就看出是一条嵌套子查询层层累加导致的全表扫描。修完之后把日志级别调回 info代理链自动消失线上完全没有因为日志代码产生额外性能开销。后来我在另一个组件里也借鉴了这个思路对外提供接口时内部可选地包装一层代理来做统一审计开关一关就完全透明。这种可插拔的打点比到处硬编码日志要干净得多。再分享一个小技巧如果你也在读框架源码学设计模式优先挑这种小而完整的子包比如 MyBatis 的 logging、某连接池的空闲连接管理这类模块。它们因为职责单一设计意图不会被大量业务代码稀释是学习模式落地最好的样本。读的时候别只看 UML动手搜一下每个模式里的三角色分别对应哪些类像今天这样把角色拆出来比你背十遍定义都管用。
阅读完成 · 觉得有帮助?
咨询建站