Logback源碼分析

在日常開發中經常通過打印日志記錄程序執行的步驟或者排查問題，如下代碼類似很多，但是，它是如何執行的呢？

package chapters;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
// 省略...
Logger logger = LoggerFactory.getLogger(LogbackTest.class);
logger.info(" {} is best player in world", "Greizmann");

本文以Logback日志框架來分析以上代碼的實現。

slf4j

如今日志框架常用的有log4j、log4j2、jul(common-log)以及logback。假如項目中用的是jul，如今想改成用log4j，如果直接引用java.util.logging包中Logger，需要修改大量代碼，為了解決這個麻煩的事情，Ceki Gülcü 大神開發了slf4j(Simple Logging Facade for Java) 。slf4j 是眾多日志框架抽象的門面接口，有了slf4j 想要切換日志實現，只需要把對應日志jar替換和添加對應的適配器。

> 圖片來源： [一個著名的日志系統是怎么設計出來的？](https://mp.weixin.qq.com/s/XiCky-Z8-n4vqItJVHjDIg)

從圖中就可以知道我們開始的代碼為什么引 slf4j 包。在阿里的開發手冊上一條

強制：應用中不可直接使用日志系統（log4j、logback）中的 API ，而應依賴使用日志框架 SLF4J 中的 API 。使用門面模式的日志框架，有利於維護和各個類的日志處理方式的統一。

Logback 實現了 SLF4J ,少了中間適配層， Logback也是Ceki Gülcü 大神開發的。

Logger & Appender & Layouts

Logback 主要的三個類 logger，appender和layouts。這三個組件一起作用可以滿足我們開發中根據消息的類型以及日志的級別打印日志到不同的地方。

Logger

ch.qos.logback.classic.Logger類結構：

Logger 依附在LoggerContext上，LoggerContext負責生產Logger，通過一個樹狀的層次結構來進行管理。Logger 維護着當前節點的日志級別及level值。logger按 "." 分代（層級），日志級別有繼承能力，如：名字為 chapters.LogbackTest 如果沒有設置日志級別，會繼承它的父類chapters 日志級別。所有日志的老祖宗都是ROOT名字的Logger，默認DEBUG級別。當前節點設置了日志級別不會考慮父類的日志級別。Logger 通過日志級別控制日志的啟用和禁用。日志級別 TRACE < DEBUG < INFO < WARN < ERROR。

接下來我們結合配置文件看一下Logger屬性對應的配置標簽：

<configuration>
  <turboFilter class="ch.qos.logback.classic.turbo.MDCFilter">
    <MDCKey>username</MDCKey>
    <Value>sebastien</Value>
    <OnMatch>ACCEPT</OnMatch>
  </turboFilter>

  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>/Users/wolf/study/logback/logback-examples/myApp.log</file>
    <encoder>
      <pattern>%msg%n</pattern>
    </encoder>
  </appender>
 
  <logger name="chapters.LogbackTest" level="DEBUG"></logger>

  <root>
    <appender-ref ref="FILE"/>
  </root>
</configuration>

name：logger 標簽中 name 屬性值。

level：logger 標簽中 level 屬性值。

parent：封裝了父類 "chapters"，以及"chapters"的父類“ROOT”的logger對象。

aai：appender-ref 標簽，及這里對應 FileAppender 的實現類對象。如果沒有appender-ref標簽該值為null。

loggerContext：維護着過濾器，如 turbo 過濾器等。

Appender

Appender 作用是控制日志輸出的目的地。日志輸出的目的地是多元化，你可以把日志輸出到console、file、remote socket server、MySQL、PostgreSQL、Oracle 或者其它的數據庫、JMS、remote UNIX Syslog daemons 中。一個日志可以輸出到多個目的地。如

<configuration>
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>/Users/wolf/study/logback/logback-examples/myApp.log</file>
    <encoder>
      <pattern>%msg%n</pattern>
    </encoder>
  </appender>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%msg%n</pattern>
    </encoder>
  </appender>

  <root>
    <appender-ref ref="STDOUT" />
    <appender-ref ref="FILE"/>
  </root>
</configuration>

該xml配置把日志輸出到了myApp.log文件和console中。

Layouts/Encoder

有上面Logger和Appender兩大組件，日志已經輸出到目的地了，但是這樣打印的日志對我們這種凡人不太友好，讀起來費勁。凡人就要做到美觀，那就用Layouts或Encoder美化一下日志輸出格式吧。Encoder 在 logback 0.9.19 版本引進。在之前的版本中，大多數的 appender 依賴 layout 將日志事件轉換為 string，然后再通過 java.io.Writer 寫出。在之前的版本中，用戶需要在 FileAppender 中內置一個 PatternLayout。在 0.9.19 之后的版本中，FileAppender 以及子類需要一個 encoder 而不是 layout。

源碼

Logger創建

Logger logger = LoggerFactory.getLogger(LogbackTest.class);

接下來我們根據源碼分析一下logger的初始化。分析源碼之前還是按照老規矩來一張接口調用時序圖吧。

第步：org.slf4j.LoggerFactory#getLogger(java.lang.String)

public static Logger getLogger(String name) {
    ILoggerFactory iLoggerFactory = getILoggerFactory();
    return iLoggerFactory.getLogger(name);
}

獲取一個ILoggerFactory，即LoggerContext。然后從其獲取到Logger對象。

第3步：org.slf4j.LoggerFactory#getILoggerFactory

public static ILoggerFactory getILoggerFactory() {
    return getProvider().getLoggerFactory();
}

第4步：org.slf4j.LoggerFactory#getProvider

static SLF4JServiceProvider getProvider() {
    if (INITIALIZATION_STATE == UNINITIALIZED) {
        synchronized (LoggerFactory.class) {
            if (INITIALIZATION_STATE == UNINITIALIZED) {
                INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                performInitialization();
            }
        }
    }
    switch (INITIALIZATION_STATE) {
    case SUCCESSFUL_INITIALIZATION:
        return PROVIDER;
    case NOP_FALLBACK_INITIALIZATION:
        return NOP_FALLBACK_FACTORY;
    case FAILED_INITIALIZATION:
        throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
    case ONGOING_INITIALIZATION:
        return SUBST_PROVIDER;
    }
    throw new IllegalStateException("Unreachable code");
}

對SLF4JServiceProvider初始化，即LogbackServiceProvider對象。然后檢查初始化狀態，如果成功就返回PROVIDER。

第5步：org.slf4j.LoggerFactory#performInitialization

private final static void performInitialization() {
    bind();
    if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
        versionSanityCheck();
    }
}

