前言
在上一章当中我们介绍了MyBatis的日志模块没有自己的具体实现，而是通过适配器模式兼容了其它主流日志组件的功能。这样通过org.apache.ibatis.logging.Log就可以打印日志了。本章我们来聊一聊MyBatis的日志增强，什么是日志增强呢？在我们执行数据库查询的时候，希望通过日志查看到查询语句和查询参数、以及查询的结果，这一块的功能相对于主要业务来说算是额外功能了，因为没有也并不影响系统的运行。MyBatis恰好为我们提供了这种增强，只要通过简单的方式就可以开启和关闭日志功能
MyBatis日志增强简单介绍
当我们执行mapper接口的时候，控制台会出现如下的日志信息。
其中带有Cache Hit Ratio是关于二级缓存的命中率的，带有==> Preparing:的是预编译的SQL语句（select * from city where state = ?），带有==> Parameters:是对应的参数（CA(String)），带有<==是查询结果。
在Spring Boot项目中默认是不会打印这个日志的。因为Spring Boot的默认日志级别为INFO，可以在配置文件中将日志级别改为DEBUG
logging.level.root=DEBUG
可以看到这里确实打印了相关日志，但是这样做的后果就是由于日志级别的调低导致其他的模块也一起打印了很多日志，需要更细粒度的配置才好。我们当前的mapper接口放在目录sample.mybatis.mapper下，所以修改我们的配置文件
#logging.level.root=DEBUG
logging.level.sample.mybatis.mapper=DEBUG
通过精确针对MyBatis的mapper接口日志级别调整，现在可以控制只有MyBatis接口的日志会打印了。不过这里还有另一个问题，就是和一开始的日志有点不一样，就是一个包含了返回的查询结果，而现在只有一个Total记录返回数量。那如何配置才能显示返回的结果呢？其实也比较简单，继续调低日志级别就可以了。
可以看出，对于返回结果日志的级别为最低的，为TRACE，为啥要这么设计呢？打印日志终究会影响系统的性能，而且大量日志会占用磁盘的容量，一个系统很大概率上需要查询数据库大量的数据，如果此时把结果都打印出来，无疑会导致日志文件的暴增，而查询语句与参数以及简单的结果计数相比起来就微乎其微了。MyBatis的考虑真的是非常周到呀。
MyBatis日志增强源码分析
可以看出，对于返回结果日志的级别为最低的，为有时候我们在项目当中，一个日志级别用到底是不是有改善的空间？以上这种情况其实还是比较简单的，因为项目比较小，mapper接口都放在一个路径下，如果在一个大型项目中，mapper接口分布在十几个不同的包中，针对每个目录就需要单独的配置了。比如说一般一个项目的包都有自己的前缀，比如在上面的项目中就是sample.mybatis，如果我们给这个路径设置目录级别为DEBUG或是TRACE，且好这个目录下不少业务类使用DEBUG级别的日志来打印重要信息，那就有点坑了！为啥这么说。首先我们通常希望对于一个引用的第三方包通过一个日志级别的配置就可以精确重要的日志和不重要的日志了，而现在这个项目都以DEBUG级别，具体到每一个包又会导致配置太多，直接使用logging.level.sample.mybatis=DEBUG又会导致数据层的日志打印（其实业务代码里重要的信息还是应该调高日志级别的，与不重要的信息的日志级别区分开）。有没有一种办法可以直接关闭所有MyBatis的日志呢？那么下面我们来研究一下MyBatis是如何实现日志增强功能的。
在MyBatis中真正执行数据库操作的为org.apache.ibatis.executor.Executor这个接口，它的实现如上图所示，如果看过前面关于一级缓存和二级缓存的章节，应该对这两个都不会陌生，其中一级缓存是在BaseExecutor中实现的，而二级缓存是在CachingExecutor中实现的，实际执行中根据ExecutorType的值选择不同的真实实现类。对应的源码在org.apache.ibatis.session.Configuration#newExecutor
protected ExecutorType defaultExecutorType = ExecutorType.SIMPLE;
public Executor newExecutor(Transaction transaction, ExecutorType executorType) {
1. 如果用户没有设置executorType，则使用默认值SIMPLE
executorType = executorType == null ? defaultExecutorType : executorType;
executorType = executorType == null ? ExecutorType.SIMPLE : executorType;
2. 根据executorType选择Executor的真实实现
Executor executor;
if (ExecutorType.BATCH == executorType) {
executor = new BatchExecutor(this, transaction);
} else if (ExecutorType.REUSE == executorType) {
executor = new ReuseExecutor(this, transaction);
} else {
executor = new SimpleExecutor(this, transaction);
}
3. 如果支持二级缓存 则通过装饰器模式再包装一层
if (cacheEnabled) {
executor = new CachingExecutor(executor);
}
4. 通过动态代理添加拦截器 这里可以暂时不关心
executor = (Executor) interceptorChain.pluginAll(executor);
return executor;
}
分析源码以及继承关系，可以得出结论无论是那种模式，最后都会涉及到BaseExecutor这个类，因为另外三个类继承自BaseExecutor这个抽象类，然后再实现各自不同的特色操作罢了，这也是模板模式的使用。主要逻辑实在抽象类中实现的，而子类实现如下抽象方法
在这个抽象类BaseExecutor中有如下这段代码
org.apache.ibatis.executor.BaseExecutor#getConnection
protected Connection getConnection(Log statementLog) throws SQLException {
Connection connection = transaction.getConnection();
if (statementLog.isDebugEnabled()) {
// 不判断 全部采用日志
return ConnectionLogger.newInstance(connection, statementLog, queryStack);
} else {
return connection;
}
}
这里就是是否需要进行日志增强的关键之处，上面为啥要分析子类父类还有抽象类的关系呢？其实就是要得出一个结论，无论采用什么模式，执行数据库获取连接都要通过这一段代码（相同的逻辑在父类中实现）。
在以上代码中，如果当前支持Debug日志级别，则会通过ConnectionLogger这个类创建一个连接，否则就使用从事务中获取的连接。
/*
* Creates a logging version of a connection
*
* @param conn - the original connection
* @return - the connection with logging
*/
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);
}
看到Proxy.newProxyInstance，应该就立刻明白了，其实并没有真的再次创建另一个连接，而是针对原来的连接做了增强，主要增强的逻辑需要看InvocationHandler的invoke方法。在这里就是ConnectionLogger(实现了InvocationHandler接口)。
invoke方法如下
@Override
public Object invoke(Object proxy, Method method, Object[] params) throws Throwable {
try {
1. 如果是继承自Object的方法 则直接调用 不需要增强 比如hashCode equals wait这些方法
if (Object.class.equals(method.getDeclaringClass())) {
return method.invoke(this, params);
}
2. 方法名称为prepareStatement
if ("prepareStatement".equals(method.getName())) {
if (isDebugEnabled()) {
2.1 如果statementLog的日志级别为DEBUG 则打印日志
比如我们前面的 Preparing: select * from city where state = ?
debug(" Preparing: " + removeBreakingWhitespace((String) params[0]), true);
}
2.2 调用真实的方法也就是prepareStatement，该方法会返回一个PreparedStatement对象
PreparedStatement stmt = (PreparedStatement) method.invoke(connection, params);
2.3 针对返回的PreparedStatement增强
stmt = PreparedStatementLogger.newInstance(stmt, statementLog, queryStack);
return stmt;
} else if ("prepareCall".equals(method.getName())) {
if (isDebugEnabled()) {
debug(" Preparing: " + removeBreakingWhitespace((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);
}
}
仔细阅读以上的逻辑不难发现，这里无非针对特定的方法比如prepareStatement额外做了以下两个操作：
1. 根据日志级别是否符合在方法执行前打印日志
2. 针对返回的对象做增强，对应代码如下,依然是动态代理，以前面的逻辑完全一致
/*
* Creates a logging version of a PreparedStatement
*
* @param stmt - the statement
* @param sql - the sql statement
* @return - the proxy
*/
public static PreparedStatement newInstance(PreparedStatement stmt, Log statementLog, int queryStack) {
InvocationHandler handler = new PreparedStatementLogger(stmt, statementLog, queryStack);
ClassLoader cl = PreparedStatement.class.getClassLoader();
return (PreparedStatement) Proxy.newProxyInstance(cl,
new Class[] { PreparedStatement.class, CallableStatement.class }, handler);
}
在SimpleExecutor这个真实实现中的执行逻辑如下，因为MyBatis这一段逻辑比较分散，这里放在一起，实际代码是分散在各个类里面的
1. 获取连接
Connection connection = getConnection(statementLog);
2. 预编译
stmt = handler.prepare(connection, transaction.getTimeout());
3. 设置参数
handler.parameterize(stmt);
4. 执行数据库查询操作
PreparedStatement ps = (PreparedStatement) stmt;
ps.execute();
5. 获取执行结果
ResultSet rs = stmt.getResultSet();
if (rs == null) {
6. 这里会调用rs.getMetaData等rs的各种方法获取结果
return getNextResultSet(stmt);
} else {
return new ResultSetWrapper(rs, configuration);
}
由于日志增强，这里通过stmt的所有操作包括设置参数、执行数据库操作还有查询执行结果都会进入到通过以上生成的代理实现类PreparedStatementLogger的invoke方法当中。
这个集合是在BaseJdbcLogger（抽象父类）中定义的
protected static final Set<String> EXECUTE_METHODS = new HashSet<String>();
@Override
public Object invoke(Object proxy, Method method, Object[] params) throws Throwable {
try {
1. 同样针对Object类中定义的方法不特殊处理 直接调用
if (Object.class.equals(method.getDeclaringClass())) {
return method.invoke(this, params);
}
2. 包含在EXECUTE_METHODS集合中的方法名称执行增强逻辑
if (EXECUTE_METHODS.contains(method.getName())) {
2.1 打印参数
Parameters: CA(String)
if (isDebugEnabled()) {
debug("Parameters: " + getParameterValueString(), true);
}
clearColumnInfo();
2.2 执行ps的方法 如果是查询方法也就是executeQuery
if ("executeQuery".equals(method.getName())) {
ResultSet rs = (ResultSet) method.invoke(statement, params);
2.3 针对返回的ResultSet进行增强
return rs == null ? null : ResultSetLogger.newInstance(rs, statementLog, queryStack);
} else {
2.2 如果非查询方法 比如更新方法execute 是没有返回值
return method.invoke(statement, params);
}
} else if (SET_METHODS.contains(method.getName())) {
3. set方法不需要增强
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())) {
4. 通过getResultSet返回ResultSet结果
ResultSet rs = (ResultSet) method.invoke(statement, params);
如果返回的结果不为空 则继续增强
return rs == null ? null : ResultSetLogger.newInstance(rs, statementLog, queryStack);
} else if ("getUpdateCount".equals(method.getName())) {
5. 获取更新的结果数量 这里需要记录日志
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);
}
}
接下来如果返回结果包含ResultSet，按照同样的模式进行增强org.apache.ibatis.logging.jdbc.ResultSetLogger#newInstance.
/*
* Creates a logging version of a ResultSet
*
* @param rs - the ResultSet to proxy
* @return - the ResultSet with logging
*/
public static ResultSet newInstance(ResultSet rs, Log statementLog, int queryStack) {
InvocationHandler handler = new ResultSetLogger(rs, statementLog, queryStack);
ClassLoader cl = ResultSet.class.getClassLoader();
return (ResultSet) Proxy.newProxyInstance(cl, new Class[] { ResultSet.class }, handler);
}
同样接下来针对ResultSet的所有操作，都会进入到org.apache.ibatis.logging.jdbc.ResultSetLogger#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;
这里的几个打印日志级别都是trace
printColumnHeaders(rsmd, columnCount);
}
这里的几个打印日志级别都是trace
printColumnValues(columnCount);
}
} else {
打印总条数的日志界别为debug
debug(" Total: " + rows, false);
}
}
clearColumnInfo();
return o;
} catch (Throwable t) {
throw ExceptionUtil.unwrapThrowable(t);
}
}
最后的调用过程如下所示，通过动态代理给Connection、Statement、ResultSet添加了日志功能。
如果在一开始获取的不是Connection的代理，则后续都不会带有日志功能。
一个配置解决所有MyBatis日志的开关问题
所以最后最关键的点就是我们一开始的那个判断语句，我们回顾一下：
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究竟是什么意思呢？根据调用栈我们可以发现原来这个statementLog是MappedStatement的一个属性。什么是MappedStatement呢？如果看过前面关于二级缓存一章的话一定不会陌生，这个类就是代表mapper接口中的一个方法（mapper配置文件中的select|insert|update|delete标签）的抽象。
在项目启动过程中解析mapper文件构造MappedStatement对象时会通过LogFactory创建这个statementLog属性值（实现的就是上一章中我们说到的日志组件org.apache.ibatis.logging.Log）。
这里在getLog方法中传入的logId就是开启日志和设置日志级别的关键。从上面可以看出这个值默认为mapper文件的namespace+id，也就是对应接口的类名称和方法名称组成的字符串。这下我们应该就会对我们一开始通过以下方式开启MyBatis日志感到奇怪了。
logging.level.sample.mybatis.mapper=TRACE
如果再仔细看一下这和logId的取值，我们会发现其实还与全局配置中的logPrefix有关系。
然后我们在mybatis-config.xml文件中加入以下配置项
<settings>
<setting name="logPrefix" value="org.apache.ibatis."/>
</settings>
运行的结果如下
为啥呢？看下图
此时的logId都包含了我们配置的前缀了。随意现在改如何开启MyBatis的日志功能呢?修改Spring Boot项目的配置文件即可
mybatis.config-location=classpath:mybatis-config.xml
#logging.level.root=DEBUG
# 如果设置config-location读取配置文件，就通过这种方式设置logId前缀
# mybatis.configuration.log-prefix=org.apache.ibatis.
# 一个配置开启和关闭MyBatis的日志功能
logging.level.org.apache.ibatis=TRACE
如果打印部分日志
不打印日志，提高日志级别即可
另外这里提一句，在与Spring结合的项目中，通常可能不使用MyBatis的配置文件，此时可以通过SpringBoot提供的配置设置日志的前缀
# 如果设置config-location读取配置文件，就通过这种方式设置logId前缀
mybatis.configuration.log-prefix=org.apache.ibatis.
总结
MyBatis通过代理模式为JDBC的主要组件Connection、Statement、ResultSet提供了日志功能，代理模式是非常重要的设计模式，在MyBatis中大量使用了这种模式。而且是动态代理。因为静态代理模式需要代理对象和目标对象实现同样的接口，会产生过多的代理类，而且不易维护，一旦接口增加方法，目标对象和代理对象都需要进行修改。而动态代理动态的在内存中代理对象，修改原有接口不需要修改代理类。
328
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
