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的值必须线程间独立，否则会导致日志漏打。