磁盘IO告警问题排查记录-MyBatis日志源码分析

背景

业务凌晨收到磁盘IO告警，每秒内IO操作时长平均占用比例大于90%

分析

查看磁盘IO监控指标

发现有一个操作，该操作导致大量的磁盘读写IO。

cp catalina.out catalina.out-2021-12-18

了解背后的原因发现，业务日志大量输出到了tomcat的catalina.out中，期间有收到磁盘满的告警，因此才做了这样的一个日志轮转：先拷贝一份，然后旧的日志清空。

分析结果：业务日志写入tomcat catalina.out中，导致磁盘占满，所以做了日志轮转策略，导致凌晨IO操作频繁。

为什么业务日志会输出到tomcat catalina.out中

1、首先了解什么样的日志会输出到catalina.out中？

catalina.out主要记录运行的一些信息，尤其是一些异常错误日志信息。

• tomcat运行日志
• catalina.out其实是tomcat的标准输出(stdout)和标准出错(stderr)
• 在tomcat的启动脚本里指定，如果没有修改的话stdout和stderr会重定向到这里。所以我们在应用里使用System.out、System.err打印的日志都会输出到这里。
• 如果我们在应用里使用其他的日志框架，配置了向Console输出的，则也会在这里出现。以logback为例，如果配置ch.qos.logback.core.ConsoleAppender则会输出到catalina.out里。

2、查看线上的log4j配置文件，发现并没有配置org.apache.log4j.ConsoleAppender，只有测试环境配置了

3、询问运维，目前预发都是什么样的业务日志，发现都是SQL打印日志，询问同事发现他们的版本中有日志打印开关，但是预发线上均已经关闭，但是运维依然可以看到SQL日志还在打印。查看MyBatis的SQL日志配置，发现MyBatis配置开启了SQL日志打印。xml配置文件中配置了如下内容：

<setting name="logImpl" value="org.apache.ibatis.logging.stdout.StdOutImpl" />

4、查看StdOutImpl源码，发现方法中均有标准输出以及标准输错，去掉后问题得以解决。

public class StdOutImpl implements Log {
 
  public StdOutImpl(String clazz) {
    // Do Nothing
  }
 
  @Override
  public boolean isDebugEnabled() {
    return true;
  }
 
  @Override
  public boolean isTraceEnabled() {
    return true;
  }
 
  @Override
  public void error(String s, Throwable e) {
    System.err.println(s);
    e.printStackTrace(System.err);
  }
 
  @Override
  public void error(String s) {
    System.err.println(s);
  }
 
  @Override
  public void debug(String s) {
    System.out.println(s);
  }
 
  @Override
  public void trace(String s) {
    System.out.println(s);
  }
 
  @Override
  public void warn(String s) {
    System.out.println(s);
  }
}

Mybatis 日志源码分析

日志加载部分

Log接口

Log接口比较简单，源码如下：

public interface Log {
  // 是否启用debug
  boolean isDebugEnabled();
  // 是否启用debug
  boolean isTraceEnabled();
  // 错误日志级别输出方法
  void error(String s, Throwable e);
  //重载错误日志级别输出方法
  void error(String s);
  //debug日志级别输出方法
  void debug(String s);
  //trace日志级别输出方法
  void trace(String s);
  //warn日志级别输出方法
  void warn(String s);
}

关于Log的实现类较多，参考org.apache.ibatis.logging包下的实现类，如Jdk14LoggingImpl、Log4jImpl、Log4j2Impl、Slf4jImpl、StdOutImpl等，Mybatis实现了当前很多日志框架的适配。

日志组件加载

用户未在xml中设置logImpl属性时，默认加载方式为LogFactory的static静态代码块，默认优先加载slf4j。如果设置了logImpl，则使用用户自定义的log组件。

public final class LogFactory {
 
  /**
   * Marker to be used by logging implementations that support markers
   */
  public static final String MARKER = "MYBATIS";
 
  private static Constructor<? extends Log> logConstructor;
  // 类加载时尝试设置使用的日志组件，依次按序加载，slf4j默认为第一个；第一个加载成功后，logConstructor 设置对应的值；此种加载方式生效的场景为用户未在xml中设置logImpl属性
  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();
      }
    });
  }
 
  private LogFactory() {
    // disable construction
  }
 
  public static Log getLog(Class<?> aClass) {
    return getLog(aClass.getName());
  }
 
  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);
    }
  }
  // 用户设置了logImpl之后，会调用该方法覆盖默认加载的日志组件，logConstructor会替换掉
  public static synchronized void useCustomLogging(Class<? extends Log> clazz) {
    setImplementation(clazz);
  }
 
  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);
  }
 
  public static synchronized void useLog4JLogging() {
    setImplementation(org.apache.ibatis.logging.log4j.Log4jImpl.class);
  }
 
  public static synchronized void useLog4J2Logging() {
    setImplementation(org.apache.ibatis.logging.log4j2.Log4j2Impl.class);
  }
 
  public static synchronized void useJdkLogging() {
    setImplementation(org.apache.ibatis.logging.jdk14.Jdk14LoggingImpl.class);
  }
 
  public static synchronized void useStdOutLogging() {
    setImplementation(org.apache.ibatis.logging.stdout.StdOutImpl.class);
  }
 
  public static synchronized void useNoLogging() {
    setImplementation(org.apache.ibatis.logging.nologging.NoLoggingImpl.class);
  }
  // 加载时会进行logConstructor是否为空的判断，为空才加载，有值不加载
  private static void tryImplementation(Runnable runnable) {
    if (logConstructor == null) {
      try {
        runnable.run();
      } catch (Throwable t) {
        // ignore
      }
    }
  }
  //根据传入的实现类，获取对应的构造函数，反射获取实例，重新设置logConstructor值
  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);
    }
  }
 
}

