logback性能优化及源码分析

logback性能测试

logback版本:1.0.13
下图是logback在实际并发环境中的表现,200并发请求，大量blocked：
移除日志输出做对比:
查看thread dump 可以看到blocked是由logback导致。

logback源码分析

logback文件输出类是RollingFileAppender,打印日志的方法是subAppend，rollover是关闭文件切换日志文件。

/**     * Implemented by delegating most of the rollover work to a rolling policy.     */    public void rollover() {        synchronized (lock) {            // Note: This method needs to be synchronized because it needs            // exclusive            // access while it closes and then re-opens the target file.            //            // make sure to close the hereto active log file! Renaming under            // windows            // does not work for open files.            this.closeOutputStream();            try {                super.getRollingPolicy().rollover();            } catch (RolloverFailure rf) {                addWarn("RolloverFailure occurred. Deferring roll-over.");                // we failed to roll-over, let us not truncate and risk data                // loss                this.append = true;            }            try {                // update the currentlyActiveFile                // http://jira.qos.ch/browse/LBCORE-90                currentlyActiveFile = new File(super.getRollingPolicy().getActiveFileName());                // This will also close the file. This is OK since multiple                // close operations are safe.                this.openFile(super.getRollingPolicy().getActiveFileName());            } catch (IOException e) {                addError("setFile(" + fileName + ", false) call failed.", e);            }        }    }    /**   * This method differentiates RollingFileAppender from its super class.   */  @Override  protected void subAppend(E event) {    // The roll-over check must precede actual writing. This is the    // only correct behavior for time driven triggers.    // We need to synchronize on triggeringPolicy so that only one rollover    // occurs at a time    synchronized (triggeringPolicy) {      if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) {        rollover();      }    }    super.subAppend(event);  }

再看super.subAppend,代码在父类OutputStreamAppender中:

protected void subAppend(E event) {    if (!isStarted()) {      return;    }    try {      // this step avoids LBCLASSIC-139      if (event instanceof DeferredProcessingAware) {        ((DeferredProcessingAware) event).prepareForDeferredProcessing();      }      // the synchronization prevents the OutputStream from being closed while we      // are writing. It also prevents multiple threads from entering the same      // converter. Converters assume that they are in a synchronized block.      synchronized (lock) {        writeOut(event);      }    } catch (IOException ioe) {      // as soon as an exception occurs, move to non-started state      // and add a single ErrorStatus to the SM.      this.started = false;      addStatus(new ErrorStatus("IO failure in appender", this, ioe));    }  }

跟关闭文件使用同一个锁，保证文件关闭切换不会跟写文件冲突。

结论

使用logback时，每个对象间的锁是独立的，并且必须保留。

优化方案

• 在源码中做改动
• 给logback打补丁，在日志输出上做改动

实际解决方案

使用第一种方案会导致logback升级后代码也要随机更改，并且性能提升不会太大，随着日志量的增加，性能下降会愈加明显。因此本人使用第二种方案。

• 文件只输出error级别
• 业务日志采用kafka+elasticsearch
  上代码只输出error:

public class ErrorRollingFileAppender<E> extends RollingFileAppender<E> {    File currentlyActiveFile;    public void start() {        currentlyActiveFile = new File(getFile());        super.start();    }    /**     * Implemented by delegating most of the rollover work to a rolling policy.     */    public void rollover() {        synchronized (lock) {            // Note: This method needs to be synchronized because it needs            // exclusive            // access while it closes and then re-opens the target file.            //            // make sure to close the hereto active log file! Renaming under            // windows            // does not work for open files.            this.closeOutputStream();            try {                super.getRollingPolicy().rollover();            } catch (RolloverFailure rf) {                addWarn("RolloverFailure occurred. Deferring roll-over.");                // we failed to roll-over, let us not truncate and risk data                // loss                this.append = true;            }            try {                // update the currentlyActiveFile                // http://jira.qos.ch/browse/LBCORE-90                currentlyActiveFile = new File(super.getRollingPolicy().getActiveFileName());                // This will also close the file. This is OK since multiple                // close operations are safe.                this.openFile(super.getRollingPolicy().getActiveFileName());            } catch (IOException e) {                addError("setFile(" + fileName + ", false) call failed.", e);            }        }    }    /**     * This method differentiates RollingFileAppender from its super class.     */    @Override    protected void subAppend(E event) {        if(event instanceof LoggingEvent){            LoggingEvent tempLoggingEvent = (LoggingEvent) event;            if(!tempLoggingEvent.getLevel().toString().equals(Level.ERROR.toString()))                return;        }        // The roll-over check must precede actual writing. This is the        // only correct behavior for time driven triggers.        // We need to synchronize on triggeringPolicy so that only one rollover        // occurs at a time//      synchronized (super.getTriggeringPolicy()) {//          if (super.getTriggeringPolicy().isTriggeringEvent(currentlyActiveFile, event)) {//              rollover();//          }//      }          super.subAppend(event);    }}

对应配置

<appender name="logfile" class="ErrorRollingFileAppender">        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">            <FileNamePattern>xxx-%d{yyyy-MM-dd}.log</FileNamePattern>        </rollingPolicy>        <layout class="ch.qos.logback.classic.PatternLayout">            <pattern>[%d{HH:mm:ss:SSS}][%5p]- %m%n</pattern>            <pattern>[%d{HH:mm:ss:SSS}][%5p][%c:%L] %m%n</pattern>        </layout>        </appender>

日志使用卡夫卡发送

public class UnblockedKafkaAppender extends UnsynchronizedAppenderBase<ILoggingEvent>{    @SuppressWarnings("rawtypes")    @Override    protected void append(ILoggingEvent eventObject) {        //日志发送    }    @SuppressWarnings("static-access")    @Override    public void start() {        super.start();        //启动配置    }    @Override    public void stop() {        super.stop();    }}

logback.xml配置

<appender name="kafka" class="UnblockedKafkaAppender"><!-- 文件输出配置 --><root level="info">        <appender-ref ref="logfile"/>           <appender-ref ref="kafka"/>     </root>

注意事项

appender 可以继承AppenderBase 但是AppenderBase也是有锁，发kafka不需要加锁，因此使用UnsynchronizedAppenderBase。

源码对比
AppenderBase :

 public synchronized void doAppend(E eventObject) {    // WARNING: The guard check MUST be the first statement in the    // doAppend() method.    // prevent re-entry.    if (guard) {      return;    }    try {      guard = true;      if (!this.started) {        if (statusRepeatCount++ < ALLOWED_REPEATS) {          addStatus(new WarnStatus(              "Attempted to append to non started appender [" + name + "].",              this));        }        return;      }      if (getFilterChainDecision(eventObject) == FilterReply.DENY) {        return;      }      // ok, we now invoke derived class' implementation of append      this.append(eventObject);    } catch (Exception e) {      if (exceptionCount++ < ALLOWED_REPEATS) {        addError("Appender [" + name + "] failed to append.", e);      }    } finally {      guard = false;    }  }

UnsynchronizedAppenderBase

public void doAppend(E eventObject) {    // WARNING: The guard check MUST be the first statement in the    // doAppend() method.    // prevent re-entry.    if (Boolean.TRUE.equals(guard.get())) {      return;    }    try {      guard.set(Boolean.TRUE);      if (!this.started) {        if (statusRepeatCount++ < ALLOWED_REPEATS) {          addStatus(new WarnStatus(              "Attempted to append to non started appender [" + name + "].",              this));        }        return;      }      if (getFilterChainDecision(eventObject) == FilterReply.DENY) {        return;      }      // ok, we now invoke derived class' implementation of append      this.append(eventObject);    } catch (Exception e) {      if (exceptionCount++ < ALLOWED_REPEATS) {        addError("Appender [" + name + "] failed to append.", e);      }    } finally {      guard.set(Boolean.FALSE);    }  }

去锁的关键在guard上，guard的值必须线程间独立，否则会导致日志漏打。