第6步：org.slf4j.LoggerFactory#bind

private final static void bind() {
    try {
        // 加載 SLF4JServiceProvider 
        List<SLF4JServiceProvider> providersList = findServiceProviders();
        reportMultipleBindingAmbiguity(providersList);
        if (providersList != null && !providersList.isEmpty()) {
           PROVIDER = providersList.get(0);
           // SLF4JServiceProvider.initialize()
           PROVIDER.initialize();
           INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            reportActualBinding(providersList);
            fixSubstituteLoggers();
            replayEvents();
            SUBST_PROVIDER.getSubstituteLoggerFactory().clear();
        } else {
            // 省略代碼。。。
        }
    } catch (Exception e) {
        // 失敗，設置狀態值，上報
        failedBinding(e);
        throw new IllegalStateException("Unexpected initialization failure", e);
    }
}

通過ServiceLoader加載LogbackServiceProvider，然后進行初始化相關字段。初始化成功后把初始化狀態設置成功狀態值。

第7步：ch.qos.logback.classic.spi.LogbackServiceProvider#initialize

public void initialize() {
    // 初始化默認的loggerContext
    defaultLoggerContext = new LoggerContext();
    defaultLoggerContext.setName(CoreConstants.DEFAULT_CONTEXT_NAME);
    initializeLoggerContext();
    markerFactory = new BasicMarkerFactory();
    mdcAdapter = new LogbackMDCAdapter();
}

