深入mybatis日志模块源码

最新推荐文章于 2024-06-05 20:55:01 发布

Cloud_N

最新推荐文章于 2024-06-05 20:55:01 发布

阅读量1.7k

点赞数

分类专栏： ORM 文章标签： mybatis mybatis日志模块

本文链接：https://blog.csdn.net/hfismyangel/article/details/80367528

版权

ORM 专栏收录该内容

1 篇文章 0 订阅

订阅专栏

mybatis打出的日志是这样的：

2018-05-18 17:17:09,870|DEBUG|c.i.c.d.m.B.listByKeys|debug|dao|[http-nio-8090-exec-3]|xlk|icu|127.0.0.1|133455757jhbr2ty5|75007|==>  Preparing: SELECT * FROM department WHERE id IN ( ? ) 
2018-05-18 17:17:09,871|DEBUG|c.i.c.d.m.B.listByKeys|debug|dao|[http-nio-8090-exec-3]|xlk|icu|127.0.0.1|133455757jhbr2ty5|75007|==> Parameters: 3647(Integer)
2018-05-18 17:17:09,875|DEBUG|c.i.c.d.m.B.listByKeys|debug|dao|[http-nio-8090-exec-3]|xlk|icu|127.0.0.1|133455757jhbr2ty5|75007|<==      Total: 1

也就是说sql、参数和返回值分别通过三条log打印，这种格式打印的日志通过elk进入kibana后也是分成三条消息显示，很不直观，需要一条一条打开看。那有没有办法将这三条日志合为一条呢，最终想要的效果如下：

2018-05-18 17:17:09,870|DEBUG|c.i.c.d.m.B.listByKeys|debug|dao|[http-nio-8090-exec-3]|xlk|icu|127.0.0.1|133455757jhbr2ty5|75007|==>  Preparing: SELECT * FROM department WHERE id IN ( ? ) 
    ==> Parameters: 3647(Integer)
    <==      Total: 1

使用logstash的正则再合并三条日志消息可能非常麻烦，第一个想法是从mybatis的日志入手，看有没有什么好的办法修改日志格式。

先从最基本的logFactory入手，logFactory有一个静态代码块，根据其顺序开启6个线程分别加载slf4j,apache commons,log4j2,log4j,jdk logging。如果前一个日志组件被加载，则后面的日志组件均不会被初始化。这里把初始化的过程全部写在静态代码块里了，值得商榷，而且开了6个线程加载，没太看懂，静态块代码只加载一次，不知道useSlf4jLogging等方法为什么要加锁。而且开多个线程并不能加快日志加载速度。

static {
    tryImplementation(new Runnable() {
      @Override
      public void run() {
        useSlf4jLogging();
      }
    });
    tryImplementation(new Runnable() {
      @Override
      public void run() {
        useCommonsLogging();
      }
    });
    tryImplementation(new Runnable() {
      @Override
      public void run() {
        useLog4J2Logging();
      }
    });
    tryImplementation(new Runnable() {
      @Override
      public void run() {
        useLog4JLogging();
      }
    });
    tryImplementation(new Runnable() {
      @Override
      public void run() {
        useJdkLogging();
      }
    });
    tryImplementation(new Runnable() {
      @Override
      public void run() {
        useNoLogging();
      }
    });
  }

mybatis分别为以上几个日志进行了包装，并实现mybatis的Log接口。然后通过日志的类对象获取构造器构造出相应的log实现类。此时日志组件已加载完成。tryImplementation方法中的线程异常捕获的是Throwable，而且完全被忽略了。。。可以说写的也蛮糟糕的

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);
  }... ...

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

  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);
    }
  }

下面是BaseExecutor中获取connection的方法，这里只分析日志组件的运行流程，mybatis的executor及运行原理不做分析。

protected Connection getConnection(Log statementLog) throws SQLException {
    Connection connection = transaction.getConnection();
    if (statementLog.isDebugEnabled()) {
      return ConnectionLogger.newInstance(connection, statementLog, queryStack);
    } else {
      return connection;
    }
  }

