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的值必須執行緒間獨立，否則會導致日誌漏打。