在不同版本的MyBatis中通过Log4j打印实际执行的SQL
文章目录
项目中ORM框架用的是 MyBatis，最近由于业务上的需求将MyBatis从3.1.1升级到3.4.5，发现升级后通过Log4j显示SQL的配置方式发生了变化，由于变化较大，故先记录下。
假设我们测试的sql文件为UserMapper.xml ， 对应的代码如下，其命名空间为com.lucumt.mapper.UserMappper
<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE mapper PUBLIC "-//mybatis.org//DTD Mapper 3.0//EN" "http://mybatis.org/dtd/mybatis-3-mapper.dtd">
<mapper namespace="com.lucumt.mapper.UserMappper">
<select id="getUsers" parameterType="String" resultType="com.lucumt.model.UserModel">
SELECT id,username,password,create_time AS createTime FROM system_users WHERE username!=#{username}
</select>
</mapper>
对应的执行代码如下
@Test
public void testMybatis(){
String resource = "mybatis-config.xml";
InputStream is = AppTest.class.getClassLoader().getResourceAsStream(resource);
SqlSessionFactory sessionFactory = new SqlSessionFactoryBuilder().build(is);
SqlSession session = sessionFactory.openSession();
String statement = "com.lucumt.mapper.UserMappper.getUsers";
List<UserModel> userList = session.selectList(statement, "admin");
for(UserModel u:userList){
System.out.println(u.toString());
}
}
本文会基于上述代码说明不同版本下如何利用Log4j在MyBatis中配置打印日志以及其实现原理。
MyBatis3.1.1分析
Log4j相关配置
在MyBatis3.1.1及以前的版本中若我们想通过Log4j配置来打印实际执行的SQL，log4j.properties的配置通常类似如下
# 在不开启log4j DEBUG模式下显示mybatis中运行的SQL语句
log4j.logger.java.sql.Connection=DEBUG
log4j.logger.java.sql.Statement=DEBUG
log4j.logger.java.sql.PreparedStatement=DEBUG
log4j.logger.java.sql.ResultSet=DEBUG
原理分析
以log4j.logger.java.sql.Connection=DEBUG这个配置为例，分析源码可知其sql日志来源于ConnectionLogger，查看 ConnectionLogger的代码可知ConnectionLogger以硬编码的方式生成了一个log对象,当DEBUG模式开启时该log对象会打印sql语句等信息。
public final class ConnectionLogger extends BaseJdbcLogger implements InvocationHandler {
//生成一个Connection的log
private static final Log log = LogFactory.getLog(Connection.class);
private Connection connection;
private ConnectionLogger(Connection conn, Log statementLog) {
super(statementLog);
this.connection = conn;
if (isDebugEnabled()) {
debug("ooo Using Connection [" + conn + "]");
}
}
public Object invoke(Object proxy, Method method, Object[] params)
throws Throwable {
try {
if ("prepareStatement".equals(method.getName())) {
if (isDebugEnabled()) {//打印执行的SQL语句
debug("==> Preparing: " + removeBreakingWhitespace((String) params[0]));
}
PreparedStatement stmt = (PreparedStatement) method.invoke(connection, params);
stmt = PreparedStatementLogger.newInstance(stmt, getStatementLog());
return stmt;
}
//... other code
} catch (Throwable t) {
throw ExceptionUtil.unwrapThrowable(t);
}
}
//... other code
}
运行结果如下
从上述代码可知在Mybatis3.1.1中通过Log4j实现打印执行SQL的操作很简单，实现原理也易懂，但其存在的一个缺点: 当开启打印SQL日志后，会打印所有正在执行的SQL语句，不能实现针对特定SQL的打印 ，基于此MyBatis从3.2.0版本之后重新实现了相关功能。
MyBatis3.4.5分析
Log4j相关配置
在MyBatis3.2.0及以后的版本中若我们想通过Log4j配置来打印实际执行的SQL，log4j.properties的配置通常类似如下
# 在不开启log4j DEBUG模式下显示mybatis中运行的SQL语句
log4j.logger.com.lucumt.mapper=DEBUG
在本文写作时，mybatis官网上已有关于这方面更 详细的说明 。
原理分析
同样以log4j.logger.java.sql.Connection=DEBUG为例，其sql日志来源于ConnectionLogger，对应代码如下
public final class ConnectionLogger extends BaseJdbcLogger implements InvocationHandler {
private final Connection connection;
//通过注入的方式生成log对象
private ConnectionLogger(Connection conn, Log statementLog, int queryStack) {
super(statementLog, queryStack);
this.connection = conn;
}
@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())) {
if (isDebugEnabled()) {
debug(" Preparing: " + removeBreakingWhitespace((String) params[0]), true);
}
}
//... other code
} catch (Throwable t) {
throw ExceptionUtil.unwrapThrowable(t);
}
}
//... other code
}
从上述代码可知，其日志生成是调用BaseJdbcLogger的构造方法生成的，BaseJdbcLogger 代码如下
public abstract class BaseJdbcLogger {
protected Log statementLog;
protected int queryStack;
public BaseJdbcLogger(Log log, int queryStack) {
this.statementLog = log;
if (queryStack == 0) {
this.queryStack = 1;
} else {
this.queryStack = queryStack;
}
}
//... other code
}
DEBUG模式下查看ConnectionLogger的调用堆栈如下
从其调用堆栈可知log对象是通过MappedStatement生成的，如下
public class SimpleExecutor extends BaseExecutor {
//... other code
@Override
public <E> List<E> doQuery(MappedStatement ms,Object parameter,
RowBounds rowBounds, ResultHandler resultHandler, BoundSql boundSql) throws SQLException {
Statement stmt = null;
try {
Configuration configuration = ms.getConfiguration();
StatementHandler handler = configuration.newStatementHandler(wrapper, ms, parameter, rowBounds, resultHandler, boundSql);
//log对象通过MappedStatement生成
stmt = prepareStatement(handler, ms.getStatementLog());
return handler.<E>query(stmt, resultHandler);
} finally {
closeStatement(stmt);
}
}
}
查看MappedStatement的源码，发现log的生成是在Builder方法中，如下
public final class MappedStatement {
public static class Builder {
private MappedStatement mappedStatement = new MappedStatement();
public Builder(Configuration configuration, String id, SqlSource sqlSource, SqlCommandType sqlCommandType) {
mappedStatement.configuration = configuration;
mappedStatement.id = id;
mappedStatement.sqlSource = sqlSource;
mappedStatement.statementType = StatementType.PREPARED;
mappedStatement.parameterMap = new ParameterMap.Builder(configuration, "defaultParameterMap", null, new ArrayList<ParameterMapping>()).build();
mappedStatement.resultMaps = new ArrayList<ResultMap>();
mappedStatement.sqlCommandType = sqlCommandType;
mappedStatement.keyGenerator = configuration.isUseGeneratedKeys() && SqlCommandType.INSERT.equals(sqlCommandType) ? Jdbc3KeyGenerator.INSTANCE : NoKeyGenerator.INSTANCE;
String logId = id;
//可以通过设置logPrefix的方法来生成log对象
if (configuration.getLogPrefix() != null) {
logId = configuration.getLogPrefix() + id;
}
//通过logId生成log对象
mappedStatement.statementLog = LogFactory.getLog(logId);
mappedStatement.lang = configuration.getDefaultScriptingLanguageInstance();
}
}
通过上面的代码可知log对象是由logId生成的，进一步debug发现logId是由 namespace+方法id 组成，在本例中为com.lucumt.mapper.UserMappper.getUsers，而前面的配置为log4j.logger.com.lucumt.mapper=DEBUG ，由于Log4j中的log示例的继承关系，相当于com.lucumt.mapper.UserMappper.getUser也开启了DEBUG模式，故在实际执行时可以显示打印SQL语句，运行结果如下
利用新版MyBatis的这一特性，我们可以实现类似如下的不同粒度sql打印
log4j.logger.com.xxx.mapper=DEBUG #打印xxx包下所有的执行SQL
log4j.logger.com.yyy.mapper.PersonMapper=DEBUG #打印PersonMapper下所有的执行SQL
log4j.logger.com.zzz.mapper.GroupMapper.getGroups=DEBUG #只打印getGroups对应的执行SQL
由前面的代码可知MappedStatement的Build方法在生成log对象时会检测是否有logPrefix配置，若有则用logPrefix来生成log对象，于是可以通过设置logPrefix以另外一种方式配置打印sql。 可在MyBatis配置文件中添加如下配置
<settings>
<setting name="logPrefix" value="dao."/> <!-- 设置前缀为dao -->
<setting name="logImpl" value="log4j"/> <!-- 设置使用log4j为日志实现类 -->
</settings>
然后将 log4j.properties的配置修改为
log4j.logger.dao=DEBUG
执行结果与前面相同，通过 logPrefix可以在有些时候简化sql打印配置。
待分析问题
若将MyBatis的版本变3.3.0时，通过Log4j配置打印SQL时，如下所示的配置方式只有部分生效，原因待分析
log4j.logger.com.xxx=DEBUG #可以打印SQL
log4j.logger.com.xxx.mapper=DEBUG #可以打印SQL
log4j.logger.com.xxx.mapper.UserMapper=DEBUG #不能打印SQL
log4j.logger.com.xxx.mapper.UserMapper.getUsers=DEBUG #不能打印SQL
文章作者 飞狐
上次更新 2017-12-18