先往下看，这个是BaseExecutor的子类SimpleExecutor的几个查询方法，可以看到方法入参中均传入了MappedStatement对象，然后从该对象中拿到StatementLog，即mybatis内置的日志组件。那么mappedStatement对象是如何获取日志组件的？我们继续往下看代码。

  public SimpleExecutor(Configuration configuration, Transaction transaction) {
    super(configuration, transaction);
  }

  @Override
  public int doUpdate(MappedStatement ms, Object parameter) throws SQLException {
    Statement stmt = null;
    try {
      Configuration configuration = ms.getConfiguration();
      StatementHandler handler = configuration.newStatementHandler(this, ms, parameter, RowBounds.DEFAULT, null, null);
      stmt = prepareStatement(handler, ms.getStatementLog());
      return handler.update(stmt);
    } finally {
      closeStatement(stmt);
    }
  }

  @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);
      stmt = prepareStatement(handler, ms.getStatementLog());
      return handler.<E>query(stmt, resultHandler);
    } finally {
      closeStatement(stmt);
    }
  }

  @Override
  protected <E> Cursor<E> doQueryCursor(MappedStatement ms, Object parameter, RowBounds rowBounds, BoundSql boundSql) throws SQLException {
    Configuration configuration = ms.getConfiguration();
    StatementHandler handler = configuration.newStatementHandler(wrapper, ms, parameter, rowBounds, null, boundSql);
    Statement stmt = prepareStatement(handler, ms.getStatementLog());
    return handler.<E>queryCursor(stmt);
  }

  @Override
  public List<BatchResult> doFlushStatements(boolean isRollback) throws SQLException {
    return Collections.emptyList();
  }

  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;
  }

可以看到是通过MappedStatement的builder方法中LogFactory.getLog方法获取的，在调用build方法之前，mybatis选择的日志实现已经被初始化好了，这个LogFactory.getLog方法里面保存了日至实现（如slf4J）的构造器引用，底层也是调用日至实现比如slf4J的LoggerFactory.getLogger方法。

除此之外，可以看到LogFactory.getLog方法转递的是一个logId，由logPrefix和id组成，logPrefix是通过org.apache.ibatis.builder.xml.XMLConfigBuilder读取mybatis的配置文件拿到的，默认为空，我们可以自己配置这个log前缀。而id则是通过位于org.apache.ibatis.builder.xml.XMLStatementBuilder的parseStatementNode方法在你的mapper文件中读取的，其实也就是你写查询接口的方法名。最后可以看到LoggerFactory.getLogger方法返回一个实现了Log接口的对象，传递给MappedStatement的全局变量statementLog中，完成了它的功能。

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;
      if (configuration.getLogPrefix() != null) {
        logId = configuration.getLogPrefix() + id;
      }
      mappedStatement.statementLog = LogFactory.getLog(logId);
      mappedStatement.lang = configuration.getDefaultScriptingLanguageInstance();
    }

日志已经初始化好了，那么它具体是怎么记录的呢？这里只能说一下mybatis的运行流程了，因为它最基本的三个打印日志的组件ConnectionLogger、PreparedStatementLogger、ResultSetLogger是通过动态代理，和jdbc的connection、preparedStatement、resultSet代理类对象牢牢绑定在一起的。

mybatis一般的初始化方式如下，最终是获取一个mapper对象，其实就是你写的dao接口的代理类对象，你在调用这个mapper对象进行查询的时候，它最后会调用MapperMethod类的execute方法，对jdbc的操作都封装在里面了。

SqlSessionFactory sqlSessionFactory = new SqlSessionFactoryBuilder().build(Resources.getResourceAsStream("config location"));
        SqlSession sqlSession = sqlSessionFactory.openSession();
        Tools mapper = sqlSession.getMapper(Tools.class);
        mapper.justTest();

MapperedMethod类中execute方法代码只贴一部分，该方法有CURD四个标志位，这里把update拿出来，第一行是参数转换没什么讲的，下一行最主要的是通过sqlsession调用update方法实现的，这个sqlsession提供了大量各种各样的CURD方法和事务管理方法。

case UPDATE: {
        Object param = method.convertArgsToSqlCommandParam(args);
        result = rowCountResult(sqlSession.update(command.getName(), param));
        break;
      }

我们找到sqlsession最基础的一个实现类defaultSqlSession看看，可以看到这里传入了一个MapperedStatement，通过执行器调用update方法。

