本文先介绍当mybatis 使用log4j时的配置原理,然后介绍如何在运行时动态的开关log!!!
无论使用哪一种ORM框架，我们都希望在开发的时候能打印出最后产生的SQL语句，网上有很多关于mybatis配置的文章，都是相互转载，而且让人郁闷的是都是基于ibatis时代的配置。javacoder.cn博主秉着知其然，必知其所以然的原则，决定对其源码进行一番分析。揭开log4j的日志到底是如何影响sql输出的。本文使用slf4j桥接log4j的日志实现，这样即使classpath下有别的日志jar,也能正常输出。文件结尾处有我调试跟踪时使用的demo,该demo基于maven,导入Eclipse就可以调试了，欢迎下载！！
1)假设classpath下有如下内容的log4j.properties

请求http://localhost:8080/testoom/test，发现控制台的输出为
DEBUG [http-bio-8080-exec-1] - ooo Using Connection [jdbc:mysql://localhost:3306/test UserName=root@localhost, MySQLDriver]
DEBUG [http-bio-8080-exec-1] - ==> Preparing: select * from application
DEBUG [http-bio-8080-exec-1] - ==> Parameters:
第一行是在org.apache.ibatis.logging.jdbc.ConnectionLogger.ConnectionLogger(Connection conn, Log statementLog)中输出的
第二行是在Object org.apache.ibatis.logging.jdbc.ConnectionLogger.invoke(Object proxy, Method method, Object[] params)throws Throwable中输出的
第三行是在Object org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(Object proxy, Method method, Object[]params) throws Throwable中输出的。

接下来我们详细分析ConnectionLogger(Connection conn, Log statementLog)方法

跟踪isDebugEnabled()，

statementLog是org.apache.ibatis.logging.slf4j.Slf4jImpl的实例，层层深入
org.slf4j.impl.Log4jLoggerAdapter.isDebugEnabled()
org.apache.log4j.Logger.isDebugEnabled()
最后真正的逻辑Category.getEffectiveLevel(),Category是org.apache.log4j.Logger的父类。

查看this的值，如图

注意"cn.javacoder.testoom.mapper"指的是Mapper的namespace的前缀，而不是dao的完整包名的前缀，切记！！

看到这张图，大家一定豁然开朗了。log4j就是按照完整包名来查找日志等级的，越详细优先级越高，在我们的例子中先在"cn.javacoder.testoom.mapper.TestMapper.select"对应的logger对象中匹配，由于我们没有指定日志等级，所以查找它的parent 对象，在本例中parent对象是"log4j.logger.cn.javacoder.testoom.mapper"对应的logger对象，匹配，返回该对象对应的Level. 在这个链当中，最后是RootLogger对象。

再回头看ConnectionLogger.isDebugEnabled()方法，我们刚才分析了"statementLog.isDebugEnabled() || getLog().isDebugEnabled()"的前面一个分支，如果将log4j.logger.cn.javacoder开始的行注释掉，启用log4j.logger.java.sql开始的行，那么就会执行getLog().isDebugEnabled()对应的判断。我们还是按照刚才的方式继续跟踪函数调用，最后我们按照一样的路径到达Category.getEffectiveLevel()方法。
此时this值如图

先判断"java.sql.Connection"对应的logger对象是否指定了Level对象，没有指定就返回parent RootLogger对应的日志等级,在mybatis中，分别对java.sql.Connection, java.sql.ResultSet, java.sql.Statement, java.sql.PreparedStatem对象进行了封装，这个子类一个重要的任务就是调试日志功能的支持：类图如下：

在log4j.Category类中，很多的成员属性都声明为volatile，这引起了我的兴趣。直觉告诉我，logger对象的层级是可以动态改变的，于是决定删除log4j.properties中的所有配置，然后在代码中动态的启用日志等级。
我在TestController.main中打一个断点，然后在Expressions窗口中输入org.apache.log4j.Logger.getLogger("cn.javacoder.testoom.mapper")获取Logger 对象，然后如图改变Logger的Level，完美的打印出log;当不需要日志时，将Logger.level设为null,如图：

结束语：

我们既可以通过mapper的namespace来指定哪些SQL需要输出，也可以通过对java.sql.*包的接口指定日志等级为DEBUG来全局的启用输出SQL功能，前缀的优先级大于后者，还可以再运行时动态的启用SQL输出功能。

demo 下载：test-oom-javacoder.cn

Posted in: Mybatis practise | Tags: Log, Log4j, mybatis