log4j是如何拖慢你的系统的

log4j 引起的线上事故

1 问题起因

这个是在生产环境中发生的问题，第一次事故因为别人把大量的请求打来过来，猜测是机器扛不住，后来量少后发现问题不存在了，大致把问题定位是因为量的问题，也就准备后续的扩容，大概过了几个月，线上又发生了一次事故，事故的特征排查之后的特征就是打印log的速度非常慢，而且nginx处理速度也慢，同一个请求两个条日志之间间隔了好几秒， 经过运维排查后，是因为nginx worker数量不够，导致整体思路都被带到了nginx优化，包括worker的增加，直到第三次压力测试才完整的找出问题所在

2 问题排查过程

2.1 排查tomcat

线上项目机器配置是64核 128G，压力测试之后发觉集群tomcat总体qps大概到1200左右开始扛不住，也就大概单机600qps，起初找了一下网上很多人说Tomcat性能不行，很多人也是Tomcat600qps左右，怀疑tomcat扛不住，为了验证Tomcat，对另外一个查询了数据库的项目进行压测，纯查询数据库的qps达到了2000qps，Tomcat性能不高的这个可以否定了

2.2 排查log4j

因为两个log之间的输出时间经常超过好几秒，所以开始排查log4j，对log4j采用buffer进行输出，增加buffer大小，进行压力测试，buffer增加到了8M，发现并没有什么实际的效果，于是开始怀疑同步性能低

2.3 采用异步输出

怀疑是因为同步输出和普通磁盘，导致的问题，然后采用异步进行输出日志，发现qps开始无上限，为了保证跟线上环境一致，所以单独出一台pre环境进行测试，qps达到了6000，并且整个平均响应时间没有太大波动，然后停止了测试，担心把线上codis打垮，也是这个时候确认了是同步异步之间的性能问题。

2.4 因无法输出log的文件名和具体的代码行找出真正原因

采用异步之后，已经觉得基本解决了，也定位到是因为异步和同步之间的性能差距，于是发现log中多了几个问号，继续倒腾这个问题,查看源码后发现AsyncAppender中有一个locationInfo信息，默认是false，然后进行配置<param name="locationInfo" value="true"/>，解决了%l这个参数失效的问题，然后继续压测，这个时候发现，单机qps到了600多左右性能无法提升，这个时候才最终发现影响性能的问题是在于%l这个参数打印的数据问题，通过官网才真正确认了确是是这个参数的问题http://logging.apache.org/log4j/2.x/performance.html#asyncLoggingWithLocation,大概描述如下

“`
Some layouts can show the class, method and line number in the application where the logging call was made. In Log4j 2, examples of such layout options are HTML locationInfo, or one of the patterns %C or $class, %F or %file, %l or %location, %L or %line, %M or %method. In order to provide caller location information, the logging library will take a snapshot of the stack, and walk the stack trace to find the location information.

The graph below shows the performance impact of capturing caller location information when logging asynchronously from a single thread. Our tests show that capturing caller location has a similar impact across all logging libraries, and slows down asynchronous logging by about 30-100x.
“`

大概也就是说这些参数的使用会导致性能的急剧下降C or $class, %F or %file, %l or %location, %L or %line, %M or %method, 大概下降30-100倍左右，这才找到真正的原因

3 探讨Log4j的同步异步实现机制

3.1 同步实现机制

正常开发使用中，基本上都是使用的DailyRollingFileAppender，进行日志的输出

protected
  void subAppend(LoggingEvent event) {
    this.qw.write(this.layout.format(event));

    //.....

    if(shouldFlush(event)) {
      this.qw.flush();
    }
  }
  protected boolean shouldFlush(final LoggingEvent event) {
     return immediateFlush;
  }
public
  synchronized
  void setFile(String fileName, boolean append, boolean bufferedIO, int bufferSize)
                                                            throws IOException {
    //省略...
    Writer fw = createWriter(ostream);
    //如果有buffer就使用BufferedWriter
    if(bufferedIO) {
      fw = new BufferedWriter(fw, bufferSize);
    }
    this.setQWForFiles(fw);
    this.fileName = fileName;
    this.fileAppend = append;
    this.bufferedIO = bufferedIO;
    this.bufferSize = bufferSize;
    writeHeader();
    LogLog.debug("setFile ended");
  }

整体逻辑如下: