Log4J,在踩坑中升级版本

基本概念

Commons-logging

apache最早提供的日志的门面接口。避免和具体的日志方案(log4j、logback等)直接耦合。类似于JDBC的api接口,具体的的JDBC driver实现由各数据库提供商实现。JCL的思想也是想通过统一接口解耦,将日志方案的实现与日志接口分离。
但是Apache Commons Logging的动态绑定并不是总能成功。解决方法之一就是在程序部署时静态绑定指定的日志工具,这就是slf4j产生的原因。

slf4j

slf4j跟JCL一样,slf4j也是只提供log接口,具体的实现是在打包应用程序时所放入的绑定器(名字为 slf4j-XXX-version.jar)来决定,XXX 可以是log4j12, jdk14, jcl, nop等,他们实现了跟具体日志工具(比如 log4j)的绑定及代理工作。举个例子:如果一个程序希望用log4j日志工具,那么程序只需针对slf4j-api接口编程,然后在打包时再放入log4j-slf4j-impl.jar等相关包就可以了。

比如我们的系统,使用了slf4j+log4j,需要使用到下面几个包

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.7</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.7</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-slf4j-impl</artifactId>
    <version>2.7</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.21</version>
</dependency>

Log4j、Logback

Log4j

Apache的一个开放源代码项目,通过使用Log4j,我们可以控制日志信息输送的目的地是控制台、文件、GUI组件、甚至是套接口服务器、NT的事件记录器、UNIX Syslog守护进程等;用户也可以控制每一条日志的输出格式;通过定义每一条日志信息的级别,用户能够更加细致地控制日志的生成过程。这些可以通过一个 配置文件来灵活地进行配置,而不需要修改程序代码。

LogBack

Logback是由log4j创始人设计的又一个开源日记组件。logback当前分成三个模块:logback-core,logback- classic和logback-access。logback-core是其它两个模块的基础模块。logback-classic是log4j的一个改良版本。此外logback-classic完整实现slf4j API使你可以很方便地更换成其它日记系统如log4j或JDK14 Logging。logback-access访问模块与Servlet容器集成提供通过Http来访问日记的功能。

Log4j与LogBack比较

LogBack作为一个通用可靠、快速灵活的日志框架,将作为Log4j的替代和SLF4J组成新的日志系统的完整实现。LOGBack声称具有极佳的性能,“ 某些关键操作,比如判定是否记录一条日志语句的操作,其性能得到了显著的提高。这个操作在LogBack中需要3纳秒,而在Log4J中则需要30纳秒。 LogBack创建记录器(logger)的速度也更快:13微秒,而在Log4J中需要23微秒。更重要的是,它获取已存在的记录器只需94纳秒,而 Log4J需要2234纳秒,时间减少到了1/23。跟JUL相比的性能提高也是显著的”。 另外,LOGBack的所有文档是全面免费提供的,不象Log4J那样只提供部分免费文档而需要用户去购买付费文档。

Log4j版本升级

对于Log4j的使用场景,肯定是多线程并发的情况。一个new FileOutputStream对象表示一个打开文件对象。那么当多个线程使用同一个FileOutputStream对象写文件时,就需要进行同步操作。
可以把一个FileAppender对象理解成维护了一个打开文件对象,当Logger在多线程情况下把日志写入文件时,需要对Appender进行同步,也就是说对Logger加锁,保证使用同一个Logger对象时,一次只有一个线程使用这个FileAppender来写文件,避免了多线程情况下写文件错误。

log4j 1.x版本的锁

Hierarchy.java,多个线程使用同一个Logger时,加锁。

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) {
      if(c.aai != null) {
        writes += c.aai.appendLoopOnAppenders(event);
      }
      if(!c.additive) {
        break;
      }
    }
  }

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

AppenderSkeleton.java,多个线程使用同一个Appender时,对Appender加锁

  public  synchronized void doAppend(LoggingEvent event) {
    if(closed) {
      LogLog.error("Attempted to append to closed appender named ["+name+"].");
      return;
    }

    if(!isAsSevereAsThreshold(event.getLevel())) {
      return;
    }

    Filter f = this.headFilter;

    FILTER_LOOP:
    while(f != null) {
      switch(f.decide(event)) {
        case Filter.DENY: return;
        case Filter.ACCEPT: break FILTER_LOOP;
        case Filter.NEUTRAL: f = f.getNext();
      }
    }

    this.append(event);    
  }
  

