Mybatis的log机制

比特织云人
• 阅读 800

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接口有以下实现:
Mybatis的log机制

我们可以看到,除了上面提到的针对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" />  <!-- 允许 JDBC 支持自动生成主键 -->
        <setting name="defaultExecutorType"      value="REUSE" /> <!-- 配置默认的执行器 -->
        <setting name="logImpl"                  value="SLF4J" /> <!-- 指定 MyBatis 所用日志的具体实现 -->
        <!-- <setting name="mapUnderscoreToCamelCase" value="true"/>  驼峰式命名 -->
    </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的虚拟类,专门用来提供数据库操作的日志记录能力,我们先看一下类结构:

Mybatis的log机制

有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打印记录数。

如果日志级别设置为TRACE,则ResultSetLogger会打印获取到的数据结果,内容会很多,一般来讲也没有什么意义,建议即使测试环境也不打开。

总结

通过对Mybatis的log框架源码的分析,我们知道了Mybatis日志的来龙去脉,SQL语句的打印是DEBUG级别的,正式环境下我们一般不会开DEBUG级别的日志,特殊情况需要观察正式环境下的SQL语句执行情况的话,可以只开启mapper接口的DEBUG日志。

上一篇 连接池 Druid (补充) - removeAbandoned

点赞
收藏
评论区
推荐文章
blmius blmius
3年前
MySQL:[Err] 1292 - Incorrect datetime value: ‘0000-00-00 00:00:00‘ for column ‘CREATE_TIME‘ at row 1
文章目录问题用navicat导入数据时,报错:原因这是因为当前的MySQL不支持datetime为0的情况。解决修改sql\mode:sql\mode:SQLMode定义了MySQL应支持的SQL语法、数据校验等,这样可以更容易地在不同的环境中使用MySQL。全局s
皕杰报表之UUID
​在我们用皕杰报表工具设计填报报表时,如何在新增行里自动增加id呢?能新增整数排序id吗?目前可以在新增行里自动增加id,但只能用uuid函数增加UUID编码,不能新增整数排序id。uuid函数说明:获取一个UUID,可以在填报表中用来创建数据ID语法:uuid()或uuid(sep)参数说明:sep布尔值,生成的uuid中是否包含分隔符'',缺省为
Jacquelyn38 Jacquelyn38
4年前
2020年前端实用代码段,为你的工作保驾护航
有空的时候,自己总结了几个代码段,在开发中也经常使用,谢谢。1、使用解构获取json数据let jsonData  id: 1,status: "OK",data: 'a', 'b';let  id, status, data: number   jsonData;console.log(id, status, number )
Stella981 Stella981
3年前
Mabatis中#{}和${}的区别
动态sql是mybatis的主要特性之一,在mapper中定义的参数传到xml中之后,在查询之前mybatis会对其进行动态解析。mybatis为我们提供了两种支持动态sql的语法:{}以及${}。  在下面的语句中,如果username的值为zhangsan,则两种方式无任何区别:selectfr
Wesley13 Wesley13
3年前
Java框架之Mybatis(二)
本文主要介绍Mybatis(一)之后剩下的内容:1mybatis中log4j的配置2dao层的开发(使用mapper代理的方式)3mybatis的配置详解4输入输出映射对应的类型(parameterType和resultType)5mybatis动态sql6mybatis中的一级缓存7mybat
Stella981 Stella981
3年前
MyBatis插件开发
MyBatis插件开发一、前言MyBatis在四大对象的创建过程中,都会有插件进行介入。插件可以利用动态代理机制一层层的包装目标对象,而实现在目标对象执行目标方法之前进行拦截的效果。MyBatis允许在已映射语句执行过程中的某一点进行拦截调用。默认情况下,MyBatis允许使用插件来拦截的方法调用包
Stella981 Stella981
3年前
Spring Boot日志集成
!(https://oscimg.oschina.net/oscnet/1bde8e8d00e848be8b84e9d1d44c9e5c.jpg)SpringBoot日志框架SpringBoot支持JavaUtilLogging,Log4j2,Lockback作为日志框架,如果你使用star
Stella981 Stella981
3年前
Mybatis日志信息
问题:开发组说MyBatis的日志信息只能通过顶级日志记录器在debug下打印SQL,所以测试时一大堆的信息,弄得个单元测试,启动要老半天。    为了解决这样的问题,我看了下开发组的日志信息配置,代码如下:log4j.logger.com.ibatisDEBUGlog4j.logger.com.ibatis.common.jdbc.Simp
Wesley13 Wesley13
3年前
MySQL部分从库上面因为大量的临时表tmp_table造成慢查询
背景描述Time:20190124T00:08:14.70572408:00User@Host:@Id:Schema:sentrymetaLast_errno:0Killed:0Query_time:0.315758Lock_
美凌格栋栋酱 美凌格栋栋酱
4个月前
Oracle 分组与拼接字符串同时使用
SELECTT.,ROWNUMIDFROM(SELECTT.EMPLID,T.NAME,T.BU,T.REALDEPART,T.FORMATDATE,SUM(T.S0)S0,MAX(UPDATETIME)CREATETIME,LISTAGG(TOCHAR(
比特织云人
比特织云人
Lv1
就算步伐很小,也要步步前进。
文章
4
粉丝
0
获赞
0