public int update(String statement, Object parameter) {
    try {
      dirty = true;
      MappedStatement ms = configuration.getMappedStatement(statement);
      return executor.update(ms, wrapCollection(parameter));
    } catch (Exception e) {
      throw ExceptionFactory.wrapException("Error updating database.  Cause: " + e, e);
    } finally {
      ErrorContext.instance().reset();
    }
  }

找到我们之前看过的抽象类baseExecutor，第一行的ErrorContext是mybatis的异常处理器，通过链式调用往里注入各种状态，内部是用一个threadLocal包装起来以解决并发问题，这里不多介绍了。closed则是一个标志位，mybatis中的执行器中有一些参数如事务Transaction、缓存localCache等在使用过后需要被关闭，sqlSession中实现了AutoCloseable接口，在其close调用baseExecutor清理这些参数（直接置null）。接着是一个clearLocalCache的操作，这个稍后分析。最后才是正了八经调用doUpdate方法。

@Override
  public int update(MappedStatement ms, Object parameter) throws SQLException {
    ErrorContext.instance().resource(ms.getResource()).activity("executing an update").object(ms.getId());
    if (closed) {
      throw new ExecutorException("Executor was closed.");
    }
    clearLocalCache();
    return doUpdate(ms, parameter);
  }

继续向下看doUpdate方法，首先通过MappedStatement拿到Configuration，这个Configuration包含了mybatis配置文件的一切信息，而MappedStatement则包含了mapper文件的配置信息。两者都是通过xml解析器直接把配置初始化的。

@Override
  public int doUpdate(MappedStatement ms, Object parameter) throws SQLException {
    Statement stmt = null;
    try {
      Configuration configuration = ms.getConfiguration();
      StatementHandler handler = configuration.newStatementHandler(this, ms, parameter, RowBounds.DEFAULT, null, null);
      stmt = prepareStatement(handler, ms.getStatementLog());
      return handler.update(stmt);
    } finally {
      closeStatement(stmt);
    }
  }

中间那行先不看，直接看preparement方法，里面有个getConnection，这个是simpleExecutor回调的baseExecutor的方法

 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;
  }

protected Connection getConnection(Log statementLog) throws SQLException {
    Connection connection = transaction.getConnection();
    if (statementLog.isDebugEnabled()) {
      return ConnectionLogger.newInstance(connection, statementLog, queryStack);
    } else {
      return connection;
    }
  }

看这个connectionLogger的newInstance，很简单，jdk动态代理创建个代理对象，穿进去的接口是jdbc的Connection.class，那个InvocationHandler其实就是ConnectIonLogger本身，直接把三个参数传到成员变量里保存起来。

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);
  }

重点看看这个invocationHandler的invoke方法，可以看到是在这里输出了mybatis的第一条日志，把sql打出来了。仔细看里面还有个PreparedStatementLogger.newInstance，没错这也是个链式调用，把preparedStatementLogger实例化了，preparedStatementLogger顾名思义代理了jdbc的PreparedStatement类，也是个代理对象，会打印sql参数的日志，代码太长了不贴了，在这个PreparedStatementLogger内部的invoke方法又调用了resultSet的代理类——ResultSetLogger，在这里会打出来日志返回值的参数，就这样三条dao log都被打出来了。

@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);
        }        
        PreparedStatement stmt = (PreparedStatement) method.invoke(connection, params);
        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);
    }
  }

本来想只看日志部分的源码，没想到把mybatis的执行流程都看了一遍，回到最初的问题，肯定是没法实现了，毕竟那几条dao日志都是分散开的，要修改格式的话也不是在mybatis里改，只能去改log4J2的代码了，根本不可能。不过之前看到配置文件有一个logPrefix属性可以更改日志前缀，不过这个修改会覆盖所有的dao日志，依然没法实现需求。
只能在logstash里手动加工日志了，日志前缀都没什么区别，只能根据==> <==来判断是否属于同一查询过程，然后将多条消息合并为一条日志，脚本估计十分难写，所以这个需求基本可以放弃了。

Cloud_N

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
6
评论
深入mybatis日志模块源码

mybatis打出的日志是这样的：2018-05-18 17:17:09,870|DEBUG|c.i.c.d.m.B.listByKeys|debug|dao|[http-nio-8090-exec-3]|xlk|icu|127.0.0.1|133455757jhbr2ty5|75007|==&gt; Preparing: SELECT * FROM department WHERE i...
复制链接

扫一扫