日志打印[System.out.println(s)]引起的血案

日志打印引起的血案

起因

某天突然收到Cat关于某个站点的异常告警，错误数达到1000多个。过了一分钟后就恢复了。通过Cat错误日志,发现是调用下游服务异常。

• 报错有两种错误
  • com.alipay.sofa.rpc.core.exception.SofaRpcException: com.alipay.remoting.rpc.exception.InvokeServerBusyException: Server thread pool busy! the address is 10.x.xx.176:8889, id=7745871
  • com.alipay.sofa.rpc.core.exception.SofaTimeOutException: com.alipay.remoting.rpc.exception.InvokeTimeoutException: Rpc invocation timeout[responseCommand TIMEOUT]! the address is 10.x.xx.176:8889

从错误信息看可能是线程满了，导致额外的请求超时，也有可能是请求处理耗时长了,变慢了导致线程池满了。

定位

请求量突然升高？

通过查看ELK的同时期昨天的请求量，对比发现请求量没有升高，排出请求量突然升高的原因。

数据库响应慢了？

通过日志也没有看到数据库相关的错误，可以暂时排出数据库的问题

gc导致STW？

通过Cat监控发现当时没有进行过Full gc,而且yong gc的耗时也是正常的，排出gc的原因

既然是线程满了那就需要看看当时的线程情况

通过Cat的监控，发现当时的线程数量确实上升了200左右

是什么线程增加了呢？

就需要查看当时的线程池情况，可是现在去导出jvm的线程信息已经晚了，当时的现场已经没有了。幸好有Cat的心跳上报数据，可以在心跳上报数据里查看到当时的线程信息。Porblem->heartbea找到当时的上报的心跳日志，从里发现报错当时的线程SOFA-SEV-BOLT-BIZ-8889-55-T211的线程数量比报错前多了200多，也就是RPC的请求处理线程上升了，同时发现很多线程是BLOCKED。

450: "SOFA-SEV-BOLT-BIZ-8889-55-T211" Id=163642 BLOCKED on java.io.PrintStream@e7d31f5 owned by "SOFA-SEV-BOLT-BIZ-8889-55-T214" Id=163646 
at java.io.PrintStream.println(PrintStream.java:805) 
- blocked on java.io.PrintStream@e7d31f5 
at org.apache.ibatis.logging.stdout.StdOutImpl.debug(StdOutImpl.java:52) 
at org.apache.ibatis.logging.jdbc.BaseJdbcLogger.debug(BaseJdbcLogger.java:159) 
at org.apache.ibatis.logging.jdbc.ResultSetLogger.invoke(ResultSetLogger.java:82) 
at com.sun.proxy.$Proxy149.next(Unknown Source) 
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValuesForSimpleResultMap(DefaultResultSetHandler.java:353) 
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValues(DefaultResultSetHandler.java:330) 
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSet(DefaultResultSetHandler.java:303) 
... 

分析原因

通过线程信息可以看出都是被同一线程BLOCKED，阻塞在blocked on java.io.PrintStream.println方法，就是System.out.println()方法。而且是mybatis的org.apache.ibatis.logging.stdout.StdOutImpl.debug()方法导致的。
疑问来了？

• 线上的日志是info级别,怎么会调用debug方法？
• 查看了StdOutImpl.debug()的源码，如下都是调用的System.out.println的系统方法打印日志到控制台的，而不是用的项目业务使用的logback打印？

  @Override
  public void error(String s) {
    System.err.println(s);
  }

  @Override
  public void debug(String s) {
    System.out.println(s);
  }

先来看看为什么System.out.println会阻塞，看看它的源码：
java.lang.System

//从注解可以看出System类在被加载时会执行registerNatives()方法并
//调用System的initializeSystemClass()方法
  public final static PrintStream out = null;
    /* register the natives via the static initializer.
     *
     * VM will invoke the initializeSystemClass method to complete
     * the initialization for this class separated from clinit.
     * Note that to use properties set by the VM, see the constraints
     * described in the initializeSystemClass method.
     */
    private static native void registerNatives();
    static {
        registerNatives();
    }
   //java.lang.System#initializeSystemClass部分方法
   private static void initializeSystemClass() {
        // be put into it directly.
        props = new Properties();
        initProperties(props);  // initialized by the VM
       //省略部分代码..............
       //从下面可以看出在System被JVM初始化时会初始化常量属性PrintStream out
        FileInputStream fdIn = new FileInputStream(FileDescriptor.in);
        FileOutputStream fdOut = new FileOutputStream(FileDescriptor.out);
        FileOutputStream fdErr = new FileOutputStream(FileDescriptor.err);
        setIn0(new BufferedInputStream(fdIn));
        setOut0(newPrintStream(fdOut, props.getProperty("sun.stdout.encoding")));
        setErr0(newPrintStream(fdErr, props.getProperty("sun.stderr.encoding")));
   //省略部分代码...............
    }

从上的代码得出System的out(PrintStream类型)是一个常量，所以是系统公用,而PrintStream 的println()方法对当前实例加了锁，所以系统的System.out.println()在满足一定条件下有可能会阻塞，包括System.err.println(s)在满足一定条件下也有可能会阻塞
java.io.PrintStream#println(java.lang.String)

    public void println(String x) {
        synchronized (this) {
            print(x);
            newLine();
        }
    }

线程BLOCKED的问题找到了，那上面两个疑问还没有解决，通过查看mybatis文档，发现在mybatis的配置文件的settings配置里有个关于日志的配置->logImpl(指定 MyBatis 所用日志的具体实现)配置,支持
SLF4J | LOG4J | LOG4J2 | JDK_LOGGING | COMMONS_LOGGING | STDOUT_LOGGING | NO_LOGGING
而看了出问题的项目里刚刚好指定了

 <settings>
        <setting name="logImpl" value="STDOUT_LOGGING"/>
    </settings>

STDOUT_LOGGING对应的实现就是org.apache.ibatis.logging.stdout.StdOutImpl在控制台输出日志。
这就解决前面两个疑问，设置日志info级别对mybatis无效，且日志在控制台输出。
把STDOUT_LOGGING改成SLF4J后控制台就没有日志输出了，至于阻塞的问题只能说原来System.out.println()导致的问题肯定是解决了，会不会有新的问题只能待定。

总结:

• System类在初始化时会初始化常量out(PrintStream类型)，是全局公用,而PrintStream 的println()方法对当前实例加了锁，所以系统的System.out.println()在满足一定条件下有可能会阻塞，包括System.err.println(s)在满足一定条件下也有可能会阻塞。
• Mybatis通关配置文件settings可以设置mybatis的日志输出的实现，支持SLF4J | LOG4J | LOG4J2 | JDK_LOGGING | COMMONS_LOGGING | STDOUT_LOGGING | NO_LOGGING,未指定时将自动查找