这几个锁在高并发的情况下对系统的性能影响很大,会阻塞掉业务进程,特别是在for循环里加锁的方式很不可取。而日志收集工作应该是作为一个辅助功能,不能影响主业务功能。

log4j 2.3的线程切换

Log4j 2使用了新一代的基于LMAX Disruptor的无锁异步日志系统。在多线程的程序中,异步日志系统吞吐量比Log4j 1.x和logback高10倍,而时间延迟更低。

听起来很美,是不是?
发现这个问题的原因是我们线上出了一次故障,当一次网络异常,导致上游不断重试并发请求量特别高时,cpu利用率跑到了4000%,服务完全恢复不过来了,一开始以为是GC的原因导致服务出问题了。后来在线下进行复现,查看GC发现没啥异常,但是发现了如下的数据

dstat

usr 占用不高,sys 占用超高,同时csw(context switch) 达到1200w,一次csw 大约耗费1000ns,已经逼近cpu的极限。

jstack -l 43911> 43911.log
grep tid 43911.log | wc -l
12312
grep RUNNABLE 43911.log | wc -l
53

总线程12312,处于runnable的只有53个,看看这些线程在干什么

"pool-6-thread-14380" prio=10 tid=0x00007f7087594000 nid=0x53e1 runnable [0x00007f6b67bfc000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:349)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:502)
at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper.callAppendersFromAnotherThread(AsyncLoggerConfigHelper.java:342)
at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(AsyncLoggerConfig.java:114)
......

grep "LockSupport.java:349" 43911.log | wc -l
11536

线程都跑在LockSupport.java:349,
unsafe.park(false, 1);
1 nano = 10^-9s, 推测大量线程频繁的短时间sleep造成了大量的线程切换,做个实验:

public static void contextSwitchTest(int threadCount) throws Exception {
  ExecutorService executorService = Executors.newFixedThreadPool(threadCount);
  for (int i = 0; i < threadCount; i++) {
    executorService.execute(new Runnable() {
      @Override
      public void run() {
        while (true) {
          LockSupport.parkNanos(1);
        }
      }
    });
  }
  executorService.awaitTermination(Long.MAX_VALUE, TimeUnit.SECONDS);
}

在一台搭载了两个E5-2670 v3 @ 2.30GHz的机器上测试这段代码,在threadCount达到600后,测试跑起来后立即发现上下文切换到百万级别,推测被印证。

原因找到了,接下来看看出问题是log生产速度怎么样:通过不断地ls -al error.log/business.log,发现Log的生成速度才几MB/s,远没有达到磁盘的极限200M/s,再做个测试:

private static void loggerSpeedTest(int threadCount) throws Exception {
  ExecutorService executorService = Executors.newFixedThreadPool(threadCount);
  for (int i = 0; i < threadCount; i++) {
    executorService.execute(new Runnable() {
      @Override
      public void run() {
        while (true) {
          LOGGER.error("test log4j2 logging speed", new UnsupportedOperationException());
        }
      }
    });
  }
  executorService.awaitTermination(Long.MAX_VALUE, TimeUnit.SECONDS);
}

线程少的时候速度还行,线程一多很慢,问题找到了,但什么造成的这个问题呢,顺着stacktrace挖一挖:

AsyncLoggerConfig.callAppenders()

@Override
protected void callAppenders(final LogEvent event) {
    // populate lazily initialized fields
    event.getSource();
    event.getThreadName();

    // pass on the event to a separate thread
    if (!helper.callAppendersFromAnotherThread(event)) {
        super.callAppenders(event);
    }
}

AsyncLoggerConfigHelper.callAppendersFromAnotherThread()

public boolean callAppendersFromAnotherThread(final LogEvent event) {
    // TODO refactor to reduce size to <= 35 bytecodes to allow JVM to inline it
    final Disruptor<Log4jEventWrapper> temp = disruptor;
    if (temp == null) { // LOG4J2-639
        LOGGER.fatal("Ignoring log event after log4j was shut down");
        return true;
    }

    // LOG4J2-471: prevent deadlock when RingBuffer is full and object
    // being logged calls Logger.log() from its toString() method
    if (isAppenderThread.get() == Boolean.TRUE //
            && temp.getRingBuffer().remainingCapacity() == 0) {

        // bypass RingBuffer and invoke Appender directly
        return false;
    }
    // LOG4J2-639: catch NPE if disruptor field was set to null after our check above
    try {
        LogEvent logEvent = event;
        if (event instanceof RingBufferLogEvent) {
            logEvent = ((RingBufferLogEvent) event).createMemento();
        }
        logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters

        // Note: do NOT use the temp variable above!
        // That could result in adding a log event to the disruptor after it was shut down,
        // which could cause the publishEvent method to hang and never return.
        disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig);
    } catch (final NullPointerException npe) {
        LOGGER.fatal("Ignoring log event after log4j was shut down.");
    }
    return true;
}

