Mybatis的log机制

最新推荐文章于 2024-09-16 20:31:03 发布

weixin_44612246

最新推荐文章于 2024-09-16 20:31:03 发布

阅读量570

点赞数

文章标签： mybatis java 开发语言

本文链接：https://blog.csdn.net/weixin_44612246/article/details/130588430

版权

Mybatis的一个非常有用的附加功能就是能帮助我们打印执行过程中的log：sql语句、参数、执行结果等。这一特性在开发过程中非常有用，可以帮助我们快速高效定位开发过程中的问题。

今天我们从源码的角度研究一下Mybatis的log机制，主要包括两部分：

1. Mybatis的日志框架
2. 日志打印源码分析，也就是找到Mybatis源码中打印日志的地方

#### 日志框架#Log接口及其实现
目前java世界已经有如下非常优秀的日志框架：
1. Slf4j
2. CommonsLog
3. Log4J2
4. Log4J
5. JdkLog

Mybatis当然不会自己再实现一套日志框架，所谓Mybatis的日志框架，指的是Mybatis针对日志处理的内部实现，从而非常简单方便的支持上述各种主流日志框架。

首先，Mybatis定义了一个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);

}
```
Log接口定义了4种log级别，和上面提到的Java主流log框架的日志级别对应。

Log接口有以下实现：
![image.png](/img/bVc7L4L)

我们可以看到，除了上面提到的针对java主流log框架的实现之外，Mybatis还提供了其他的Log接口的实现，都非常简单，比如StdOutImpl就是直接System.out.println或者System.err.println，NoLoggingImpl就是没有log的意思。

java主流日志框架的实现类其实也非常简单：创建相应java日志框架的log对象作为Mybatis日志对象的代理对象，Mybatis需要记录日志的时候，委派给代理对象执行。

#### 日志框架#Log对象初始化
既然Mybatis支持各种java主流日志框架，那他到底是怎么决定具体使用哪个日志框架呢？其实就是Mybatis的log对象的初始化过程。

这个工作是LogFactory完成的。
```
private static Constructor<? extends Log> logConstructor;
//...
private LogFactory() {
// disable construction
}

```
***logFactory定义了一个静态Constructor变量logConstructor，并且把构造方法定义为private来阻止通过构造方法初始化，对外通过getLog方法提供Log对象：***
```
public static Log getLog(String logger) {
try {
return logConstructor.newInstance(logger);
} catch (Throwable t) {
throw new LogException("Error creating logger for logger " + logger + ". Cause: " + t, t);
}
}
```
getLog方法也非常简单，直接通过构造器logConstructor调用newInstance方法获取Log对象。所以，LogFactory的核心其实就应该是这个logConstructor的初始化过程了。

继续看源码：
```
static {
tryImplementation(LogFactory::useSlf4jLogging);
tryImplementation(LogFactory::useCommonsLogging);
tryImplementation(LogFactory::useLog4J2Logging);
tryImplementation(LogFactory::useLog4JLogging);
tryImplementation(LogFactory::useJdkLogging);
tryImplementation(LogFactory::useNoLogging);
}

...
private static void tryImplementation(Runnable runnable) {
if (logConstructor == null) {
try {
runnable.run();
} catch (Throwable t) {
// ignore
}
}
}

public static synchronized void useSlf4jLogging() {
setImplementation(org.apache.ibatis.logging.slf4j.Slf4jImpl.class);
}