創建名字為default的LoggerContext對象，並初始化一些字段默認值。

ch.qos.logback.classic.LoggerContext#LoggerContext

public LoggerContext() {
    super();
    this.loggerCache = new ConcurrentHashMap<String, Logger>();
    this.loggerContextRemoteView = new LoggerContextVO(this);
    this.root = new Logger(Logger.ROOT_LOGGER_NAME, null, this);
    this.root.setLevel(Level.DEBUG);
    loggerCache.put(Logger.ROOT_LOGGER_NAME, root);
    initEvaluatorMap();
    size = 1;
    this.frameworkPackages = new ArrayList<String>();
}

初始化LoggerContext時設置了ROOT的Logger，日志級別為DEBUG。

第8步：ch.qos.logback.classic.spi.LogbackServiceProvider#initializeLoggerContext

private void initializeLoggerContext() {
    try {
        try {
            new ContextInitializer(defaultLoggerContext).autoConfig();
        } catch (JoranException je) {
            Util.report("Failed to auto configure default logger context", je);
        }
        // 省略代碼。。。
    } catch (Exception t) { // see LOGBACK-1159
        Util.report("Failed to instantiate [" + LoggerContext.class.getName() + "]", t);
    }
}

把第7步初始化好的LoggerContext當做參數傳入ContextInitializer，構建其對象。然后解析配置文件。

第9步：ch.qos.logback.classic.util.ContextInitializer#autoConfig

public void autoConfig() throws JoranException {
    StatusListenerConfigHelper.installIfAsked(loggerContext);
    // (1) 從指定路徑獲取
    URL url = findURLOfDefaultConfigurationFile(true);
    if (url != null) {
        configureByResource(url);
    } else {
        // (2) 從運行環境中獲取
        Configurator c = EnvUtil.loadFromServiceLoader(Configurator.class);
        if (c != null) {
            // 省略代碼。。。
        } else {
            // （3）設置默認的
            BasicConfigurator basicConfigurator = new BasicConfigurator();
            basicConfigurator.setContext(loggerContext);
            basicConfigurator.configure(loggerContext);
        }
    }
}

首先從指定的路徑獲取資源URL,如果存在就進行解析；如果不存在再從運行環境中獲取配置；如果以上都沒有最后會構建一個BasicConfigurator當作默認的。

ch.qos.logback.classic.util.ContextInitializer#findURLOfDefaultConfigurationFile

public URL findURLOfDefaultConfigurationFile(boolean updateStatus) {
    ClassLoader myClassLoader = Loader.getClassLoaderOfObject(this);
    // 啟動參數中獲取
    URL url = findConfigFileURLFromSystemProperties(myClassLoader, updateStatus);
    if (url != null) {
        return url;
    }
    // logback-test.xml
    url = getResource(TEST_AUTOCONFIG_FILE, myClassLoader, updateStatus);
    if (url != null) {
        return url;
    }
    //logback.groovy
    url = getResource(GROOVY_AUTOCONFIG_FILE, myClassLoader, updateStatus);
    if (url != null) {
        return url;
    }
    // logback.xml
    return getResource(AUTOCONFIG_FILE, myClassLoader, updateStatus);
}

先從啟動參數中查找logback.configurationFile參數值，如果沒有再從classpath中一次查找logback-test.xml -> logback.groovy -> logback.xml 。由此可知文件的優先級是 啟動參數 -> logback-test.xml -> logback.groovy -> logback.xml

第10步：ch.qos.logback.classic.util.ContextInitializer#configureByResource

public void configureByResource(URL url) throws JoranException {
    if (url == null) {
        throw new IllegalArgumentException("URL argument cannot be null");
    }
    final String urlString = url.toString();
    if (urlString.endsWith("groovy")) {
         // 省略代碼。。。
    } else if (urlString.endsWith("xml")) {
        JoranConfigurator configurator = new JoranConfigurator();
        configurator.setContext(loggerContext);
        configurator.doConfigure(url);
    } else {
        // 省略代碼。。。
    }
}

