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、log4j二、jul(common-log)以及logback。假如項目中用的是jul，現在想改爲用log4j，若是直接引用java.util.logging包中Logger，須要修改大量代碼，爲了解決這個麻煩的事情，Ceki Gülcü 大神開發了slf4j(Simple Logging Facade for Java) 。slf4j 是衆多日誌框架抽象的門面接口，有了slf4j 想要切換日誌實現，只須要把對應日誌jar替換和添加對應的適配器。

圖片來源： 一個著名的日誌系統是怎麼設計出來的？

從圖中就能夠知道咱們開始的代碼爲何引 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。

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