public static synchronized void useCommonsLogging() {
setImplementation(org.apache.ibatis.logging.commons.JakartaCommonsLoggingImpl.class);
}
```
LogFactory定义了一个尝试创建日志实现对象的静态区，通过调用静态方法tryImplementation尝试创建日志对象，尝试的先后顺序就是我们文章开篇列出的日志框架的顺序，首先会尝试Slf4j、然后是CommonsLogging...最后使用NoLogging，不记录日志。

tryImplementation方法接收Runnable参数，调用的时候通过Lambda方式创建，分别指定为useSlf4jLogging()、useCommonsLogging()......等。通过调用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());
if (log.isDebugEnabled()) {
log.debug("Logging initialized using '" + implClass + "' adapter.");
}
logConstructor = candidate;
} catch (Throwable t) {
throw new LogException("Error setting Log implementation. Cause: " + t, t);
}
}
```
setImplementation创建日志实现类的构造器，只要该日志框架(比如Slf4j）的包引入到项目、创建该日志框架的日志对象成功的话，就一定能够获取到该日志对象的构造器，则将该构造器赋值给logConstructor。

这样，静态区6个tryImplementation方法的逻辑就清楚了：按照调用顺序，首先尝试初始化logConstructor为Slf4j的实现类，创建成功的话，后面的调用就会被直接跳过、不会生效了。创建不成功的话（比如Slf4j的包没有导入项目中）则尝试下一个......以此类推，最后一定会创建出来合适的logConstructor。

除了静态区的tryImplementation方法的调用先后顺序来决定日志框架的优先级（到底是使用哪一个日志框架）之外，其实Mybatis还提供了另外两种手动设置日志框架的方式：
1. 通过配置文件
2. 代码中直接调用LocFactory.useCustomLogging

配置文件：
```
   <settings>
       <setting name="cacheEnabled" value="true" /> 
       <setting name="useGeneratedKeys" value="true" /> 
       <setting name="defaultExecutorType" value="REUSE" /> 
       <setting name="logImpl" value="SLF4J" /> 
       
   </settings>
```
配置文件指定的日志实现类是和typeAlias配合生效的，Configuration中实例化的时候已经完成了注册：
```
typeAliasRegistry.registerAlias("SLF4J", Slf4jImpl.class);
typeAliasRegistry.registerAlias("COMMONS_LOGGING", JakartaCommonsLoggingImpl.class);
typeAliasRegistry.registerAlias("LOG4J", Log4jImpl.class);
typeAliasRegistry.registerAlias("LOG4J2", Log4j2Impl.class);
typeAliasRegistry.registerAlias("JDK_LOGGING", Jdk14LoggingImpl.class);
typeAliasRegistry.registerAlias("STDOUT_LOGGING", StdOutImpl.class);
typeAliasRegistry.registerAlias("NO_LOGGING", NoLoggingImpl.class);
```
配置文件在Mybatis初始化的过程中被读入，通过XMLConfigBuilder调用loadCustomLogImpl->Configuration.setLogImpl->LogFactory.useCustomLogging完成日志实现类的初始化。useCustomLogging方法代码我们上面已经看过了，直接调用setImplementation(clazz);方法无条件覆盖掉logConstructor，从而实现配置文件的最高优先级。

***所以，决定Mybatis日志实现类（最终到底使用哪一个日志框架）的优先顺序由低到高是：***
1. LogFactory静态区tryImplementation调用顺序指定
2. 通过配置文件指定
3. 用户代码中通过调用useCustomLogging随时指定，立即生效

Mybatis的日志框架分析完成，***小结一下：Mybatis支持Java主流框架，包括Slf4j/CommonLogging/log4J2/log4J/JDKLoging/NoLogging/或者用户自定义Logging（应该没有人这么干吧）。用户可以通过配置文件或者在代码中指定具体使用哪一个日志框架，不指定的话Mybatis自行按照以上优先级逐个尝试当前项目允许使用的日志框架（导入日志框架的包就可以使用）。***

#### SQL语句打印
允许Mybatis打印SQL语句的配置也比较简单：在日志配置文件中指定打开针对mapper接口类的DEBUG级别的日志。比如，我们项目中配置Mybatis使用Slf4j->logback作为日志框架，则需要在logback.xml做如下配置：
```
<logger name="com.myproject.mapper" level="debug" />
```
其中com.myproject.mapper是项目的mapper接口文件所在的包名称。

或者，基于Springboog的项目，直接在application.yml文件中添加：
```
logging:
level:
com.myproject.mapper: debug
```

配置的是mapper接口类的日志，顺着这个线索来找找Mybatis控制日志的代码：从Mapper接口出发。

前面的文章已经分析过了mapper.xml文件中的sql语句，初始化过程中被加载到Configuration中的mappedStatements中，最终被mapper接口的动态代理类通过调用MapperMethod的execute方法执行。

那我们就直接看 MapperMethod的execute方法，我们就以INSERT语句为代表：
```
public Object execute(SqlSession sqlSession, Object[] args) {
Object result;
switch (command.getType()) {
case INSERT: {
Object param = method.convertArgsToSqlCommandParam(args);
result = rowCountResult(sqlSession.insert(command.getName(), param));
break;
}
```
看DefaultSqlSession的insert方法，一直追下去，最后调用到Executor的prepareStatement方法：
```
private Statement prepareStatement(StatementHandler handler, Log statementLog) throws SQLException {
Statement stmt;
Connection connection = getConnection(statementLog);
stmt = handler.prepare(connection, transaction.getTimeout());
handler.parameterize(stmt);
return stmt;
}
```
这里看到了非常熟悉的获取数据库连接的语句，调用了getConnection（BaseExecutor中）方法：
```
protected Connection getConnection(Log statementLog) throws SQLException {
Connection connection = transaction.getConnection();
if (statementLog.isDebugEnabled()) {
return ConnectionLogger.newInstance(connection, statementLog, queryStack);
} else {
return connection;
}
}
```
看到这里会判断statementLog.isDebugEnabled()，如果log打开了debug level的话，调用了ConnectionLogger.newInstance方法，去看一眼代码：
```
public static Connection newInstance(Connection conn, Log statementLog, int queryStack) {
InvocationHandler handler = new ConnectionLogger(conn, statementLog, queryStack);
ClassLoader cl = Connection.class.getClassLoader();
return (Connection) Proxy.newProxyInstance(cl, new Class[]{Connection.class}, handler);
}
```
又是非常熟悉的JDK动态代理，说明返回的实际是数据库连接的动态代理对象。

真相渐渐浮出水面了，我们现在就要去认真研究一下这个ConnectionLogger对象了，因为我们要追查Mybatis日志的真相，这个类的名字实在太可疑了。

#### BaseJdbcLogger
Mybatis提供了一个叫BaseJdbcLogger的虚拟类，专门用来提供数据库操作的日志记录能力，我们先看一下类结构：

![image.png](/img/bVc7Nni)

有4个实现类，分别对应Connection、Statement、PrepareStatement和Resultset，4个实现类都实现了InvocationHandler接口，充当了JDK动态代理的回调类，所有对被代理Connection、Statement、PrepareStatement、ResultSet对象的方法调用，都会回调到动态代理类的invoke方法上。

所以我们直接看他们的invoke方法。

#### ConnectionLogger
直接看invoke方法：

```
@Override
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()) {
debug(" Preparing: " + removeExtraWhitespace((String) params[0]), true);
}
PreparedStatement stmt = (PreparedStatement) method.invoke(connection, params);
stmt = PreparedStatementLogger.newInstance(stmt, statementLog, queryStack);
return stmt;
} else if ("createStatement".equals(method.getName())) {
Statement stmt = (Statement) method.invoke(connection, params);
stmt = StatementLogger.newInstance(stmt, statementLog, queryStack);
return stmt;
} else {
return method.invoke(connection, params);
}
} catch (Throwable t) {
throw ExceptionUtil.unwrapThrowable(t);
}
}

```
看到了非常熟悉的、经常在日志中出现的内容“ Preparing：”，后面跟的就是要执行的sql语句。

而且，创建的prepareStatement之后，通过调用PreparedStatementLogger.newInstance创建代理对象，最终返回的是代理对象PreparedStatementLogger。

顺便说一句，我们现在项目中绝大多数情况应该都是使用prepareStatement了，Mybatis支持在配置文件中指定statementType，但是一般情况下建议不指定。不指定的话，默认也是PrepareStatement。所以绝大多数情况都是通过调用Connection的prepareStatement方法创建PrepareStatement的，日志里的Sql语句就是在这儿被打印的。

而且，上面我们也从代码角度一路跟踪过来了，连接创建以及statement的创建是mapper接口调用进来的，所以打开debug level的日志需要针对mapper包做配置。

#### PrepareStatementLogger
其实从日志追踪的角度看，代码就非常简单了：
```
@Override
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_METHODS.contains(method.getName())) {
if (isDebugEnabled()) {
debug("Parameters: " + getParameterValueString(), true);
}
clearColumnInfo();
if ("executeQuery".equals(method.getName())) {
ResultSet rs = (ResultSet) method.invoke(statement, params);
return rs == null ? null : ResultSetLogger.newInstance(rs, statementLog, queryStack);
} else {
return method.invoke(statement, params);
}
} else if (SET_METHODS.contains(method.getName())) {
if ("setNull".equals(method.getName())) {
setColumn(params[0], null);
} else {
setColumn(params[0], params[1]);
}
return method.invoke(statement, params);
} else if ("getResultSet".equals(method.getName())) {
ResultSet rs = (ResultSet) method.invoke(statement, params);
return rs == null ? null : ResultSetLogger.newInstance(rs, statementLog, queryStack);
} else if ("getUpdateCount".equals(method.getName())) {
int updateCount = (Integer) method.invoke(statement, params);
if (updateCount != -1) {
debug(" Updates: " + updateCount, false);
}
return updateCount;
} else {
return method.invoke(statement, params);
}
} catch (Throwable t) {
throw ExceptionUtil.unwrapThrowable(t);
}
}
```
同样，日志中非常熟悉的“Parameters ， Updates:”等内容出现了。

如果是executeQuery方法调用、需要返回ResultSet的话，通过ResultSetLogger.newInstance方法创建并返回ResultSet的代理对象ResultSetLogger。

#### ResultSetLogger
和ConnectionLoger、PreparedStatementLogger的invoke方法大同小异：
```
@Override
public Object invoke(Object proxy, Method method, Object[] params) throws Throwable {
try {
if (Object.class.equals(method.getDeclaringClass())) {
return method.invoke(this, params);
}
Object o = method.invoke(rs, params);
if ("next".equals(method.getName())) {
if ((Boolean) o) {
rows++;
if (isTraceEnabled()) {
ResultSetMetaData rsmd = rs.getMetaData();
final int columnCount = rsmd.getColumnCount();
if (first) {
first = false;
printColumnHeaders(rsmd, columnCount);
}
printColumnValues(columnCount);
}
} else {
debug(" Total: " + rows, false);
}
}
clearColumnInfo();
return o;
} catch (Throwable t) {
throw ExceptionUtil.unwrapThrowable(t);
}
}
```
调用ResultSet的next方法获取数据的过程中累加记录条数，获取数据结束后log打印记录数。