根據文件后綴判斷是 groovy或者xml，然后交給不同的配置解析器處理。這里也是把第7步中的LoggerContext傳進去，繼續封裝它的字段值。

第12步：ch.qos.logback.core.joran.GenericConfigurator#doConfigure(org.xml.sax.InputSource)

public final void doConfigure(final InputSource inputSource) throws JoranException {

    long threshold = System.currentTimeMillis();
    SaxEventRecorder recorder = new SaxEventRecorder(context);
    recorder.recordEvents(inputSource);
    // 處理配置文件，封裝到 LoggerContext 中
    playEventsAndProcessModel(recorder.saxEventList);
    StatusUtil statusUtil = new StatusUtil(context);
    if (statusUtil.noXMLParsingErrorsOccurred(threshold)) {
        registerSafeConfiguration(recorder.saxEventList);
    }
}

真正解析配置文件的邏輯在playEventsAndProcessModel方法中，這里就不展開分析了。到這一步LoggerContext基本初始化完成了。

第13步：ch.qos.logback.classic.LoggerContext#getLogger(java.lang.String)

@Override
public Logger getLogger(final String name) {
    // 省略代碼。。。 
    if (Logger.ROOT_LOGGER_NAME.equalsIgnoreCase(name)) {
        return root;
    }

    int i = 0;
    Logger logger = root;
    // 從緩存中獲取， 有直接返回
    Logger childLogger = (Logger) loggerCache.get(name);
    if (childLogger != null) {
        return childLogger;
    }

    // if the desired logger does not exist, them create all the loggers
    // in between as well (if they don't already exist)
    String childName;
    while (true) {
        int h = LoggerNameUtil.getSeparatorIndexOf(name, i);
        if (h == -1) {
            childName = name;
        } else {
            childName = name.substring(0, h);
        }
        // move i left of the last point
        i = h + 1;
        synchronized (logger) {
            childLogger = logger.getChildByName(childName);
            if (childLogger == null) {
                childLogger = logger.createChildByName(childName);
                loggerCache.put(childName, childLogger);
                incSize();
            }
        }
        logger = childLogger;
        if (h == -1) {
            return childLogger;
        }
    }
}

經過前面漫長的對LoggerContext進行初始化工作，這一步就是從LoggerContext獲取Logger對象。如果緩存中直接返回。否則通過“.”分代構建層次結構。

日志執行步驟

上一節Logger創建完成，接下來分析一下打日志的流程。

logger.info(" {} is best player in world", "Greizmann");

第1步：ch.qos.logback.classic.Logger#info(java.lang.String, java.lang.Object)

public void info(String format, Object arg) {
    filterAndLog_1(FQCN, null, Level.INFO, format, arg, null);
}

把接口的日志級別（Level.INFO）傳到下一個方法。

第2步：ch.qos.logback.classic.Logger#filterAndLog_1

private void filterAndLog_1(final String localFQCN, final Marker marker, final Level level, final String msg, final Object param, final Throwable t) {
    // 先通過turboFilter過濾
    final FilterReply decision = loggerContext.getTurboFilterChainDecision_1(marker, this, level, msg, param, t);
    // 判斷日志級別
    if (decision == FilterReply.NEUTRAL) {
        if (effectiveLevelInt > level.levelInt) {
            return;
        }
    } else if (decision == FilterReply.DENY) {
        return;
    }

    buildLoggingEventAndAppend(localFQCN, marker, level, msg, new Object[] { param }, t);
}

如果TurboFilter過濾器存在就會執行相關操作，並返回FilterReply。如果結果是FilterReply.DENY本條日志消息直接丟棄；如果是FilterReply.NEUTRAL會繼續判斷日志級別是否在該方法級別之上；如果是FilterReply.ACCEPT直接跳到下一步。

第3步：ch.qos.logback.classic.Logger#buildLoggingEventAndAppend