RingBuffer.publishEvent()

@Override
public <A, B> void publishEvent(EventTranslatorTwoArg<E, A, B> translator, A arg0, B arg1){
    final long sequence = sequencer.next();
    translateAndPublish(translator, sequence, arg0, arg1);
}

MultiProducerSequencer.next()

@Override
public long next(int n){
    if (n < 1){
        throw new IllegalArgumentException("n must be > 0");
    }

    long current;
    long next;

    do{
        current = cursor.get();
        next = current + n;

        long wrapPoint = next - bufferSize;
        long cachedGatingSequence = gatingSequenceCache.get();

        if (wrapPoint > cachedGatingSequence || cachedGatingSequence > current){
            long gatingSequence = Util.getMinimumSequence(gatingSequences, current);

            if (wrapPoint > gatingSequence){
                LockSupport.parkNanos(1); // TODO, should we spin based on the wait strategy?
                continue;
            }

            gatingSequenceCache.set(gatingSequence);
        }else if (cursor.compareAndSet(current, next)){
            break;
        }
    }while (true);

    return next;
}

整个流程下来就是说在消费速度跟不上生产速度的时候,生产线程做了无限重试,重试间隔为1 nano,这个1 nano 会导致线程被频繁休眠/唤醒,造成kernal cpu 利用率高,context switch已经达到了cpu的极限,进而导致写log的线程的线程获取cpu时间少,吞吐量下降。

查了下log4j的bug,发现:https://github.com/apache/logging-log4j2/commit/7a7f5e4ed1ce8a27357a12a06d32ca2b04e5eb56

if this fails because the queue is full, then fall back to asking AsyncEventRouter what to do with the event,

把log4j2版本切到2.7, 跑一下上面的测试,发现性能上来了, context swtich也有了数量级的下降,看看怎么办到的:

AsyncLoggerConfig.callAppenders()

@Override
protected void callAppenders(final LogEvent event) {
    populateLazilyInitializedFields(event);
    if (!delegate.tryEnqueue(event, this)) {
        final EventRoute eventRoute = delegate.getEventRoute(event.getLevel());
        eventRoute.logMessage(this, event);
    }
}

AsyncLoggerConfigDisruptor.getEventRoute()

@Override
public EventRoute getEventRoute(final Level logLevel) {
    final int remainingCapacity = remainingDisruptorCapacity();
    if (remainingCapacity < 0) {
        return EventRoute.DISCARD;
    }
    return asyncQueueFullPolicy.getRoute(backgroundThreadId, logLevel);
}

DefaultAsyncQueueFullPolicy.getRoute()

@Override
public EventRoute getRoute(final long backgroundThreadId, final Level level) {

    // LOG4J2-1518: prevent deadlock when RingBuffer is full and object being logged calls
    // Logger.log in application thread
    // See also LOG4J2-471: prevent deadlock when RingBuffer is full and object
    // being logged calls Logger.log() from its toString() method in background thread
    return EventRoute.SYNCHRONOUS;
}

没有了park,被block的线程没有一直被调度,context switch减少了,kernel cpu下降了,真正获取到lock的线程获得了更多的cpu用来干活了。

log4j的性能

一想到性能,有哪些是对java程序影响大的呢? 我们直观地会认为反射、编解码,这些东西对性能影响比较大。
使用JProfiler进行分析后,一些结果却让人吃惊不小,最耗CPU的居然是以下函数
InetSocketAddress.getHostName()
Log.info
String.format
String.replace
Gson.fromJson
把log关闭后,InetSocketAddress.getHostName()的居然占到了惊人的27%!

当然,性能并不是最重要的指标,相比于日志能带来的定位线上问题的好处,这一点性能的损耗其实不值一提,毕竟业务开发中,效率和稳定性才是最重要的。

参考文档

java日志,需要知道的几件事
本文中关于log4j 2.3的主要内容其实是我mentor写的,我主要是重新走了一下流程,补全了图片与测试数据,并对内容做了少部分处理。

posted on 2017-04-23 11:02 flystar32 阅读(...) 评论(...) 编辑 收藏

导航

公告