×

Log4j 升级Log4j 2 后的性能简单比较

96
HelloArmin
2016.10.24 10:25* 字数 381

主机配置

  • CPU:8核
  • 内存: 4G

测试目标过程和配置

  • 一个业务处理接口
  • 分层的各个函数进行切面监控执行时间并进行日志打印输出
  • log4j appender 采用 RollingFileAppdendar

测试工具:

LoadRunner

压测过程:

采用200个并发请求进行压测,压测的结果显示TPS只有18(即每秒处理18个请求)。然后被这个结果深深的震惊了。

查看主机性能情况,负载、IO、内存使用都很低,同时并没有存在频繁的full gc的情况。

监控线程执行情况

thread_monitor_1.png

真是红透半天天了呀,这货。

打印并查看线程一看,发现大量的处理线程blocked在等待同一个log4j的rootLogger对象锁。

http-bio-8080-exec-76" daemon prio=10 tid=0x00007f4b6428b800 nid=0x2ce2 waiting for monitor entry [0x00007f4c19d66000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:204)
        - waiting to lock <0x00000005bd1bfe58> (a org.apache.log4j.spi.RootLogger)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.log(Category.java:856)
        at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:304)
        at com.best.ti.util.log.MethodTimeAdvice.invoke(MethodTimeAdvice.java:44)

查看log4j源码

public
 void callAppenders(LoggingEvent event) {
  int writes = 0;

  for(Category c = this; c != null; c=c.parent) {
  // Protected against simultaneous call to addAppender, removeAppender,...
  synchronized(c) {    //------- here is a LOCK
     if(c.aai != null) {
       writes += c.aai.appendLoopOnAppenders(event);
     }
     if(!c.additive) {
       break;
     }
       }
  }

  if(writes == 0) {
       repository.emitNoAppenderWarning(this);
  }
 }

日志并发输出的时候,所有的logger对象关联的parent category链路路引用的是同一个rootLogger对象,所以会锁等待,在高并发且日志输出频繁的情况下, 这个锁等待的情况会很严重,进而影响了应用的性能表现。

关闭执行时间监控的日志打印

关闭后, QPS上升到了200左右。

升级为log4j 2

不修改代码,采用bridge的方式升级为log4j2日志实现。

压测结果显示:

  • 用 同步输出,TPS 为58
  • 采用异步AsyncAppender输出,TPS 达到了 116
技术文章
Web note ad 1