private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params, final Throwable t) {
    LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
    le.setMarker(marker);
    callAppenders(le);
}

創建了LoggingEvent對象，該對象包含日志請求所有相關的參數，請求的 logger，日志請求的級別，日志信息，與日志一同傳遞的異常信息，當前時間，當前線程，以及當前類的各種信息和 MDC。其實打印日志就是一個事件，所以這個對象是相關重要，下面全部是在操作該對象。

第4步：ch.qos.logback.classic.Logger#callAppenders

public void callAppenders(ILoggingEvent event) {
    int writes = 0;
    // 從自己往父輩查找滿足
    for (Logger l = this; l != null; l = l.parent) {
        // 寫文件
        writes += l.appendLoopOnAppenders(event);
        if (!l.additive) {
            break;
        }
    }
    // No appenders in hierarchy
    if (writes == 0) {
        loggerContext.noAppenderDefinedWarning(this);
    }
}

第5步：ch.qos.logback.classic.Logger#appendLoopOnAppenders

private int appendLoopOnAppenders(ILoggingEvent event) {
    if (aai != null) {
        return aai.appendLoopOnAppenders(event);
    } else {
        return 0;
    }
}

從當前Logger到父節點遍歷，直到AppenderAttachableImpl不為空（有appender-ref 標簽）。

第6步：ch.qos.logback.core.spi.AppenderAttachableImpl#appendLoopOnAppenders

public int appendLoopOnAppenders(E e) {
    int size = 0;
    final Appender<E>[] appenderArray = appenderList.asTypedArray();
    final int len = appenderArray.length;
    for (int i = 0; i < len; i++) {
        appenderArray[i].doAppend(e);
        size++;
    }
    return size;
}

如果設置了多個日志輸出目的地，這里就是循環調用對應的Appender進行輸出。

第7步：ch.qos.logback.core.UnsynchronizedAppenderBase#doAppend

public void doAppend(E eventObject) {
    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;
        }

        this.append(eventObject);

    } catch (Exception e) {
        if (exceptionCount++ < ALLOWED_REPEATS) {
            addError("Appender [" + name + "] failed to append.", e);
        }
    } finally {
        guard.set(Boolean.FALSE);
    }
}

通過ThreadLocal控制遞歸導致的重復提交

第8步：ch.qos.logback.core.OutputStreamAppender#append

protected void append(E eventObject) {
    if (!isStarted()) {
        return;
    }

    subAppend(eventObject);
}

第9步：ch.qos.logback.core.OutputStreamAppender#subAppend

protected void subAppend(E event) {
    if (!isStarted()) {
        return;
    }
    try {
        if (event instanceof DeferredProcessingAware) {
            // 拼接日志信息（填充占位符），設置當前線程以及MDC等信息
            ((DeferredProcessingAware) event).prepareForDeferredProcessing();
        }
        byte[] byteArray = this.encoder.encode(event);
        writeBytes(byteArray);
    } catch (IOException ioe) {
        this.started = false;
        addStatus(new ErrorStatus("IO failure in appender", this, ioe));
    }
}

Encoder在這里慘淡登場，返回byte數組。

第10步：ch.qos.logback.core.encoder.LayoutWrappingEncoder#encode

public byte[] encode(E event) {
    String txt = layout.doLayout(event);
    return convertToBytes(txt);
}

Encoder先把LoggerEvent交給Layout，Layout組裝日志信息，在每條信息后加上換行符。

第11步：ch.qos.logback.core.OutputStreamAppender#writeBytes

private void writeBytes(byte[] byteArray) throws IOException {
    if(byteArray == null || byteArray.length == 0)
        return;
    
    lock.lock();
    try {
        this.outputStream.write(byteArray);
        if (immediateFlush) {
            this.outputStream.flush();
        }
    } finally {
        lock.unlock();
    }
}

使用AQS鎖控制並發問題。這也是Logback性能不如 Log4j2的原因。后面有時間分析一下Log4j2。

本文到此結束了，還有兩天就要放假了，祝大家新年快樂。