Mybatis配置加载时会调用org.apache.ibatis.session.SqlSessionFactoryBuilder#build(java.io.Reader, java.lang.String, java.util.Properties)方法，该方法中使用XMLConfigBuilder进行配置的加载及解析。

public SqlSessionFactory build(Reader reader, String environment, Properties properties) {
    try {
      // 配置加载
      XMLConfigBuilder parser = new XMLConfigBuilder(reader, environment, properties);
      // 配置解析
      return build(parser.parse());
    } catch (Exception e) {
      throw ExceptionFactory.wrapException("Error building SqlSession.", e);
    } finally {
      ErrorContext.instance().reset();
      try {
        reader.close();
      } catch (IOException e) {
        // Intentionally ignore. Prefer previous error.
      }
    }
  }
  //配置解析
  private void parseConfiguration(XNode root) {
    try {
      //issue #117 read properties first
      propertiesElement(root.evalNode("properties"));
     // 解析settings属性
      Properties settings = settingsAsProperties(root.evalNode("settings"));
      loadCustomVfs(settings);
      typeAliasesElement(root.evalNode("typeAliases"));
      pluginElement(root.evalNode("plugins"));
      objectFactoryElement(root.evalNode("objectFactory"));
      objectWrapperFactoryElement(root.evalNode("objectWrapperFactory"));
      reflectorFactoryElement(root.evalNode("reflectorFactory"));
      // 加载settings中的配置项
      settingsElement(settings);
      // read it after objectFactory and objectWrapperFactory issue #631
      environmentsElement(root.evalNode("environments"));
      databaseIdProviderElement(root.evalNode("databaseIdProvider"));
      typeHandlerElement(root.evalNode("typeHandlers"));
      mapperElement(root.evalNode("mappers"));
    } catch (Exception e) {
      throw new BuilderException("Error parsing SQL Mapper Configuration. Cause: " + e, e);
    }
  }
 
  private void settingsElement(Properties props) throws Exception {
    // 省略其他加载操作 直接看加载logImpl操作，首先根据logImpl属性对应的value值反射生成Class实例，设置logImpl属性值，
    @SuppressWarnings("unchecked")
    Class<? extends Log> logImpl = (Class<? extends Log>)resolveClass(props.getProperty("logImpl"));
    configuration.setLogImpl(logImpl);
  }
  //设置logImpl属性值
  public void setLogImpl(Class<? extends Log> logImpl) {
    if (logImpl != null) {
      this.logImpl = logImpl;
      // 设置用户自定义的日志组件，参考上文提到的useCustomLogging方法，将logConstructor值替换掉
      LogFactory.useCustomLogging(this.logImpl);
    }
  }

因此在xml中配置logImpl属性会干预默认的日志组件。

日志打印部分

MyBatis在构建MappedStatement时会调用LogFactory.getLog(logId)方法，由于上文中已经将日志组件替换为StdOutImpl，因此此时mappedStatement.statementLog = StdOutImpl。

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;
      }
      // 调用LogFactory的getLog获取实际的日志组件
      mappedStatement.statementLog = LogFactory.getLog(logId);
      mappedStatement.lang = configuration.getDefaultScriptingLanguageInstance();
    }
  // 上文中已经将logConstructor替换为StdOutImpl的构造方法，因此该方法返回StdOutImpl的日志组件
  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);
    }
  }

Mybatis的日志打印基类为BaseJdbcLogger，实现子类有四个：ConnectionLogger、PreparedStatementLogger、ResultSetLogger、StatementLogger。

已获取连接为例，会返回一个代理对象，在执行对象代理方法时，会进行日志打印。

// 传入的statementLog为StdOutImpl，发现isDebugEnabled为true，则返回一个ConnectionLogger
protected Connection getConnection(Log statementLog) throws SQLException {
    Connection connection = transaction.getConnection();
    if (statementLog.isDebugEnabled()) {
      return ConnectionLogger.newInstance(connection, statementLog, queryStack);
    } else {
      return connection;
    }
  }
  //利用jdk动态代理生成Connection代理类，new ConnectionLogger会初始化statementLog属性为StdOutImpl
  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);
  }
 
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())) {
        // 条件为true，进入debug方法
        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);
    }
  }
  //new ConnectionLogger已经将statementLog设置为StdOutImpl，因此实际调用的StdOutImpl的debug方法
  protected void debug(String text, boolean input) {
    if (statementLog.isDebugEnabled()) {
      statementLog.debug(prefix(input) + text);
    }
  }
  //StdOutImpl的debug方法
  public void debug(String s) {
    System.out.println(s);
  }

其他的类似，此时整条链路就串起来了，就是通过config.xml文件中configuration → settings → setting中的logImpl，更改MyBatis的日志组件，进而在sql执行时进行isDebugEnabled方法判断，调用debug方法进行打印。